pjsua blocked for about 6s after reinvite
Hi All,
to explain my problem the best way should be to show a commented log: The first part of the line is always the thread name or number.
incoming call from our pabx with sdp body
3355440704:SIP:DEBUG:15:55:46.109 pjsua_core.c .RX 1346 bytes Request msg INVITE/cseq=1765929166 (rdata0x7f2830003bb8) from UDP 10.151.129.148:5060:
We reply with 180
3355440704:SIP:DEBUG:15:55:46.112 pjsua_core.c ......TX 496 bytes Response msg 180/INVITE/cseq=1765929166 (tdta0x7f2830021d58) to UDP 10.151.129.148:5060:
we answer the call now with sdp body
SIP:SIP:DEBUG:15:55:51.252 pjsua_core.c ....TX 945 bytes Response msg 200/INVITE/cseq=1765929166 (tdta0x7f27f40af038) to UDP 10.151.129.148:5060:
The pabx does an ack as it should be
3355440704:SIP:DEBUG:15:55:51.255 pjsua_core.c .RX 386 bytes Request msg ACK/cseq=1765929166 (rdata0x7f2830003bb8) from UDP 10.151.129.148:5060:
For an unknown reason the papx sends an invite again, but without sdp body
3355440704:INVITE sip:894885@10.151.147.130:5060;ob SIP/2.0#015
3355440704:SIP:DEBUG:15:55:51.321 pjsua_call.c ......Call 0: asked to send a new offer
200OK is sent with sdp body
3355440704:SIP:DEBUG:15:55:51.321 pjsua_core.c ........TX 978 bytes Response msg 200/INVITE/cseq=1765929167 (tdta0x7f2830021d58) to UDP 10.151.129.148:5060:
The ack with sdp body is received
3355440704:SIP:DEBUG:15:55:51.339 pjsua_core.c .RX 704 bytes Request msg ACK/cseq=1765929167 (rdata0x7f2830003bb8) from UDP 10.151.129.148:5060:
3355440704:SIP:DEBUG:15:55:51.340 inv0x7f283000e0e8 ..SDP negotiation done: Success
3355440704:SIP:DEBUG:15:55:51.340 pjsua_media.c ...Call 0: updating media..
At this point the thread is blocked for about 6s
3355440704:SIP:DEBUG:15:55:57.573 pjsua_media.c .....Media stream call00:0 is destroyed
3355440704:SIP:DEBUG:15:55:57.573 pjsua_aud.c ....Audio channel update..
3355440704:SIP:DEBUG:15:55:57.573 strm0x7f2830024528 .....Encoder stream started
3355440704:SIP:DEBUG:15:55:57.573 strm0x7f2830024528 .....Decoder stream started
3355440704:SIP:DEBUG:15:55:57.573 pjsua_media.c ....Audio updated, stream #0: PCMA (sendrecv)
3355440704:Cpjsua::on_call_media_state():begin
After the callback the play frame function will be called with length=0 therefore no audio will be heard anymore.
In the meantime other threads do an resend of the 200OK after 500ms 1s and 2s
3841955392:SIP:DEBUG:15:55:51.823 pjsua_core.c .TX 978 bytes Response msg 200/INVITE/cseq=1765929167 (tdta0x7f2830021d58) to UDP 10.151.129.148:5060:
3841955392:SIP:DEBUG:15:55:52.824 pjsua_core.c .TX 978 bytes Response msg 200/INVITE/cseq=1765929167 (tdta0x7f2830021d58) to UDP 10.151.129.148:5060:
3841955392:SIP:DEBUG:15:55:54.823 pjsua_core.c .TX 978 bytes Response msg 200/INVITE/cseq=1765929167 (tdta0x7f2830021d58) to UDP 10.151.129.148:5060:
The answers to the resend will be received after 15:55:57.573 from the prior blocked thread 3355440704
Kind Regards
Holger
Backtrace in this case
Thread 42 (Thread 0x7fff477fe640 (LWP 28145) "SIP"):
#0 0x00007ffff47baea0 in __lll_lock_wait () from /lib64/libpthread.so.0
#1 0x00007ffff47b37f1 in pthread_mutex_lock () from /lib64/libpthread.so.0
#2 0x0000000000a63ad2 in pj_mutex_lock ()
#3 0x00000000009eb114 in pjmedia_conf_remove_port ()
#4 0x0000000000989824 in pjsua_conf_remove_port ()
#5 0x0000000000988fec in pjsua_aud_stop_stream ()
#6 0x000000000097ee7b in stop_media_stream ()
#7 0x000000000097ff58 in pjsua_media_channel_update ()
#8 0x000000000096e289 in pjsua_call_on_media_update ()
#9 0x0000000000994bc6 in inv_negotiate_sdp ()
#10 0x0000000000995242 in inv_check_sdp_in_incoming_msg ()
#11 0x0000000000992357 in mod_inv_on_rx_request ()
#12 0x00000000009daaee in pjsip_dlg_on_rx_request ()
#13 0x00000000009dc6ec in mod_ua_on_rx_request ()
#14 0x00000000009ba2b3 in pjsip_endpt_process_rx_data ()
#15 0x00000000009ba5a6 in endpt_on_rx_msg ()
#16 0x00000000009c349c in pjsip_tpmgr_receive_packet ()
#17 0x00000000009c44f0 in udp_on_read_complete ()
#18 0x0000000000a6057e in ioqueue_dispatch_read_event ()
#19 0x0000000000a62462 in pj_ioqueue_poll ()
#20 0x0000000000972749 in worker_thread_ioqueue ()
#21 0x0000000000a63173 in thread_main ()
#22 0x00007ffff47b13f9 in start_thread () from /lib64/libpthread.so.0
#23 0x00007ffff3da2903 in clone () from /lib64/libc.so.6
in debug build deadlock detection is on
1207957056:SIP:ERROR:10:32:01.008 pjsua_call.c !.Timed-out trying to acquire dialog mutex (possibly system has deadlocked) in reinv_timer_cb()
1207957056:SIP:DEBUG:10:32:01.008 pjsua_core.c .TX 976 bytes Response msg 200/INVITE/cseq=228954190 (tdta0x7fff480210e8) to UDP 10.151.129.148:5060:
1207957056:SIP/2.0 200 OK#015
Backtrace in this case
Thread 42 (Thread 0x7fff477fe640 (LWP 28145) "SIP"):
#0 0x00007ffff47baea0 in __lll_lock_wait () from /lib64/libpthread.so.0
#1 0x00007ffff47b37f1 in pthread_mutex_lock () from /lib64/libpthread.so.0
#2 0x0000000000a63ad2 in pj_mutex_lock ()
#3 0x00000000009eb114 in pjmedia_conf_remove_port ()
#4 0x0000000000989824 in pjsua_conf_remove_port ()
#5 0x0000000000988fec in pjsua_aud_stop_stream ()
#6 0x000000000097ee7b in stop_media_stream ()
#7 0x000000000097ff58 in pjsua_media_channel_update ()
#8 0x000000000096e289 in pjsua_call_on_media_update ()
#9 0x0000000000994bc6 in inv_negotiate_sdp ()
#10 0x0000000000995242 in inv_check_sdp_in_incoming_msg ()
#11 0x0000000000992357 in mod_inv_on_rx_request ()
#12 0x00000000009daaee in pjsip_dlg_on_rx_request ()
#13 0x00000000009dc6ec in mod_ua_on_rx_request ()
#14 0x00000000009ba2b3 in pjsip_endpt_process_rx_data ()
#15 0x00000000009ba5a6 in endpt_on_rx_msg ()
#16 0x00000000009c349c in pjsip_tpmgr_receive_packet ()
#17 0x00000000009c44f0 in udp_on_read_complete ()
#18 0x0000000000a6057e in ioqueue_dispatch_read_event ()
#19 0x0000000000a62462 in pj_ioqueue_poll ()
#20 0x0000000000972749 in worker_thread_ioqueue ()
#21 0x0000000000a63173 in thread_main ()
#22 0x00007ffff47b13f9 in start_thread () from /lib64/libpthread.so.0
#23 0x00007ffff3da2903 in clone () from /lib64/libc.so.6
in debug build deadlock detection is on
1207957056:SIP:ERROR:10:32:01.008 pjsua_call.c !.Timed-out trying to acquire dialog mutex (possibly system has deadlocked) in reinv_timer_cb()
1207957056:SIP:DEBUG:10:32:01.008 pjsua_core.c .TX 976 bytes Response msg 200/INVITE/cseq=228954190 (tdta0x7fff480210e8) to UDP 10.151.129.148:5060:
1207957056:SIP/2.0 200 OK#015