[pjsip] Deadlock in crossing pjsua_call_answer with EOF-callback

Tue Mar 9 07:14:33 CST 2010

Hello all,

Recently we started testing our multi-line IVR solution, and
unfortunately we ran into a deadlock related to End-Of-File callback
of wav_player and answering or clearing of the call. There seems to be
a race-situation between pjsua glueing PJSIP and PJMedia.
A trace is included showing the answer/eof deadlock situation.

Our test-scenario:
Multiple accounts receiving incoming calls, which are answered and
then a prompt is being played. After playing, the call is cleared
again.

Part of our code flow (related to deadlock):
Answering of the calls is done by application and not on the back of
an callback from pjsua/pjsip (so from other thread).
Our callback of End-Of-File is registered via
pjmedia_wav_player_set_eof_cb() and is calling pjsua_player_destroy().

What happens (from trace)
1. A line is answered. Within the context of the application the
pjsua_call_answer() is called.
2. Within this pjsua_call_answer(), any media session (for that call)
is stopped and re-created and stream is started.
3. While still busy with step 2, the EOF is fired, calling our
EOF-callback which also executes the pjsua_player_destroy().
    => mind that this EOF is of a prompt-playing on another
line/account/call !!!
4. From that moment 3 + 2 are deadlocked. Also no new incoming
SIP-messages are being processed.

Comments with respect to the trace-file (it looks a bit different than
regular pjsip log):
- We're using a modified .Net wrapper originated from SIPEK project (pjsipDLL)
- Tracing is passed to our own logging mechanism using the log_writer callback.
- First 80% of traces is added to give indication WHAT is answered,
but gives no extra info regarding deadlock.

 ... stripped above...
08:11:53.343 | THRID:  5332 | sip_endpoint.c Processing incoming
message: Request msg INVITE/cseq=20 (rdata06B09DA4)
08:11:53.343 | THRID:  5332 | pjsua_core.c RX 941 bytes Request msg
INVITE/cseq=20 (rdata06B09DA4) from UDP 192.168.12.205:5060:
INVITE sip:2771 at 192.168.12.40 SIP/2.0
Via: SIP/2.0/UDP 192.168.12.205:5060;branch=z9hG4bK-6627909-28780
From: <sip:4100 at 192.168.12.205>;tag=662790920416
To: <sip:2771 at 192.168.12.40>
Call-ID: 662790914086 at 192.168.12.205
CSeq: 20 INVITE
Contact: <sip:4100 at 192.168.12.205:5060>
Max-Forwards: 70
User-Agent: SIP Server 9810.43.G
Privacy: none
P-Asserted-Identity: <sip:4100 at 192.168.12.205>
P-Asserted-Identity: <tel:4100>
Alert-Info: <internal-ring>
Diversion: <tel:9>;reason=unconditional
Allow: INVITE, ACK, CANCEL, BYE, OPTIONS, REFER, NOTIFY, SUBSCRIBE
Content-Type: application/sdp
Accept: application/sdp
Content-Length:   285
v=0
o=iS3000 20 20 IN IP4 192.168.12.205
s=-
c=IN IP4
08:11:53.343 | THRID:  5332 | pjsua_media.c Media index 0 selected for call 1
08:11:53.343 | THRID:  5332 | tsx07BE81EC Transaction created for
Request msg INVITE/cseq=20 (rdata06B09DA4)
08:11:53.343 | THRID:  5332 | tsx07BE81EC Incoming Request msg
INVITE/cseq=20 (rdata06B09DA4) in state Null
08:11:53.343 | THRID:  5332 | tsx07BE81EC State changed from Null to
Trying, event=RX_MSG
08:11:53.343 | THRID:  5332 | dlg06B14F54 Transaction tsx07BE81EC
state changed to Trying
08:11:53.343 | THRID:  5332 | dlg06B14F54 UAS dialog created
08:11:53.343 | THRID:  5332 | dlg06B14F54 Module mod-invite added as
dialog usage, data=07BE4ECC
08:11:53.343 | THRID:  5332 | dlg06B14F54 Session count inc to 2 by mod-invite
08:11:53.343 | THRID:  5332 | inv06B14F54 UAS invite session created
for dialog dlg06B14F54
08:11:53.343 | THRID:  5332 | pjsua_call.c Call 1: remote NAT type is
0 (Unknown)
08:11:53.343 | THRID:  5332 | endpoint Response msg 100/INVITE/cseq=20
(tdta07BE89B8) created
08:11:53.343 | THRID:  5332 | dlg06B14F54 Initial answer Response msg
100/INVITE/cseq=20 (tdta07BE89B8)
08:11:53.359 | THRID:  5332 | inv06B14F54 Sending Response msg
100/INVITE/cseq=20 (tdta07BE89B8)
08:11:53.359 | THRID:  5332 | dlg06B14F54 Sending Response msg
100/INVITE/cseq=20 (tdta07BE89B8)
08:11:53.359 | THRID:  5332 | tsx07BE81EC Sending Response msg
100/INVITE/cseq=20 (tdta07BE89B8) in state Trying
08:11:53.359 | THRID:  5332 | sip_resolve.c Target
'192.168.12.205:5060' type=UDP resolved to '192.168.12.205:5060'
type=UDP (UDP transport)
08:11:53.359 | THRID:  5332 | pjsua_core.c TX 268 bytes Response msg
100/INVITE/cseq=20 (tdta07BE89B8) to UDP 192.168.12.205:5060:
SIP/2.0 100 Trying
Via: SIP/2.0/UDP
192.168.12.205:5060;received=192.168.12.205;branch=z9hG4bK-6627909-28780
Call-ID: 662790914086 at 192.168.12.205
From: <sip:4100 at 192.168.12.205>;tag=662790920416
To: <sip:2771 at 192.168.12.40>
CSeq: 20 INVITE
Content-Length:  0
--end msg--
08:11:53.359 | THRID:  5332 | tsx07BE81EC State changed from Trying to
Proceeding, event=TX_MSG
08:11:53.359 | THRID:  5332 | dlg06B14F54 Transaction tsx07BE81EC
state changed to Proceeding
08:11:53.359 | THRID:  5332 | pjsua_call.c pjsua_call_on_state_changed()
08:11:53.359 | THRID:  5332 | pjsipDll:on_incoming_call(Account 1,
Call 1) callCount 374
08:11:53.359 | THRID:  5332 | pjsipDll:dll_answerCall(call 1, code 180)
08:11:53.359 | THRID:  5332 | inv06B14F54 Sending Response msg
180/INVITE/cseq=20 (tdta07BE89B8)
08:11:53.375 | THRID:  5332 | dlg06B14F54 Sending Response msg
180/INVITE/cseq=20 (tdta07BE89B8)
08:11:53.375 | THRID:  5332 | tsx07BE81EC Sending Response msg
180/INVITE/cseq=20 (tdta07BE89B8) in state Proceeding
08:11:53.375 | THRID:  5332 | pjsua_core.c TX 445 bytes Response msg
180/INVITE/cseq=20 (tdta07BE89B8) to UDP 192.168.12.205:5060:
SIP/2.0 180 Ringing
Via: SIP/2.0/UDP
192.168.12.205:5060;received=192.168.12.205;branch=z9hG4bK-6627909-28780
Call-ID: 662790914086 at 192.168.12.205
From: <sip:4100 at 192.168.12.205>;tag=662790920416
To: <sip:2771 at 192.168.12.40>;tag=4bdc3a9712e8477381692ffd5f42e615
CSeq: 20 INVITE
Contact: "2771" <sip:2771 at 192.168.12.40:4496>
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, SUBSCRIBE, NOTIFY,
REFER, MESSAGE, OPTIONS
Content-Length:  0
--end msg--
08:11:53.375 | THRID:  5332 | tsx07BE81EC State changed from
Proceeding to Proceeding, event=TX_MSG
08:11:53.375 | THRID:  5332 | dlg06B14F54 Transaction tsx07BE81EC
state changed to Proceeding
08:11:53.375 | THRID:  5332 | pjsua_call.c pjsua_call_on_state_changed()
08:11:53.375 | THRID:  5332 | pjsipDll:on_call_state(Call 1) state
changed to EARLY (180, Ringing)
08:11:53.375 | THRID:  5332 | pjsua_call.c
pjsua_call_on_state_changed() executed
08:11:53.375 | THRID:  5332 | pjsipDll:dll_answerCall(call 1, code
180); Status Success.

