[OpenSIPS-Users] mi_fifo lock on reply after a period of time in 3.1.3

Andrew Yager andrew at rwts.com.au
Fri Oct 8 14:39:09 EST 2021 

Process 24103 (the blocked proc) last logged at 19:02:01, and in doing
so, it had:

Oct  8 19:02:01 hvprxy osips[24103]: DBG:tm:t_lookup_request: start
searching: hash=34811, isACK=0
Oct  8 19:02:01 hvprxy osips[24103]: DBG:tm:matching_3261: RFC3261
transaction matching failed
Oct  8 19:02:01 hvprxy osips[24103]: DBG:tm:t_lookup_request: no
transaction found
Oct  8 19:02:01 hvprxy osips[24103]: DBG:statistics:w_update_stat:
needed statistic is <cpbx_presence_notify_rcv>
Oct  8 19:02:01 hvprxy osips[24103]: DBG:statistics:parse_groupname:
group: '', name: 'cpbx_presence_notify_rcv'
Oct  8 19:02:01 hvprxy osips[24103]: DBG:core:select_contacts: ct:
sip:[snip]@[snip]:55087;transport=tls
Oct  8 19:02:01 hvprxy osips[24103]: DBG:core:push_branch: setting msg
R-URI <sip:[snip]@[snip]:55087;transport=tls>
Oct  8 19:02:01 hvprxy osips[24103]: [RELAY] Performing mid-registrar
lookup on sip:[snip]:5060
Oct  8 19:02:01 hvprxy osips[24103]: DBG:core:lookup: '' Not found in usrloc
Oct  8 19:02:01 hvprxy osips[24103]: DBG:statistics:w_update_stat:
needed statistic is <cpbx_contact_lookup_failed>
Oct  8 19:02:01 hvprxy osips[24103]: DBG:statistics:parse_groupname:
group: '', name: 'cpbx_contact_lookup_failed'
Oct  8 19:02:01 hvprxy osips[24103]: DBG:core:select_contacts: ct:
sip:[snip]@[snip]:55087;transport=tls
Oct  8 19:02:01 hvprxy osips[24103]: DBG:core:push_branch: setting msg
R-URI <sip:xxx at xxx:55087;transport=tls>
Oct  8 19:02:01 hvprxy osips[24103]: [RELAY] Performed
mid_registrar_lookup: sip:xxx at xxx:55087;transport=tls
Oct  8 19:02:01 hvprxy osips[24103]: DBG:tm:t_newtran: transaction on
entrance=(nil)
Oct  8 19:02:01 hvprxy osips[24103]: DBG:core:parse_headers:
flags=ffffffffffffffff
Oct  8 19:02:01 hvprxy osips[24103]: DBG:core:parse_headers: flags=78
Oct  8 19:02:01 hvprxy osips[24103]: DBG:tm:t_lookup_request: start
searching: hash=34811, isACK=0
Oct  8 19:02:01 hvprxy osips[24103]: DBG:tm:matching_3261: RFC3261
transaction matching failed
Oct  8 19:02:01 hvprxy osips[24103]: DBG:tm:t_lookup_request: no
transaction found
Oct  8 19:02:01 hvprxy osips[24103]: DBG:tm:run_reqin_callbacks:
trans=0x7fafa71d8150, callback type 1, id 0 entered
Oct  8 19:02:01 hvprxy osips[24103]: DBG:core:mk_proxy: doing DNS lookup...
Oct  8 19:02:01 hvprxy osips[24103]: DBG:core:parse_headers: flags=2000
Oct  8 19:02:01 hvprxy osips[24103]: DBG:core:parse_headers:
flags=ffffffffffffffff
Oct  8 19:02:01 hvprxy osips[24103]: DBG:core:tcp_conn_get: con found in state 0
Oct  8 19:02:01 hvprxy osips[24103]: DBG:core:tcp_conn_get: tcp
connection found (0x7fafa84997e8), acquiring fd
Oct  8 19:02:01 hvprxy osips[24103]: DBG:core:tcp_conn_get: c=
0x7fafa84997e8, n=16, Usock=647
< no more >

Proc 11468 (tcp main thread) logged:

