<div dir="ltr"><div><div dir="ltr" class="gmail_signature" data-smartmail="gmail_signature"><div dir="ltr"><div><div dir="ltr"><div dir="ltr"><div dir="ltr"><div dir="ltr"><div dir="ltr"><div dir="ltr"><div dir="ltr"><div dir="ltr"><div dir="ltr"><div dir="ltr"><div dir="ltr"><div dir="ltr"><div dir="ltr"><div>For those following along, this appears to have been an issue with Auto Scaling. Once disabled, the problem has not reoccured. In our case this is a perfectly acceptable way to move forward, but maybe at some stage we'll come back to working this out.</div><div><br></div><div>Andrew</div></div></div></div></div></div></div></div></div></div></div></div></div></div></div></div></div></div><br></div><br><div class="gmail_quote"><div dir="ltr" class="gmail_attr">On Sat, 9 Oct 2021 at 01:39, Andrew Yager <<a href="mailto:andrew@rwts.com.au">andrew@rwts.com.au</a>> wrote:<br></div><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex">Process 24103 (the blocked proc) last logged at 19:02:01, and in doing<br>
so, it had:<br>
<br>
Oct 8 19:02:01 hvprxy osips[24103]: DBG:tm:t_lookup_request: start<br>
searching: hash=34811, isACK=0<br>
Oct 8 19:02:01 hvprxy osips[24103]: DBG:tm:matching_3261: RFC3261<br>
transaction matching failed<br>
Oct 8 19:02:01 hvprxy osips[24103]: DBG:tm:t_lookup_request: no<br>
transaction found<br>
Oct 8 19:02:01 hvprxy osips[24103]: DBG:statistics:w_update_stat:<br>
needed statistic is <cpbx_presence_notify_rcv><br>
Oct 8 19:02:01 hvprxy osips[24103]: DBG:statistics:parse_groupname:<br>
group: '', name: 'cpbx_presence_notify_rcv'<br>
Oct 8 19:02:01 hvprxy osips[24103]: DBG:core:select_contacts: ct:<br>
sip:[snip]@[snip]:55087;transport=tls<br>
Oct 8 19:02:01 hvprxy osips[24103]: DBG:core:push_branch: setting msg<br>
R-URI <sip:[snip]@[snip]:55087;transport=tls><br>
Oct 8 19:02:01 hvprxy osips[24103]: [RELAY] Performing mid-registrar<br>
lookup on sip:[snip]:5060<br>
Oct 8 19:02:01 hvprxy osips[24103]: DBG:core:lookup: '' Not found in usrloc<br>
Oct 8 19:02:01 hvprxy osips[24103]: DBG:statistics:w_update_stat:<br>
needed statistic is <cpbx_contact_lookup_failed><br>
Oct 8 19:02:01 hvprxy osips[24103]: DBG:statistics:parse_groupname:<br>
group: '', name: 'cpbx_contact_lookup_failed'<br>
Oct 8 19:02:01 hvprxy osips[24103]: DBG:core:select_contacts: ct:<br>
sip:[snip]@[snip]:55087;transport=tls<br>
Oct 8 19:02:01 hvprxy osips[24103]: DBG:core:push_branch: setting msg<br>
R-URI <sip:xxx@xxx:55087;transport=tls><br>
Oct 8 19:02:01 hvprxy osips[24103]: [RELAY] Performed<br>
mid_registrar_lookup: sip:xxx@xxx:55087;transport=tls<br>
Oct 8 19:02:01 hvprxy osips[24103]: DBG:tm:t_newtran: transaction on<br>
entrance=(nil)<br>
Oct 8 19:02:01 hvprxy osips[24103]: DBG:core:parse_headers:<br>
flags=ffffffffffffffff<br>
Oct 8 19:02:01 hvprxy osips[24103]: DBG:core:parse_headers: flags=78<br>
Oct 8 19:02:01 hvprxy osips[24103]: DBG:tm:t_lookup_request: start<br>
searching: hash=34811, isACK=0<br>
Oct 8 19:02:01 hvprxy osips[24103]: DBG:tm:matching_3261: RFC3261<br>
transaction matching failed<br>
Oct 8 19:02:01 hvprxy osips[24103]: DBG:tm:t_lookup_request: no<br>
transaction found<br>
Oct 8 19:02:01 hvprxy osips[24103]: DBG:tm:run_reqin_callbacks:<br>
trans=0x7fafa71d8150, callback type 1, id 0 entered<br>
Oct 8 19:02:01 hvprxy osips[24103]: DBG:core:mk_proxy: doing DNS lookup...<br>
Oct 8 19:02:01 hvprxy osips[24103]: DBG:core:parse_headers: flags=2000<br>
Oct 8 19:02:01 hvprxy osips[24103]: DBG:core:parse_headers:<br>
flags=ffffffffffffffff<br>
Oct 8 19:02:01 hvprxy osips[24103]: DBG:core:tcp_conn_get: con found in state 0<br>
Oct 8 19:02:01 hvprxy osips[24103]: DBG:core:tcp_conn_get: tcp<br>
connection found (0x7fafa84997e8), acquiring fd<br>
Oct 8 19:02:01 hvprxy osips[24103]: DBG:core:tcp_conn_get: c=<br>
0x7fafa84997e8, n=16, Usock=647<br>
< no more ><br>
<br>
Proc 11468 (tcp main thread) logged:<br>
<br>
Oct 8 19:02:01 hvprxy osips[11468]: DBG:core:probe_max_sock_buff:<br>
getsockopt: snd is initially 425984<br>
Oct 8 19:02:01 hvprxy osips[11468]: DBG:core:probe_max_sock_buff:<br>
setting snd buf to 851968 had no effect<br>
Oct 8 19:02:01 hvprxy osips[11468]: DBG:core:probe_max_sock_buff:<br>
setting snd buf to 428032 had no effect<br>
Oct 8 19:02:01 hvprxy osips[11468]: DBG:core:probe_max_sock_buff:<br>
using snd buffer of 416 kb<br>
Oct 8 19:02:01 hvprxy osips[11468]: DBG:core:init_sock_keepalive: TCP<br>
keepalive enabled on socket 636<br>
Oct 8 19:02:01 hvprxy osips[11468]: DBG:core:print_ip: tcpconn_new:<br>
new tcp connection to: xxx<br>
Oct 8 19:02:01 hvprxy osips[11468]: DBG:core:tcpconn_new: on port<br>
11934, proto 3<br>
Oct 8 19:02:01 hvprxy osips[11468]: DBG:core:tcpconn_add: hashes: 1004, 320<br>
Oct 8 19:02:01 hvprxy osips[11468]: DBG:core:handle_new_connect: new<br>
connection: 0x7fafa7cc0c80 636 flags: 001c<br>
Oct 8 19:02:01 hvprxy osips[11468]: DBG:core:send2worker: no free tcp<br>
receiver, connection passed to the least busy one (proc #1, 3 con)<br>
Oct 8 19:02:01 hvprxy osips[11468]: DBG:core:send2worker: to tcp<br>
worker 1 (0), 0x7fafa7cc0c80 rw 1<br>
Oct 8 19:02:01 hvprxy osips[11468]: DBG:core:ipc_handle_job: received<br>
job type 0[RPC] from process 1<br>
Oct 8 19:02:01 hvprxy osips[11468]: DBG:core:probe_max_sock_buff:<br>
getsockopt: snd is initially 425984<br>
Oct 8 19:02:01 hvprxy osips[11468]: DBG:core:probe_max_sock_buff:<br>
setting snd buf to 851968 had no effect<br>
Oct 8 19:02:01 hvprxy osips[11468]: DBG:core:probe_max_sock_buff:<br>
setting snd buf to 428032 had no effect<br>
Oct 8 19:02:01 hvprxy osips[11468]: DBG:core:probe_max_sock_buff:<br>
using snd buffer of 416 kb<br>
Oct 8 19:02:01 hvprxy osips[11468]: DBG:core:init_sock_keepalive: TCP<br>
keepalive enabled on socket 637<br>
Oct 8 19:02:01 hvprxy osips[11468]: DBG:core:print_ip: tcpconn_new:<br>
new tcp connection to: xxx<br>
Oct 8 19:02:01 hvprxy osips[11468]: DBG:core:tcpconn_new: on port<br>
11850, proto 3<br>
Oct 8 19:02:01 hvprxy osips[11468]: DBG:core:tcpconn_add: hashes: 824, 321<br>
Oct 8 19:02:01 hvprxy osips[11468]: DBG:core:handle_new_connect: new<br>
connection: 0x7fafa7e76170 637 flags: 001c<br>
Oct 8 19:02:01 hvprxy osips[11468]: DBG:core:send2worker: no free tcp<br>
receiver, connection passed to the least busy one (proc #5, 3 con)<br>
Oct 8 19:02:01 hvprxy osips[11468]: DBG:core:send2worker: to tcp<br>
worker 5 (0), 0x7fafa7e76170 rw 1<br>
<br>
Looking for maybe other interesting things…<br>
<br>
Oct 8 19:01:55 hvprxy osips[11397]: DBG:core:tcp_conn_get: tcp<br>
connection found (0x7fafa84997e8), acquiring fd<br>
Oct 8 19:01:55 hvprxy osips[11397]: DBG:core:tcp_conn_get: c=<br>
0x7fafa84997e8, n=16, Usock=555<br>
Oct 8 19:01:55 hvprxy osips[11397]: DBG:core:tcp_conn_get: after<br>
receive_fd: c= 0x7fafa84997e8 n=8 fd=5<br>
Oct 8 19:01:55 hvprxy osips[11397]: DBG:proto_tls:proto_tls_send:<br>
after write: c=0x7fafa84997e8 n=483 fd=5<br>
Oct 8 19:02:01 hvprxy osips[24103]: DBG:core:tcp_conn_get: tcp<br>
connection found (0x7fafa84997e8), acquiring fd<br>
Oct 8 19:02:01 hvprxy osips[24103]: DBG:core:tcp_conn_get: c=<br>
0x7fafa84997e8, n=16, Usock=647<br>
Oct 8 19:02:13 hvprxy osips[11398]: DBG:core:tcp_conn_get: tcp<br>
connection found (0x7fafa84997e8), acquiring fd<br>
Oct 8 19:02:13 hvprxy osips[11398]: DBG:core:tcp_conn_get: c=<br>
0x7fafa84997e8, n=16, Usock=557<br>
Oct 8 19:02:13 hvprxy osips[11398]: DBG:core:tcp_conn_get: after<br>
receive_fd: c= 0x7fafa84997e8 n=8 fd=5<br>
Oct 8 19:02:13 hvprxy osips[11398]: DBG:proto_tls:proto_tls_send:<br>
after write: c=0x7fafa84997e8 n=360 fd=5<br>
Oct 8 19:02:13 hvprxy osips[11460]: DBG:proto_tls:tcp_handle_req:<br>
Nothing more to read on TCP conn 0x7fafa84997e8, currently in state 0<br>
Oct 8 19:02:43 hvprxy osips[11398]: DBG:core:tcp_conn_get: tcp<br>
connection found (0x7fafa84997e8), acquiring fd<br>
Oct 8 19:02:43 hvprxy osips[11398]: DBG:core:tcp_conn_get: c=<br>
0x7fafa84997e8, n=16, Usock=557<br>
Oct 8 19:02:43 hvprxy osips[11398]: DBG:core:tcp_conn_get: after<br>
receive_fd: c= 0x7fafa84997e8 n=8 fd=5<br>
Oct 8 19:02:43 hvprxy osips[11398]: DBG:proto_tls:proto_tls_send:<br>
after write: c=0x7fafa84997e8 n=360 fd=5<br>
Oct 8 19:02:43 hvprxy osips[11460]: DBG:proto_tls:tcp_handle_req:<br>
Nothing more to read on TCP conn 0x7fafa84997e8, currently in state 0<br>
Oct 8 19:02:44 hvprxy osips[11460]: DBG:proto_tls:tcp_handle_req:<br>
Nothing more to read on TCP conn 0x7fafa84997e8, currently in state 0<br>
Oct 8 19:02:44 hvprxy osips[24113]: DBG:core:tcp_conn_get: tcp<br>
connection found (0x7fafa84997e8), acquiring fd<br>
Oct 8 19:02:44 hvprxy osips[24113]: DBG:core:tcp_conn_get: c=<br>
0x7fafa84997e8, n=16, Usock=649<br>
Oct 8 19:03:13 hvprxy osips[11458]: DBG:core:tcp_conn_get: tcp<br>
connection found (0x7fafa84997e8), acquiring fd<br>
Oct 8 19:03:13 hvprxy osips[11458]: DBG:core:tcp_conn_get: c=<br>
0x7fafa84997e8, n=16, Usock=625<br>
Oct 8 19:03:13 hvprxy osips[11458]: DBG:core:tcp_conn_get: after<br>
receive_fd: c= 0x7fafa84997e8 n=8 fd=950<br>
Oct 8 19:03:13 hvprxy osips[11458]: DBG:proto_tls:proto_tls_send:<br>
after write: c=0x7fafa84997e8 n=360 fd=950<br>
Oct 8 19:03:13 hvprxy osips[11460]: DBG:proto_tls:tcp_handle_req:<br>
Nothing more to read on TCP conn 0x7fafa84997e8, currently in state 0<br>
<br>
All this said, I can't say I'm totally sure I know what I would be<br>
looking for. Nothing seems to stand out in the logs to me; but there<br>
are a few gigs of logs so it's hard to quite know what I'm looking<br>
for.<br>
<br>
Andrew<br>
<br>
<br>
On Sat, 9 Oct 2021 at 00:19, Bogdan-Andrei Iancu <<a href="mailto:bogdan@opensips.org" target="_blank">bogdan@opensips.org</a>> wrote:<br>
><br>
> Hi Andrew,<br>
><br>
> The second blocked process (doing the TLS/TCP stuff) surprisingly got<br>
> stuck while waiting for a TCP fd from the TCP Main process.<br>
><br>
> You mentioned that the logs of the UDP worker (doing the TCP send)<br>
> suddenly stopped - around that time, do you see any errors from that<br>
> process or from the TCP MAIN processes ?<br>
><br>
> Regards,<br>
><br>
> Bogdan-Andrei Iancu<br>
><br>
> OpenSIPS Founder and Developer<br>
> <a href="https://www.opensips-solutions.com" rel="noreferrer" target="_blank">https://www.opensips-solutions.com</a><br>
> OpenSIPS eBootcamp 2021<br>
> <a href="https://opensips.org/training/OpenSIPS_eBootcamp_2021/" rel="noreferrer" target="_blank">https://opensips.org/training/OpenSIPS_eBootcamp_2021/</a><br>
><br>
> On 10/8/21 2:43 PM, Andrew Yager wrote:<br>
> > Hi Bogdan-Andrei,<br>
> ><br>
> > Have restarted since the last bt, but have recreated again and<br>
> > attached. Earlier today we did also get another bt full on the second<br>
> > blocked pid, but I didn't save it. In that case it was a UDP reply<br>
> > from one of our upstream servers that had gone through mid_registrar<br>
> > and was being relayed to a TCP endpoint. The TCP endpoint did have an<br>
> > open file descriptor we could see, and it had sent and was blocked on<br>
> > receive at the same point (I'm getting better at reading backtraces!<br>
> > :D).<br>
> ><br>
> > The thing I do note is happening is that every example I have is a UDP<br>
> > message being received from an upstream server being relayed to a<br>
> > client on a TCP/TLS connection via a UDP worker.<br>
> ><br>
> > While we are using WolfSSL in this box, the other box where we have<br>
> > the same behaviour (but I haven't taken backtraces yet) is running<br>
> > OpenSSL and on 3.1.3; so it's not SSL library specific.<br>
> ><br>
> > I'm going to see if I can get a backtrace from the 3.1.3 box shortly.<br>
> ><br>
> > Andrew<br>
> ><br>
> > On Fri, 8 Oct 2021 at 17:13, Bogdan-Andrei Iancu <<a href="mailto:bogdan@opensips.org" target="_blank">bogdan@opensips.org</a>> wrote:<br>
> >> Hi Andrew,<br>
> >><br>
> >> OK, interesting progress here. So, the FIFO process blocks as it is<br>
> >> trying to send an IPC JOB to an UDP process which looks like also being<br>
> >> blocked.<br>
> >><br>
> >> Could you attach with GDB to the that UDP blocked process too ? (you<br>
> >> have its PID in the printing of the pt[x] in first gdb)<br>
> >><br>
> >> Regards,<br>
> >><br>
> >> Bogdan-Andrei Iancu<br>
> >><br>
> >> OpenSIPS Founder and Developer<br>
> >> <a href="https://www.opensips-solutions.com" rel="noreferrer" target="_blank">https://www.opensips-solutions.com</a><br>
> >> OpenSIPS eBootcamp 2021<br>
> >> <a href="https://opensips.org/training/OpenSIPS_eBootcamp_2021/" rel="noreferrer" target="_blank">https://opensips.org/training/OpenSIPS_eBootcamp_2021/</a><br>
> >><br>
> >> On 10/8/21 1:43 AM, Andrew Yager wrote:<br>
> >>> Interestingly, where I usually see a range of continued messages from<br>
> >>> a process continually in the debug log, they appear to stop for this<br>
> >>> PID at 3:47am, and that process seems blocked on a tcp/tls send:<br>
> >>><br>
> >>><br>
><br>
</blockquote></div>