==> Start of the AnswerCall initiated by our application
08:11:53.468 | THRID:  4920 | pjsipDll:dll_answerCall(call 1, code 200)
08:11:53.468 | THRID:  4920 | inv06B14F54 SDP negotiation done, status=0
08:11:53.468 | THRID:  4920 | pjsua_call.c Call 1: remote NAT type is
0 (Unknown)
08:11:53.468 | THRID:  4920 | pjsua_media.c stop_media_session(1)
08:11:53.468 | THRID:  4920 | pjsua_media.c stop_media_session(1) executed
08:11:53.468 | THRID:  4920 | rtp.c pjmedia_rtp_session_init:
ses=07C0C214, default_pt=0, ssrc=0x1d2d3fd9
08:11:53.468 | THRID:  4920 | rtp.c pjmedia_rtp_session_init:
ses=07C0C838, default_pt=0, ssrc=0x1d2d3fd9

==> Start of EOF detection (this is a EOF of prompt started on other
sip account !!)
08:11:53.484 | THRID:  3500 | wav_player.c File port
C:\Prompts\message_002.wav EOF
08:11:53.484 | THRID:  3500 | pjsipDll:on_player_eof(Call 0): Player
has reached end of file.
08:11:53.484 | THRID:  3500 | pjsua_media.c pjsua_player_destroy. player_id=0
08:11:53.484 | THRID:  4920 | stream.c Stream strm07C0A99C created
08:11:53.484 | THRID:  4920 | strm07C0A99C Encoder stream started
08:11:53.484 | THRID:  4920 | strm07C0A99C Decoder stream started
08:11:53.968 | THRID:  5332 | tsx07BE735C Timeout timer event
08:11:53.968 | THRID:  5332 | tsx07BE735C State changed from Completed
to Terminated, event=TIMER
08:11:53.968 | THRID:  5332 | dlg07BF6D7C Transaction tsx07BE735C
state changed to Terminated
...no more tracing from PJSIP anymore... stuck...

Any suggestions?
In the meantime we're also working for a solution and/or work-around...

With regards,
Eize