Oct  8 19:02:01 hvprxy osips[11468]: DBG:core:probe_max_sock_buff:
getsockopt: snd is initially 425984
Oct  8 19:02:01 hvprxy osips[11468]: DBG:core:probe_max_sock_buff:
setting snd buf to 851968 had no effect
Oct  8 19:02:01 hvprxy osips[11468]: DBG:core:probe_max_sock_buff:
setting snd buf to 428032 had no effect
Oct  8 19:02:01 hvprxy osips[11468]: DBG:core:probe_max_sock_buff:
using snd buffer of 416 kb
Oct  8 19:02:01 hvprxy osips[11468]: DBG:core:init_sock_keepalive: TCP
keepalive enabled on socket 636
Oct  8 19:02:01 hvprxy osips[11468]: DBG:core:print_ip: tcpconn_new:
new tcp connection to: xxx
Oct  8 19:02:01 hvprxy osips[11468]: DBG:core:tcpconn_new: on port
11934, proto 3
Oct  8 19:02:01 hvprxy osips[11468]: DBG:core:tcpconn_add: hashes: 1004, 320
Oct  8 19:02:01 hvprxy osips[11468]: DBG:core:handle_new_connect: new
connection: 0x7fafa7cc0c80 636 flags: 001c
Oct  8 19:02:01 hvprxy osips[11468]: DBG:core:send2worker: no free tcp
receiver, connection passed to the least busy one (proc #1, 3 con)
Oct  8 19:02:01 hvprxy osips[11468]: DBG:core:send2worker: to tcp
worker 1 (0), 0x7fafa7cc0c80 rw 1
Oct  8 19:02:01 hvprxy osips[11468]: DBG:core:ipc_handle_job: received
job type 0[RPC] from process 1
Oct  8 19:02:01 hvprxy osips[11468]: DBG:core:probe_max_sock_buff:
getsockopt: snd is initially 425984
Oct  8 19:02:01 hvprxy osips[11468]: DBG:core:probe_max_sock_buff:
setting snd buf to 851968 had no effect
Oct  8 19:02:01 hvprxy osips[11468]: DBG:core:probe_max_sock_buff:
setting snd buf to 428032 had no effect
Oct  8 19:02:01 hvprxy osips[11468]: DBG:core:probe_max_sock_buff:
using snd buffer of 416 kb
Oct  8 19:02:01 hvprxy osips[11468]: DBG:core:init_sock_keepalive: TCP
keepalive enabled on socket 637
Oct  8 19:02:01 hvprxy osips[11468]: DBG:core:print_ip: tcpconn_new:
new tcp connection to: xxx
Oct  8 19:02:01 hvprxy osips[11468]: DBG:core:tcpconn_new: on port
11850, proto 3
Oct  8 19:02:01 hvprxy osips[11468]: DBG:core:tcpconn_add: hashes: 824, 321
Oct  8 19:02:01 hvprxy osips[11468]: DBG:core:handle_new_connect: new
connection: 0x7fafa7e76170 637 flags: 001c
Oct  8 19:02:01 hvprxy osips[11468]: DBG:core:send2worker: no free tcp
receiver, connection passed to the least busy one (proc #5, 3 con)
Oct  8 19:02:01 hvprxy osips[11468]: DBG:core:send2worker: to tcp
worker 5 (0), 0x7fafa7e76170 rw 1

Looking for maybe other interesting things…

Oct  8 19:01:55 hvprxy osips[11397]: DBG:core:tcp_conn_get: tcp
connection found (0x7fafa84997e8), acquiring fd
Oct  8 19:01:55 hvprxy osips[11397]: DBG:core:tcp_conn_get: c=
0x7fafa84997e8, n=16, Usock=555
Oct  8 19:01:55 hvprxy osips[11397]: DBG:core:tcp_conn_get: after
receive_fd: c= 0x7fafa84997e8 n=8 fd=5
Oct  8 19:01:55 hvprxy osips[11397]: DBG:proto_tls:proto_tls_send:
after write: c=0x7fafa84997e8 n=483 fd=5
Oct  8 19:02:01 hvprxy osips[24103]: DBG:core:tcp_conn_get: tcp
connection found (0x7fafa84997e8), acquiring fd
Oct  8 19:02:01 hvprxy osips[24103]: DBG:core:tcp_conn_get: c=
0x7fafa84997e8, n=16, Usock=647
Oct  8 19:02:13 hvprxy osips[11398]: DBG:core:tcp_conn_get: tcp
connection found (0x7fafa84997e8), acquiring fd
Oct  8 19:02:13 hvprxy osips[11398]: DBG:core:tcp_conn_get: c=
0x7fafa84997e8, n=16, Usock=557
Oct  8 19:02:13 hvprxy osips[11398]: DBG:core:tcp_conn_get: after
receive_fd: c= 0x7fafa84997e8 n=8 fd=5
Oct  8 19:02:13 hvprxy osips[11398]: DBG:proto_tls:proto_tls_send:
after write: c=0x7fafa84997e8 n=360 fd=5
Oct  8 19:02:13 hvprxy osips[11460]: DBG:proto_tls:tcp_handle_req:
Nothing more to read on TCP conn 0x7fafa84997e8, currently in state 0
Oct  8 19:02:43 hvprxy osips[11398]: DBG:core:tcp_conn_get: tcp
connection found (0x7fafa84997e8), acquiring fd
Oct  8 19:02:43 hvprxy osips[11398]: DBG:core:tcp_conn_get: c=
0x7fafa84997e8, n=16, Usock=557
Oct  8 19:02:43 hvprxy osips[11398]: DBG:core:tcp_conn_get: after
receive_fd: c= 0x7fafa84997e8 n=8 fd=5
Oct  8 19:02:43 hvprxy osips[11398]: DBG:proto_tls:proto_tls_send:
after write: c=0x7fafa84997e8 n=360 fd=5
Oct  8 19:02:43 hvprxy osips[11460]: DBG:proto_tls:tcp_handle_req:
Nothing more to read on TCP conn 0x7fafa84997e8, currently in state 0
Oct  8 19:02:44 hvprxy osips[11460]: DBG:proto_tls:tcp_handle_req:
Nothing more to read on TCP conn 0x7fafa84997e8, currently in state 0
Oct  8 19:02:44 hvprxy osips[24113]: DBG:core:tcp_conn_get: tcp
connection found (0x7fafa84997e8), acquiring fd
Oct  8 19:02:44 hvprxy osips[24113]: DBG:core:tcp_conn_get: c=
0x7fafa84997e8, n=16, Usock=649
Oct  8 19:03:13 hvprxy osips[11458]: DBG:core:tcp_conn_get: tcp
connection found (0x7fafa84997e8), acquiring fd
Oct  8 19:03:13 hvprxy osips[11458]: DBG:core:tcp_conn_get: c=
0x7fafa84997e8, n=16, Usock=625
Oct  8 19:03:13 hvprxy osips[11458]: DBG:core:tcp_conn_get: after
receive_fd: c= 0x7fafa84997e8 n=8 fd=950
Oct  8 19:03:13 hvprxy osips[11458]: DBG:proto_tls:proto_tls_send:
after write: c=0x7fafa84997e8 n=360 fd=950
Oct  8 19:03:13 hvprxy osips[11460]: DBG:proto_tls:tcp_handle_req:
Nothing more to read on TCP conn 0x7fafa84997e8, currently in state 0

All this said, I can't say I'm totally sure I know what I would be
looking for. Nothing seems to stand out in the logs to me; but there
are a few gigs of logs so it's hard to quite know what I'm looking
for.

Andrew


On Sat, 9 Oct 2021 at 00:19, Bogdan-Andrei Iancu <bogdan at opensips.org> wrote:
>
> Hi Andrew,
>
> The second blocked process (doing the TLS/TCP stuff) surprisingly got
> stuck while waiting for a TCP fd from the TCP Main process.
>
> You mentioned that the logs of the UDP worker (doing the TCP send)
> suddenly stopped - around that time, do you see any errors from that
> process or from the TCP MAIN processes ?
>
> Regards,
>
> Bogdan-Andrei Iancu
>
> OpenSIPS Founder and Developer
>    https://www.opensips-solutions.com
> OpenSIPS eBootcamp 2021
>    https://opensips.org/training/OpenSIPS_eBootcamp_2021/
>
> On 10/8/21 2:43 PM, Andrew Yager wrote:
> > Hi Bogdan-Andrei,
> >
> > Have restarted since the last bt, but have recreated again and
> > attached. Earlier today we did also get another bt full on the second
> > blocked pid, but I didn't save it. In that case it was a UDP reply
> > from one of our upstream servers that had gone through mid_registrar
> > and was being relayed to a TCP endpoint. The TCP endpoint did have an
> > open file descriptor we could see, and it had sent and was blocked on
> > receive at the same point (I'm getting better at reading backtraces!
> > :D).
> >
> > The thing I do note is happening is that every example I have is a UDP
> > message being received from an upstream server being relayed to a
> > client on a TCP/TLS connection via a UDP worker.
> >
> > While we are using WolfSSL in this box, the other box where we have
> > the same behaviour (but I haven't taken backtraces yet) is running
> > OpenSSL and on 3.1.3; so it's not SSL library specific.
> >
> > I'm going to see if I can get a backtrace from the 3.1.3 box shortly.
> >
> > Andrew
> >
> > On Fri, 8 Oct 2021 at 17:13, Bogdan-Andrei Iancu <bogdan at opensips.org> wrote:
> >> Hi Andrew,
> >>
> >> OK, interesting progress here. So, the FIFO process blocks as it is
> >> trying to send an IPC JOB to an UDP process which looks like also being
> >> blocked.
> >>
> >> Could you attach with GDB to the that UDP blocked process too ? (you
> >> have its PID in the printing of the pt[x] in first gdb)
> >>
> >> Regards,
> >>
> >> Bogdan-Andrei Iancu
> >>
> >> OpenSIPS Founder and Developer
> >>     https://www.opensips-solutions.com
> >> OpenSIPS eBootcamp 2021
> >>     https://opensips.org/training/OpenSIPS_eBootcamp_2021/
> >>
> >> On 10/8/21 1:43 AM, Andrew Yager wrote:
> >>> Interestingly, where I usually see a range of continued messages from
> >>> a process continually in the debug log, they appear to stop for this
> >>> PID at 3:47am, and that process seems blocked on a tcp/tls send:
> >>>
> >>>
>

More information about the Users mailing list