Call disconnected due to request timeout after a minute.

983 views
Skip to first unread message

anand prajapati

unread,
May 22, 2017, 4:32:26 AM5/22/17
to PJSIP experts
This is a great and extensive library. I am using Pjsua bindings for Java. Everything works fine but the call gets disconnected after a minute or so. Maximum duration for which it lasts is 71 seconds. This is happening for every single call. I have checked this on couple of different networks, so this must not be a firewall issue. I tried setting code priorities, but that didn't work out either. It seems I need to tweak some parameters during initialization of the library, but I fail to understand what exact parameters need to be tweaked. Is there any specific reason why I am getting request timeout followed by call disconnection ? 

PjSip Version : 2.6

I am getting the following logs -

13:49:52.280 os_core_unix.c !pjlib 2.6 for POSIX initialized
13:49:52.280 sip_endpoint.c  .Creating endpoint instance...
13:49:52.281          pjlib  .select() I/O Queue created (0x7f9c4792f4d8)
13:49:52.281 sip_endpoint.c  .Module "mod-msg-print" registered
13:49:52.281 sip_transport.  .Transport manager created.
13:49:52.281   pjsua_core.c  .PJSUA state changed: NULL --> CREATED
13:49:52.282 sip_endpoint.c  .Module "mod-pjsua-log" registered
13:49:52.282 sip_endpoint.c  .Module "mod-tsx-layer" registered
13:49:52.282 sip_endpoint.c  .Module "mod-stateful-util" registered
13:49:52.282 sip_endpoint.c  .Module "mod-ua" registered
13:49:52.282 sip_endpoint.c  .Module "mod-100rel" registered
13:49:52.282 sip_endpoint.c  .Module "mod-pjsua" registered
13:49:52.282 sip_endpoint.c  .Module "mod-invite" registered
13:49:52.321 coreaudio_dev.  ..core audio detected 3 devices
13:49:52.324 coreaudio_dev.  .. dev_id 0: Built-in Output  (in=0, out=2) 44100Hz
13:49:52.325 coreaudio_dev.  .. dev_id 1: Built-in Microphone  (in=2, out=0) 44100Hz
13:49:52.325 coreaudio_dev.  .. dev_id 2: Boom2Device  (in=2, out=2) 44100Hz
13:49:52.325 coreaudio_dev.  ..core audio initialized
13:49:52.325          pjlib  ..select() I/O Queue created (0x7f9c48069228)
13:49:52.325   conference.c  ..Creating conference bridge with 254 ports
13:49:52.325   Master/sound  ..Using delay buffer with WSOLA.
13:49:52.326 sip_endpoint.c  .Module "mod-evsub" registered
13:49:52.327 sip_endpoint.c  .Module "mod-presence" registered
13:49:52.327        evsub.c  .Event pkg "presence" registered by mod-presence
13:49:52.327 sip_endpoint.c  .Module "mod-mwi" registered
13:49:52.327        evsub.c  .Event pkg "message-summary" registered by mod-mwi
13:49:52.327 sip_endpoint.c  .Module "mod-refer" registered
13:49:52.327        evsub.c  .Event pkg "refer" registered by mod-refer
13:49:52.327 sip_endpoint.c  .Module "mod-pjsua-pres" registered
13:49:52.327 sip_endpoint.c  .Module "mod-pjsua-im" registered
13:49:52.327 sip_endpoint.c  .Module "mod-pjsua-options" registered
13:49:52.327   pjsua_core.c  .1 SIP worker threads created
13:49:52.327   pjsua_core.c  .pjsua version 2.6 for Darwin-16.6/x86_64 initialized
13:49:52.327   pjsua_core.c  .PJSUA state changed: CREATED --> INIT
13:49:52.328   pjsua_core.c  SIP UDP socket reachable at <sip_client_ip>
13:49:52.329 udp0x7f9c48ab4  SIP UDP transport started, published address is <sip_client_ip>
13:49:52.329    tcptp:53148  SIP TCP listener ready for incoming connections at 192.168.101.147:53148
13:49:52.329   pjsua_core.c  PJSUA state changed: INIT --> STARTING
13:49:52.329 sip_endpoint.c  .Module "mod-unsolicited-mwi" registered
13:49:52.329   pjsua_core.c  .PJSUA state changed: STARTING --> RUNNING
13:49:52.330   endpoint.cpp  pjsua_codec_set_priority(&codec_str, priority) error: Not found (PJ_ENOTFOUND) (status=70006) [../src/pjsua2/endpoint.cpp:1875]
13:49:52.379    pjsua_acc.c  Adding account: id=<sip_acc>
13:49:52.380    pjsua_acc.c  .Account <sip_acc> added with id 0
13:49:52.380    pjsua_acc.c  .Acc 0: setting registration..
13:49:52.380       endpoint  ..Request msg REGISTER/cseq=42611 (tdta0x7f9c481f1a00) created.
13:49:52.380 tsx0x7f9c481f2  ...Transaction created for Request msg REGISTER/cseq=42612 (tdta0x7f9c481f1a00)
13:49:52.380 tsx0x7f9c481f2  ..Sending Request msg REGISTER/cseq=42612 (tdta0x7f9c481f1a00) in state Null
13:49:52.384   pjsua_core.c  ...TX 581 bytes Request msg REGISTER/cseq=42612 (tdta0x7f9c481f1a00) to UDP <sip_server_ip>:5060:
REGISTER sip: SIP/2.0
Via: SIP/2.0/UDP <sip_client_ip>;rport;branch=z9hG4bKPjGqArR0Z5.QTmm6Lq0rWb5c7.qQoH0qPU
Route: <sip:;lr>
Max-Forwards: 70
From: <sip:>;tag=kMqoN3Lpi44-hTXX3oEkW.L.N-acWl3J
To: <sip:>
Call-ID: BhYb2RxCt4s1rrf7QLJ2mxog0qv5K9TB
CSeq: 42612 REGISTER
User-Agent: services.SipService
Contact: <sip:<callee account>;ob>
Expires: 90
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
Content-Length:  0


--end msg--
13:49:52.385 tsx0x7f9c481f2  ...State changed from Null to Calling, event=TX_MSG
13:49:52.385    pjsua_acc.c  ..Acc 0: Registration sent
13:49:52.469 sip_endpoint.c !Processing incoming message: Response msg 200/REGISTER/cseq=42612 (rdata0x7f9c481fe828)
13:49:52.469   pjsua_core.c  .RX 519 bytes Response msg 200/REGISTER/cseq=42612 (rdata0x7f9c481fe828) from UDP <sip_server_ip>:5060:
SIP/2.0 200 OK
Via: SIP/2.0/UDP <sip_client_ip>;rport=53900;branch=z9hG4bKPjGqArR0Z5.QTmm6Lq0rWb5c7.qQoH0qPU;received=<sip_client_ip>
From: <sip:<callee account>>;tag=kMqoN3Lpi44-hTXX3oEkW.L.N-acWl3J
To: <sip:<callee account>>;tag=b27e1a1d33761e85846fc98f5f3a7e58.fa4f
Call-ID: BhYb2RxCt4s1rrf7QLJ2mxog0qv5K9TB
CSeq: 42612 REGISTER
Contact: <sip:<caller_uri>;ob>;expires=36, <sip:anand@<sip_server>;ob>;expires=90
Server: kamailio (4.4.5 (x86_64/linux))
Content-Length: 0


--end msg--
13:49:52.469 tsx0x7f9c481f2  .Incoming Response msg 200/REGISTER/cseq=42612 (rdata0x7f9c481fe828) in state Calling
13:49:52.469 tsx0x7f9c481f2  ..State changed from Calling to Completed, event=RX_MSG
13:49:52.469    pjsua_acc.c  ....SIP outbound status for acc 0 is not active
13:49:52.469    pjsua_acc.c  ....IP address change detected for account 0 (<sip_client_ip> --> <sip_server>). Updating registration (using method 2)
13:49:52.470    pjsua_acc.c  ....Acc 0: setting registration..
13:49:52.470       endpoint  .....Request msg REGISTER/cseq=42612 (tdta0x7f9c493b8000) created.
13:49:52.470 tsx0x7f9c46e51  ......Transaction created for Request msg REGISTER/cseq=42613 (tdta0x7f9c493b8000)
13:49:52.470 tsx0x7f9c46e51  .....Sending Request msg REGISTER/cseq=42613 (tdta0x7f9c493b8000) in state Null
13:49:52.470  sip_resolve.c  ......DNS resolver not available, target '' type=Unspecified will be resolved with getaddrinfo()
13:49:52.471  sip_resolve.c  ......Target '' type=Unspecified resolved to '<sip_server_ip>:5060' type=UDP (UDP transport)
13:49:52.471   pjsua_core.c  ......TX 634 bytes Request msg REGISTER/cseq=42613 (tdta0x7f9c493b8000) to UDP <sip_server_ip>:5060:
REGISTER sip: SIP/2.0
Via: SIP/2.0/UDP <sip_server>;rport;branch=z9hG4bKPjJviPEN7hrHlhOsmfH1cvFVWvd5jH5Ayx
Route: <sip:;lr>
Max-Forwards: 70
From: <sip:<callee account>>;tag=ULhT8.zyhskjwxWKTYSr3mukUrO0CE1H
To: <sip:<callee account>>
Call-ID: BhYb2RxCt4s1rrf7QLJ2mxog0qv5K9TB
CSeq: 42613 REGISTER
User-Agent: services.SipService
Contact: <sip:anand@<sip_server>;ob>
Contact: <sip:<callee account>;ob>;expires=0
Expires: 90
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
Content-Length:  0


--end msg--
13:49:52.472 tsx0x7f9c46e51  ......State changed from Null to Calling, event=TX_MSG
13:49:52.472    pjsua_acc.c  .....Acc 0: Registration sent
13:49:52.553 sip_endpoint.c  Processing incoming message: Response msg 200/REGISTER/cseq=42613 (rdata0x7f9c49166628)
13:49:52.553   pjsua_core.c  .RX 519 bytes Response msg 200/REGISTER/cseq=42613 (rdata0x7f9c49166628) from UDP <sip_server_ip>:5060:
SIP/2.0 200 OK
Via: SIP/2.0/UDP <sip_client_ip>;rport=53900;branch=z9hG4bKPjJviPEN7hrHlhOsmfH1cvFVWvd5jH5Ayx;received=<sip_client_ip>
From: <sip:<callee account>>;tag=ULhT8.zyhskjwxWKTYSr3mukUrO0CE1H
To: <sip:<callee account>>;tag=b27e1a1d33761e85846fc98f5f3a7e58.fb3a
Call-ID: BhYb2RxCt4s1rrf7QLJ2mxog0qv5K9TB
CSeq: 42613 REGISTER
Contact: <sip:<caller_uri>;ob>;expires=36, <sip:anand@<sip_server>;ob>;expires=90
Server: kamailio (4.4.5 (x86_64/linux))
Content-Length: 0


--end msg--
13:49:52.553 tsx0x7f9c46e51  .Incoming Response msg 200/REGISTER/cseq=42613 (rdata0x7f9c49166628) in state Calling
13:49:52.553 tsx0x7f9c46e51  ..State changed from Calling to Completed, event=RX_MSG
13:49:52.553    pjsua_acc.c  ....SIP outbound status for acc 0 is not active
13:49:52.553    pjsua_acc.c  ....sip:anand@: registration success, status=200 (OK), will re-register in 90 seconds
13:49:52.553    pjsua_acc.c  ....Keep-alive timer started for acc 0, destination:<sip_server_ip>:5060, interval:15s

13:49:57.181 sip_endpoint.c  Processing incoming message: Request msg INVITE/cseq=31685 (rdata0x7f9c446a5028)
13:49:57.181   pjsua_core.c  .RX 1187 bytes Request msg INVITE/cseq=31685 (rdata0x7f9c446a5028) from UDP <sip_server_ip>:5060:
INVITE sip:<callee account>;ob SIP/2.0
Record-Route: <sip:<sip_route_ip>;lr>
Via: SIP/2.0/UDP <sip_route_ip>;branch=z9hG4bK17ce.a3aceb0ada02e2991a1eb086e8c7ccd6.1;rport
Via: SIP/2.0/UDP <sip_client_ip>:50052;received=<sip_client_ip>;rport=50052;branch=z9hG4bKPjGzXQGCjrdYtbKDzvW5xAKcSqH7pISVh2
Max-Forwards: 69
From: <sip:<caller account>>;tag=s0UvzHTONEIeBumrXH8Fs5YAOTB2ziu6
To: <sip:<callee account>>
Contact: <sip:<sip_caller_uri>;ob>
Call-ID: pMyYSVqb7a-.aWwQ8jyc-g.JMiSdZe0T
CSeq: 31685 INVITE
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
Supported: replaces, 100rel, timer, norefersub
Session-Expires: 1800
Min-SE: 90
User-Agent: CSipSimple_kenzo-23/r2457
Content-Type: application/sdp
Content-Length:382

v=0
o=- 3704429996 3704429996 IN IP4 192.168.101.137
s=pjmedia
i=(o=IN IP4 192.168.101.137)
c=IN IP4 192.168.101.137
t=0 0
m=audio 4000 RTP/AVP 99 0 8 101
c=IN IP4 192.168.101.137
a=rtcp:4001 IN IP4 192.168.101.137
a=sendrecv
a=rtpmap:99 SILK/24000
a=fmtp:99 useinbandfec=0
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16

--end msg--
13:49:57.181   pjsua_call.c  .Incoming Request msg INVITE/cseq=31685 (rdata0x7f9c446a5028)
13:49:57.181 tsx0x7f9c47dd5  ...Transaction created for Request msg INVITE/cseq=31685 (rdata0x7f9c446a5028)
13:49:57.181 tsx0x7f9c47dd5  ..Incoming Request msg INVITE/cseq=31685 (rdata0x7f9c446a5028) in state Null
13:49:57.181 tsx0x7f9c47dd5  ...State changed from Null to Trying, event=RX_MSG
13:49:57.181 dlg0x7f9c44629  ....Transaction tsx0x7f9c47dd56a8 state changed to Trying
13:49:57.181 dlg0x7f9c44629  ..UAS dialog created
13:49:57.181 dlg0x7f9c44629  ..Module mod-invite added as dialog usage, data=0x7f9c48dd14d8
13:49:57.181 dlg0x7f9c44629  ...Session count inc to 3 by mod-invite
13:49:57.181 inv0x7f9c44629  ..UAS invite session created for dialog dlg0x7f9c446298a8
13:49:57.181 dlg0x7f9c44629  ...Session count inc to 3 by mod-pjsua
13:49:57.181  pjsua_media.c  ..Call 0: initializing media..
13:49:57.181  pjsua_media.c  ...RTP socket reachable at 192.168.101.147:4000
13:49:57.181  pjsua_media.c  ...RTCP socket reachable at 192.168.101.147:4001
13:49:57.182  pjsua_media.c  ...Media index 0 selected for audio call 0
13:49:57.182  pjsua_media.c  ...Call 0: media transport initialization complete: Success
13:49:57.192   pjsua_call.c  ...Answering call 0: code=180
13:49:57.192   pjsua_call.c  ....Pending answering call 0 upon completion of media transport
13:49:57.266 dlg0x7f9c44629  ...Session count dec to 3 by mod-pjsua
13:49:57.266   pjsua_call.c  ..Call 0: remote NAT type is 0 (Unknown)
13:49:57.266       endpoint  ...Response msg 100/INVITE/cseq=31685 (tdta0x7f9c498d8e00) created
13:49:57.266 dlg0x7f9c44629  ...Initial answer Response msg 100/INVITE/cseq=31685 (tdta0x7f9c498d8e00)
13:49:57.266 inv0x7f9c44629  ...Sending Response msg 100/INVITE/cseq=31685 (tdta0x7f9c498d8e00)
13:49:57.266 dlg0x7f9c44629  ....Sending Response msg 100/INVITE/cseq=31685 (tdta0x7f9c498d8e00)
13:49:57.266 tsx0x7f9c47dd5  ....Sending Response msg 100/INVITE/cseq=31685 (tdta0x7f9c498d8e00) in state Trying
13:49:57.266   pjsua_core.c  .....TX 490 bytes Response msg 100/INVITE/cseq=31685 (tdta0x7f9c498d8e00) to UDP <sip_server_ip>:5060:
SIP/2.0 100 Trying
Via: SIP/2.0/UDP <sip_route_ip>;rport=5060;received=<sip_server_ip>;branch=z9hG4bK17ce.a3aceb0ada02e2991a1eb086e8c7ccd6.1
Via: SIP/2.0/UDP <sip_client_ip>:50052;rport=50052;received=<sip_client_ip>;branch=z9hG4bKPjGzXQGCjrdYtbKDzvW5xAKcSqH7pISVh2
Record-Route: <sip:<sip_route_ip>;lr>
Call-ID: pMyYSVqb7a-.aWwQ8jyc-g.JMiSdZe0T
From: <sip:<caller account>>;tag=s0UvzHTONEIeBumrXH8Fs5YAOTB2ziu6
To: <sip:<callee account>>
CSeq: 31685 INVITE
Content-Length:  0


--end msg--
13:49:57.267 tsx0x7f9c47dd5  .....State changed from Trying to Proceeding, event=TX_MSG
13:49:57.267 dlg0x7f9c44629  ......Transaction tsx0x7f9c47dd56a8 state changed to Proceeding
13:49:57.267   pjsua_call.c  ..Answering call 0: code=180
13:49:57.267 inv0x7f9c44629  ....Sending Response msg 180/INVITE/cseq=31685 (tdta0x7f9c498d8e00)
13:49:57.267 dlg0x7f9c44629  .....Sending Response msg 180/INVITE/cseq=31685 (tdta0x7f9c498d8e00)
13:49:57.267 tsx0x7f9c47dd5  .....Sending Response msg 180/INVITE/cseq=31685 (tdta0x7f9c498d8e00) in state Proceeding
13:49:57.267   pjsua_core.c  ......TX 671 bytes Response msg 180/INVITE/cseq=31685 (tdta0x7f9c498d8e00) to UDP <sip_server_ip>:5060:
SIP/2.0 180 Ringing
Via: SIP/2.0/UDP <sip_route_ip>;rport=5060;received=<sip_server_ip>;branch=z9hG4bK17ce.a3aceb0ada02e2991a1eb086e8c7ccd6.1
Via: SIP/2.0/UDP <sip_client_ip>:50052;rport=50052;received=<sip_client_ip>;branch=z9hG4bKPjGzXQGCjrdYtbKDzvW5xAKcSqH7pISVh2
Record-Route: <sip:<sip_route_ip>;lr>
Call-ID: pMyYSVqb7a-.aWwQ8jyc-g.JMiSdZe0T
From: <sip:<caller account>>;tag=s0UvzHTONEIeBumrXH8Fs5YAOTB2ziu6
To: <sip:<callee account>>;tag=n1HHSdGPkEDw3EppCeHuzi1KlUTfk12h
CSeq: 31685 INVITE
Contact: <sip:anand@<sip_server>;ob>
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
Content-Length:  0


--end msg--
13:49:57.268 tsx0x7f9c47dd5  ......State changed from Proceeding to Proceeding, event=TX_MSG
13:49:57.268 dlg0x7f9c44629  .......Transaction tsx0x7f9c47dd56a8 state changed to Proceeding
13:49:57.469 tsx0x7f9c481f2  Timeout timer event
13:49:57.469 tsx0x7f9c481f2  .State changed from Completed to Terminated, event=TIMER
13:49:57.469 tsx0x7f9c481f2  Timeout timer event
13:49:57.469 tsx0x7f9c481f2  .State changed from Terminated to Destroyed, event=TIMER
13:49:57.469 tdta0x7f9c481f  ..Destroying txdata Request msg REGISTER/cseq=42612 (tdta0x7f9c481f1a00)
13:49:57.469 tsx0x7f9c481f2  Transaction destroyed!
13:49:57.553 tsx0x7f9c46e51  Timeout timer event
13:49:57.554 tsx0x7f9c46e51  .State changed from Completed to Terminated, event=TIMER
13:49:57.554 tsx0x7f9c46e51  Timeout timer event
13:49:57.554 tsx0x7f9c46e51  .State changed from Terminated to Destroyed, event=TIMER
13:49:57.554 tdta0x7f9c493b  ..Destroying txdata Request msg REGISTER/cseq=42613 (tdta0x7f9c493b8000)
13:49:57.554 tsx0x7f9c46e51  Transaction destroyed!

13:49:59.378   pjsua_call.c !Answering call 0: code=200
13:49:59.378 inv0x7f9c44629  ..SDP negotiation done, status=0
13:49:59.378   pjsua_call.c  ...Call 0: remote NAT type is 0 (Unknown)
13:49:59.378  pjsua_media.c  ...Call 0: updating media..
13:49:59.378    pjsua_aud.c  ....Audio channel update..
13:49:59.378 strm0x7f9c4982  .....VAD temporarily disabled
13:49:59.378          rtp.c  .....pjmedia_rtp_session_init: ses=0x7f9c499b2724, default_pt=0, ssrc=0x4ea3bc1b
13:49:59.378          rtp.c  .....pjmedia_rtp_session_init: ses=0x7f9c49828614, default_pt=0, ssrc=0x4ea3bc1b
13:49:59.378       stream.c  .....Stream strm0x7f9c49826c28 created
13:49:59.378 strm0x7f9c4982  .....Encoder stream started
13:49:59.378 strm0x7f9c4982  .....Decoder stream started
13:49:59.378     resample.c  .....resample created: high qualiy, large filter, in/out rate=8000/16000
13:49:59.378     resample.c  .....resample created: high qualiy, large filter, in/out rate=16000/8000
13:49:59.378  pjsua_media.c  ....Audio updated, stream #0: PCMU (sendrecv)
13:49:59.384 inv0x7f9c44629  ..Sending Response msg 200/INVITE/cseq=31685 (tdta0x7f9c498d8e00)
13:49:59.384 dlg0x7f9c44629  ...Sending Response msg 200/INVITE/cseq=31685 (tdta0x7f9c498d8e00)
13:49:59.384 tsx0x7f9c47dd5  ...Sending Response msg 200/INVITE/cseq=31685 (tdta0x7f9c498d8e00) in state Proceeding
13:49:59.384   pjsua_core.c  ....TX 1084 bytes Response msg 200/INVITE/cseq=31685 (tdta0x7f9c498d8e00) to UDP <sip_server_ip>:5060:
SIP/2.0 200 OK
Via: SIP/2.0/UDP <sip_route_ip>;rport=5060;received=<sip_server_ip>;branch=z9hG4bK17ce.a3aceb0ada02e2991a1eb086e8c7ccd6.1
Via: SIP/2.0/UDP <sip_client_ip>:50052;rport=50052;received=<sip_client_ip>;branch=z9hG4bKPjGzXQGCjrdYtbKDzvW5xAKcSqH7pISVh2
Record-Route: <sip:<sip_route_ip>;lr>
Call-ID: pMyYSVqb7a-.aWwQ8jyc-g.JMiSdZe0T
From: <sip:<caller account>>;tag=s0UvzHTONEIeBumrXH8Fs5YAOTB2ziu6
To: <sip:<callee account>>;tag=n1HHSdGPkEDw3EppCeHuzi1KlUTfk12h
CSeq: 31685 INVITE
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
Contact: <sip:anand@<sip_server>;ob>
Supported: replaces, 100rel, timer, norefersub
Session-Expires: 1800;refresher=uac
Require: timer
Content-Type: application/sdp
Content-Length:   283

v=0
o=- 3704429997 3704429998 IN IP4 192.168.101.147
s=pjmedia
b=AS:84
t=0 0
a=X-nat:0
m=audio 4000 RTP/AVP 0 101
c=IN IP4 192.168.101.147
b=TIAS:64000
a=rtcp:4001 IN IP4 192.168.101.147
a=sendrecv
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16

--end msg--
13:49:59.384 tsx0x7f9c47dd5  ....State changed from Proceeding to Completed, event=TX_MSG
13:49:59.384 dlg0x7f9c44629  .....Transaction tsx0x7f9c47dd56a8 state changed to Completed
13:49:59.385    pjsua_aud.c  Creating file player: /var/folders/6l/hrzdzgpn36l8f5ck9qf9__yr0000gn/T/c12ff594-5ab2-4a46-a2d0-bd405e6f373f.wav..
13:49:59.385   wav_player.c  .File player '/var/folders/6l/hrzdzgpn36l8f5ck9qf9__yr0000gn/T/c12ff594-5ab2-4a46-a2d0-bd405e6f373f.wav' created: samp.rate=48000, ch=1, bufsize=4KB, filesize=292KB
13:49:59.385     resample.c  .resample created: high qualiy, large filter, in/out rate=48000/16000
13:49:59.385     resample.c  .resample created: high qualiy, large filter, in/out rate=16000/48000
13:49:59.385    pjsua_aud.c  .Player created, id=0, slot=2
13:49:59.385    pjsua_aud.c  Conf connect: 2 --> 1
13:49:59.385    pjsua_aud.c  .Set sound device: capture=-1, playback=-2
13:49:59.385    pjsua_aud.c  ..Opening sound device (speaker + mic) PCM@16000/1/20ms
13:49:59.394 coreaudio_dev.  ...Opening device 39
13:49:59.407 ec0x7f9c4a1111  ...Creating AEC
13:49:59.407 ec0x7f9c4a1111  ...AEC created, clock_rate=16000, channel=1, samples per frame=320, tail length=196 ms, latency=0 ms
13:49:59.423 coreaudio_dev.  ...core audio stream started
13:49:59.431 coreaudio_dev. !Player thread started, (186 frames)
13:49:59.432 strm0x7f9c4982  Start talksprut..
13:49:59.432          speex  warning: discarded first playback frame
13:49:59.432 os_core_unix.c  Info: possibly re-registering existing thread
13:49:59.432 coreaudio_dev. !Recorder thread started, (512 frames)
13:49:59.443          speex  warning: discarded first playback frame
13:49:59.450   conference.c !.Port 2 (/var/folders/6l/hrzdzgpn36l8f5ck9qf9__yr0000gn/T/c12ff594-5ab2-4a46-a2d0-bd405e6f373f.wav) transmitting to port 1 (sip:<caller account>)
13:49:59.548 strm0x7f9c4982 !RTP status: badpt=0, badssrc=0, dup=0, outorder=0, probation=-1, restart=0
13:49:59.885 tsx0x7f9c47dd5 !Retransmit timer event
13:49:59.885 tsx0x7f9c47dd5  .Retransmiting Response msg 200/INVITE/cseq=31685 (tdta0x7f9c498d8e00), count=0, restart?=1
13:49:59.885   pjsua_core.c  .TX 1084 bytes Response msg 200/INVITE/cseq=31685 (tdta0x7f9c498d8e00) to UDP <sip_server_ip>:5060:
SIP/2.0 200 OK
Via: SIP/2.0/UDP <sip_route_ip>;rport=5060;received=<sip_server_ip>;branch=z9hG4bK17ce.a3aceb0ada02e2991a1eb086e8c7ccd6.1
Via: SIP/2.0/UDP <sip_client_ip>:50052;rport=50052;received=<sip_client_ip>;branch=z9hG4bKPjGzXQGCjrdYtbKDzvW5xAKcSqH7pISVh2
Record-Route: <sip:<sip_route_ip>;lr>
Call-ID: pMyYSVqb7a-.aWwQ8jyc-g.JMiSdZe0T
From: <sip:<caller account>>;tag=s0UvzHTONEIeBumrXH8Fs5YAOTB2ziu6
To: <sip:<callee account>>;tag=n1HHSdGPkEDw3EppCeHuzi1KlUTfk12h
CSeq: 31685 INVITE
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
Contact: <sip:anand@<sip_server>;ob>
Supported: replaces, 100rel, timer, norefersub
Session-Expires: 1800;refresher=uac
Require: timer
Content-Type: application/sdp
Content-Length:   283

v=0
o=- 3704429997 3704429998 IN IP4 192.168.101.147
s=pjmedia
b=AS:84
t=0 0
a=X-nat:0
m=audio 4000 RTP/AVP 0 101
c=IN IP4 192.168.101.147
b=TIAS:64000
a=rtcp:4001 IN IP4 192.168.101.147
a=sendrecv
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16

--end msg--
13:50:00.047 strm0x7f9c4982 !VAD re-enabled
13:50:00.047 strm0x7f9c4982  Starting silence
13:50:00.105   silencedet.c  Starting talk burst (level=1210 threshold=1000)
13:50:00.105 strm0x7f9c4982  Start talksprut..
13:50:00.885 tsx0x7f9c47dd5 !Retransmit timer event
13:50:00.885 tsx0x7f9c47dd5  .Retransmiting Response msg 200/INVITE/cseq=31685 (tdta0x7f9c498d8e00), count=1, restart?=1
13:50:00.886   pjsua_core.c  .TX 1084 bytes Response msg 200/INVITE/cseq=31685 (tdta0x7f9c498d8e00) to UDP <sip_server_ip>:5060:
SIP/2.0 200 OK
Via: SIP/2.0/UDP <sip_route_ip>;rport=5060;received=<sip_server_ip>;branch=z9hG4bK17ce.a3aceb0ada02e2991a1eb086e8c7ccd6.1
Via: SIP/2.0/UDP <sip_client_ip>:50052;rport=50052;received=<sip_client_ip>;branch=z9hG4bKPjGzXQGCjrdYtbKDzvW5xAKcSqH7pISVh2
Record-Route: <sip:<sip_route_ip>;lr>
Call-ID: pMyYSVqb7a-.aWwQ8jyc-g.JMiSdZe0T
From: <sip:<caller account>>;tag=s0UvzHTONEIeBumrXH8Fs5YAOTB2ziu6
To: <sip:<callee account>>;tag=n1HHSdGPkEDw3EppCeHuzi1KlUTfk12h
CSeq: 31685 INVITE
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
Contact: <sip:anand@<sip_server>;ob>
Supported: replaces, 100rel, timer, norefersub
Session-Expires: 1800;refresher=uac
Require: timer
Content-Type: application/sdp
Content-Length:   283

v=0
o=- 3704429997 3704429998 IN IP4 192.168.101.147
s=pjmedia
b=AS:84
t=0 0
a=X-nat:0
m=audio 4000 RTP/AVP 0 101
c=IN IP4 192.168.101.147
b=TIAS:64000
a=rtcp:4001 IN IP4 192.168.101.147
a=sendrecv
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16

--end msg--
13:50:02.531   wav_player.c !File port /var/folders/6l/hrzdzgpn36l8f5ck9qf9__yr0000gn/T/c12ff594-5ab2-4a46-a2d0-bd405e6f373f.wav EOF
13:50:02.532   wav_player.c  File port /var/folders/6l/hrzdzgpn36l8f5ck9qf9__yr0000gn/T/c12ff594-5ab2-4a46-a2d0-bd405e6f373f.wav rewinding..
13:50:02.886 tsx0x7f9c47dd5 !Retransmit timer event
13:50:02.886 tsx0x7f9c47dd5  .Retransmiting Response msg 200/INVITE/cseq=31685 (tdta0x7f9c498d8e00), count=2, restart?=1
13:50:02.886   pjsua_core.c  .TX 1084 bytes Response msg 200/INVITE/cseq=31685 (tdta0x7f9c498d8e00) to UDP <sip_server_ip>:5060:
SIP/2.0 200 OK
Via: SIP/2.0/UDP <sip_route_ip>;rport=5060;received=<sip_server_ip>;branch=z9hG4bK17ce.a3aceb0ada02e2991a1eb086e8c7ccd6.1
Via: SIP/2.0/UDP <sip_client_ip>:50052;rport=50052;received=<sip_client_ip>;branch=z9hG4bKPjGzXQGCjrdYtbKDzvW5xAKcSqH7pISVh2
Record-Route: <sip:<sip_route_ip>;lr>
Call-ID: pMyYSVqb7a-.aWwQ8jyc-g.JMiSdZe0T
From: <sip:<caller account>>;tag=s0UvzHTONEIeBumrXH8Fs5YAOTB2ziu6
To: <sip:<callee account>>;tag=n1HHSdGPkEDw3EppCeHuzi1KlUTfk12h
CSeq: 31685 INVITE
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
Contact: <sip:anand@<sip_server>;ob>
Supported: replaces, 100rel, timer, norefersub
Session-Expires: 1800;refresher=uac
Require: timer
Content-Type: application/sdp
Content-Length:   283

v=0
o=- 3704429997 3704429998 IN IP4 192.168.101.147
s=pjmedia
b=AS:84
t=0 0
a=X-nat:0
m=audio 4000 RTP/AVP 0 101
c=IN IP4 192.168.101.147
b=TIAS:64000
a=rtcp:4001 IN IP4 192.168.101.147
a=sendrecv
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16

--end msg--
13:50:04.424   sound_port.c !EC suspended because of inactivity
13:50:05.562   wav_player.c  File port /var/folders/6l/hrzdzgpn36l8f5ck9qf9__yr0000gn/T/c12ff594-5ab2-4a46-a2d0-bd405e6f373f.wav EOF
13:50:05.563   wav_player.c  File port /var/folders/6l/hrzdzgpn36l8f5ck9qf9__yr0000gn/T/c12ff594-5ab2-4a46-a2d0-bd405e6f373f.wav rewinding..
13:50:06.888 tsx0x7f9c47dd5 !Retransmit timer event
13:50:06.888 tsx0x7f9c47dd5  .Retransmiting Response msg 200/INVITE/cseq=31685 (tdta0x7f9c498d8e00), count=3, restart?=1
13:50:06.888   pjsua_core.c  .TX 1084 bytes Response msg 200/INVITE/cseq=31685 (tdta0x7f9c498d8e00) to UDP <sip_server_ip>:5060:
SIP/2.0 200 OK
Via: SIP/2.0/UDP <sip_route_ip>;rport=5060;received=<sip_server_ip>;branch=z9hG4bK17ce.a3aceb0ada02e2991a1eb086e8c7ccd6.1
Via: SIP/2.0/UDP <sip_client_ip>:50052;rport=50052;received=<sip_client_ip>;branch=z9hG4bKPjGzXQGCjrdYtbKDzvW5xAKcSqH7pISVh2
Record-Route: <sip:<sip_route_ip>;lr>
Call-ID: pMyYSVqb7a-.aWwQ8jyc-g.JMiSdZe0T
From: <sip:<caller account>>;tag=s0UvzHTONEIeBumrXH8Fs5YAOTB2ziu6
To: <sip:<callee account>>;tag=n1HHSdGPkEDw3EppCeHuzi1KlUTfk12h
CSeq: 31685 INVITE
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
Contact: <sip:anand@<sip_server>;ob>
Supported: replaces, 100rel, timer, norefersub
Session-Expires: 1800;refresher=uac
Require: timer
Content-Type: application/sdp
Content-Length:   283

v=0
o=- 3704429997 3704429998 IN IP4 192.168.101.147
s=pjmedia
b=AS:84
t=0 0
a=X-nat:0
m=audio 4000 RTP/AVP 0 101
c=IN IP4 192.168.101.147
b=TIAS:64000
a=rtcp:4001 IN IP4 192.168.101.147
a=sendrecv
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16

--end msg--
13:50:07.554    pjsua_acc.c  Sending 2 bytes keep-alive packet for acc 0 to <sip_server_ip>:5060
13:50:07.554 tdta0x7f9c47d7  Destroying txdata raw
13:50:08.604   wav_player.c !File port /var/folders/6l/hrzdzgpn36l8f5ck9qf9__yr0000gn/T/c12ff594-5ab2-4a46-a2d0-bd405e6f373f.wav EOF
13:50:08.604   wav_player.c  File port /var/folders/6l/hrzdzgpn36l8f5ck9qf9__yr0000gn/T/c12ff594-5ab2-4a46-a2d0-bd405e6f373f.wav rewinding..
13:50:10.890 tsx0x7f9c47dd5 !Retransmit timer event
13:50:10.890 tsx0x7f9c47dd5  .Retransmiting Response msg 200/INVITE/cseq=31685 (tdta0x7f9c498d8e00), count=4, restart?=1
13:50:10.890   pjsua_core.c  .TX 1084 bytes Response msg 200/INVITE/cseq=31685 (tdta0x7f9c498d8e00) to UDP <sip_server_ip>:5060:
SIP/2.0 200 OK
Via: SIP/2.0/UDP <sip_route_ip>;rport=5060;received=<sip_server_ip>;branch=z9hG4bK17ce.a3aceb0ada02e2991a1eb086e8c7ccd6.1
Via: SIP/2.0/UDP <sip_client_ip>:50052;rport=50052;received=<sip_client_ip>;branch=z9hG4bKPjGzXQGCjrdYtbKDzvW5xAKcSqH7pISVh2
Record-Route: <sip:<sip_route_ip>;lr>
Call-ID: pMyYSVqb7a-.aWwQ8jyc-g.JMiSdZe0T
From: <sip:<caller account>>;tag=s0UvzHTONEIeBumrXH8Fs5YAOTB2ziu6
To: <sip:<callee account>>;tag=n1HHSdGPkEDw3EppCeHuzi1KlUTfk12h
CSeq: 31685 INVITE
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
Contact: <sip:anand@<sip_server>;ob>
Supported: replaces, 100rel, timer, norefersub
Session-Expires: 1800;refresher=uac
Require: timer
Content-Type: application/sdp
Content-Length:   283

v=0
o=- 3704429997 3704429998 IN IP4 192.168.101.147
s=pjmedia
b=AS:84
t=0 0
a=X-nat:0
m=audio 4000 RTP/AVP 0 101
c=IN IP4 192.168.101.147
b=TIAS:64000
a=rtcp:4001 IN IP4 192.168.101.147
a=sendrecv
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16

--end msg--
13:50:11.646   wav_player.c !File port /var/folders/6l/hrzdzgpn36l8f5ck9qf9__yr0000gn/T/c12ff594-5ab2-4a46-a2d0-bd405e6f373f.wav EOF
13:50:11.647   wav_player.c  File port /var/folders/6l/hrzdzgpn36l8f5ck9qf9__yr0000gn/T/c12ff594-5ab2-4a46-a2d0-bd405e6f373f.wav rewinding..
13:50:14.712   wav_player.c  File port /var/folders/6l/hrzdzgpn36l8f5ck9qf9__yr0000gn/T/c12ff594-5ab2-4a46-a2d0-bd405e6f373f.wav EOF
13:50:14.712   wav_player.c  File port /var/folders/6l/hrzdzgpn36l8f5ck9qf9__yr0000gn/T/c12ff594-5ab2-4a46-a2d0-bd405e6f373f.wav rewinding..
13:50:14.890 tsx0x7f9c47dd5 !Retransmit timer event
13:50:14.890 tsx0x7f9c47dd5  .Retransmiting Response msg 200/INVITE/cseq=31685 (tdta0x7f9c498d8e00), count=5, restart?=1
13:50:14.890   pjsua_core.c  .TX 1084 bytes Response msg 200/INVITE/cseq=31685 (tdta0x7f9c498d8e00) to UDP <sip_server_ip>:5060:
SIP/2.0 200 OK
Via: SIP/2.0/UDP <sip_route_ip>;rport=5060;received=<sip_server_ip>;branch=z9hG4bK17ce.a3aceb0ada02e2991a1eb086e8c7ccd6.1
Via: SIP/2.0/UDP <sip_client_ip>:50052;rport=50052;received=<sip_client_ip>;branch=z9hG4bKPjGzXQGCjrdYtbKDzvW5xAKcSqH7pISVh2
Record-Route: <sip:<sip_route_ip>;lr>
Call-ID: pMyYSVqb7a-.aWwQ8jyc-g.JMiSdZe0T
From: <sip:<caller account>>;tag=s0UvzHTONEIeBumrXH8Fs5YAOTB2ziu6
To: <sip:<callee account>>;tag=n1HHSdGPkEDw3EppCeHuzi1KlUTfk12h
CSeq: 31685 INVITE
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
Contact: <sip:anand@<sip_server>;ob>
Supported: replaces, 100rel, timer, norefersub
Session-Expires: 1800;refresher=uac
Require: timer
Content-Type: application/sdp
Content-Length:   283

v=0
o=- 3704429997 3704429998 IN IP4 192.168.101.147
s=pjmedia
b=AS:84
t=0 0
a=X-nat:0
m=audio 4000 RTP/AVP 0 101
c=IN IP4 192.168.101.147
b=TIAS:64000
a=rtcp:4001 IN IP4 192.168.101.147
a=sendrecv
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16

--end msg--
13:50:17.741   wav_player.c !File port /var/folders/6l/hrzdzgpn36l8f5ck9qf9__yr0000gn/T/c12ff594-5ab2-4a46-a2d0-bd405e6f373f.wav EOF
13:50:17.741   wav_player.c  File port /var/folders/6l/hrzdzgpn36l8f5ck9qf9__yr0000gn/T/c12ff594-5ab2-4a46-a2d0-bd405e6f373f.wav rewinding..
13:50:18.891 tsx0x7f9c47dd5 !Retransmit timer event
13:50:18.891 tsx0x7f9c47dd5  .Retransmiting Response msg 200/INVITE/cseq=31685 (tdta0x7f9c498d8e00), count=6, restart?=1
13:50:18.891   pjsua_core.c  .TX 1084 bytes Response msg 200/INVITE/cseq=31685 (tdta0x7f9c498d8e00) to UDP <sip_server_ip>:5060:
SIP/2.0 200 OK
Via: SIP/2.0/UDP <sip_route_ip>;rport=5060;received=<sip_server_ip>;branch=z9hG4bK17ce.a3aceb0ada02e2991a1eb086e8c7ccd6.1
Via: SIP/2.0/UDP <sip_client_ip>:50052;rport=50052;received=<sip_client_ip>;branch=z9hG4bKPjGzXQGCjrdYtbKDzvW5xAKcSqH7pISVh2
Record-Route: <sip:<sip_route_ip>;lr>
Call-ID: pMyYSVqb7a-.aWwQ8jyc-g.JMiSdZe0T
From: <sip:<caller account>>;tag=s0UvzHTONEIeBumrXH8Fs5YAOTB2ziu6
To: <sip:<callee account>>;tag=n1HHSdGPkEDw3EppCeHuzi1KlUTfk12h
CSeq: 31685 INVITE
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
Contact: <sip:anand@<sip_server>;ob>
Supported: replaces, 100rel, timer, norefersub
Session-Expires: 1800;refresher=uac
Require: timer
Content-Type: application/sdp
Content-Length:   283

v=0
o=- 3704429997 3704429998 IN IP4 192.168.101.147
s=pjmedia
b=AS:84
t=0 0
a=X-nat:0
m=audio 4000 RTP/AVP 0 101
c=IN IP4 192.168.101.147
b=TIAS:64000
a=rtcp:4001 IN IP4 192.168.101.147
a=sendrecv
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16

--end msg--
13:50:20.783   wav_player.c !File port /var/folders/6l/hrzdzgpn36l8f5ck9qf9__yr0000gn/T/c12ff594-5ab2-4a46-a2d0-bd405e6f373f.wav EOF
13:50:20.783   wav_player.c  File port /var/folders/6l/hrzdzgpn36l8f5ck9qf9__yr0000gn/T/c12ff594-5ab2-4a46-a2d0-bd405e6f373f.wav rewinding..
13:50:22.555    pjsua_acc.c !Sending 2 bytes keep-alive packet for acc 0 to <sip_server_ip>:5060
13:50:22.556 tdta0x7f9c4474  Destroying txdata raw
13:50:22.891 tsx0x7f9c47dd5  Retransmit timer event
13:50:22.891 tsx0x7f9c47dd5  .Retransmiting Response msg 200/INVITE/cseq=31685 (tdta0x7f9c498d8e00), count=7, restart?=1
13:50:22.891   pjsua_core.c  .TX 1084 bytes Response msg 200/INVITE/cseq=31685 (tdta0x7f9c498d8e00) to UDP <sip_server_ip>:5060:
SIP/2.0 200 OK
Via: SIP/2.0/UDP <sip_route_ip>;rport=5060;received=<sip_server_ip>;branch=z9hG4bK17ce.a3aceb0ada02e2991a1eb086e8c7ccd6.1
Via: SIP/2.0/UDP <sip_client_ip>:50052;rport=50052;received=<sip_client_ip>;branch=z9hG4bKPjGzXQGCjrdYtbKDzvW5xAKcSqH7pISVh2
Record-Route: <sip:<sip_route_ip>;lr>
Call-ID: pMyYSVqb7a-.aWwQ8jyc-g.JMiSdZe0T
From: <sip:<caller account>>;tag=s0UvzHTONEIeBumrXH8Fs5YAOTB2ziu6
To: <sip:<callee account>>;tag=n1HHSdGPkEDw3EppCeHuzi1KlUTfk12h
CSeq: 31685 INVITE
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
Contact: <sip:anand@<sip_server>;ob>
Supported: replaces, 100rel, timer, norefersub
Session-Expires: 1800;refresher=uac
Require: timer
Content-Type: application/sdp
Content-Length:   283

v=0
o=- 3704429997 3704429998 IN IP4 192.168.101.147
s=pjmedia
b=AS:84
t=0 0
a=X-nat:0
m=audio 4000 RTP/AVP 0 101
c=IN IP4 192.168.101.147
b=TIAS:64000
a=rtcp:4001 IN IP4 192.168.101.147
a=sendrecv
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16

--end msg--
13:50:23.825   wav_player.c !File port /var/folders/6l/hrzdzgpn36l8f5ck9qf9__yr0000gn/T/c12ff594-5ab2-4a46-a2d0-bd405e6f373f.wav EOF
13:50:23.825   wav_player.c  File port /var/folders/6l/hrzdzgpn36l8f5ck9qf9__yr0000gn/T/c12ff594-5ab2-4a46-a2d0-bd405e6f373f.wav rewinding..
13:50:26.890   wav_player.c  File port /var/folders/6l/hrzdzgpn36l8f5ck9qf9__yr0000gn/T/c12ff594-5ab2-4a46-a2d0-bd405e6f373f.wav EOF
13:50:26.890   wav_player.c  File port /var/folders/6l/hrzdzgpn36l8f5ck9qf9__yr0000gn/T/c12ff594-5ab2-4a46-a2d0-bd405e6f373f.wav rewinding..
13:50:26.891 tsx0x7f9c47dd5 !Retransmit timer event
13:50:26.891 tsx0x7f9c47dd5  .Retransmiting Response msg 200/INVITE/cseq=31685 (tdta0x7f9c498d8e00), count=8, restart?=1
13:50:26.891   pjsua_core.c  .TX 1084 bytes Response msg 200/INVITE/cseq=31685 (tdta0x7f9c498d8e00) to UDP <sip_server_ip>:5060:
SIP/2.0 200 OK
Via: SIP/2.0/UDP <sip_route_ip>;rport=5060;received=<sip_server_ip>;branch=z9hG4bK17ce.a3aceb0ada02e2991a1eb086e8c7ccd6.1
Via: SIP/2.0/UDP <sip_client_ip>:50052;rport=50052;received=<sip_client_ip>;branch=z9hG4bKPjGzXQGCjrdYtbKDzvW5xAKcSqH7pISVh2
Record-Route: <sip:<sip_route_ip>;lr>
Call-ID: pMyYSVqb7a-.aWwQ8jyc-g.JMiSdZe0T
From: <sip:<caller account>>;tag=s0UvzHTONEIeBumrXH8Fs5YAOTB2ziu6
To: <sip:<callee account>>;tag=n1HHSdGPkEDw3EppCeHuzi1KlUTfk12h
CSeq: 31685 INVITE
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
Contact: <sip:anand@<sip_server>;ob>
Supported: replaces, 100rel, timer, norefersub
Session-Expires: 1800;refresher=uac
Require: timer
Content-Type: application/sdp
Content-Length:   283

v=0
o=- 3704429997 3704429998 IN IP4 192.168.101.147
s=pjmedia
b=AS:84
t=0 0
a=X-nat:0
m=audio 4000 RTP/AVP 0 101
c=IN IP4 192.168.101.147
b=TIAS:64000
a=rtcp:4001 IN IP4 192.168.101.147
a=sendrecv
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16

--end msg--
13:50:29.932   wav_player.c !File port /var/folders/6l/hrzdzgpn36l8f5ck9qf9__yr0000gn/T/c12ff594-5ab2-4a46-a2d0-bd405e6f373f.wav EOF
13:50:29.932   wav_player.c  File port /var/folders/6l/hrzdzgpn36l8f5ck9qf9__yr0000gn/T/c12ff594-5ab2-4a46-a2d0-bd405e6f373f.wav rewinding..
13:50:30.892 tsx0x7f9c47dd5 !Retransmit timer event
13:50:30.892 tsx0x7f9c47dd5  .Retransmiting Response msg 200/INVITE/cseq=31685 (tdta0x7f9c498d8e00), count=9, restart?=1
13:50:30.892   pjsua_core.c  .TX 1084 bytes Response msg 200/INVITE/cseq=31685 (tdta0x7f9c498d8e00) to UDP <sip_server_ip>:5060:
SIP/2.0 200 OK
Via: SIP/2.0/UDP <sip_route_ip>;rport=5060;received=<sip_server_ip>;branch=z9hG4bK17ce.a3aceb0ada02e2991a1eb086e8c7ccd6.1
Via: SIP/2.0/UDP <sip_client_ip>:50052;rport=50052;received=<sip_client_ip>;branch=z9hG4bKPjGzXQGCjrdYtbKDzvW5xAKcSqH7pISVh2
Record-Route: <sip:<sip_route_ip>;lr>
Call-ID: pMyYSVqb7a-.aWwQ8jyc-g.JMiSdZe0T
From: <sip:<caller account>>;tag=s0UvzHTONEIeBumrXH8Fs5YAOTB2ziu6
To: <sip:<callee account>>;tag=n1HHSdGPkEDw3EppCeHuzi1KlUTfk12h
CSeq: 31685 INVITE
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS
Contact: <sip:anand@<sip_server>;ob>
Supported: replaces, 100rel, timer, norefersub
Session-Expires: 1800;refresher=uac
Require: timer
Content-Type: application/sdp
Content-Length:   283

v=0
o=- 3704429997 3704429998 IN IP4 192.168.101.147
s=pjmedia
b=AS:84
t=0 0
a=X-nat:0
m=audio 4000 RTP/AVP 0 101
c=IN IP4 192.168.101.147
b=TIAS:64000
a=rtcp:4001 IN IP4 192.168.101.147
a=sendrecv
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16

--end msg--
13:50:31.386 tsx0x7f9c47dd5  Timeout timer event
13:50:31.386 tsx0x7f9c47dd5  .State changed from Completed to Terminated, event=TIMER
13:50:31.386 dlg0x7f9c44629  ..Transaction tsx0x7f9c47dd56a8 state changed to Terminated
13:50:31.386       endpoint  ...Request msg BYE/cseq=8837 (tdta0x7f9c46ce4e00) created.
13:50:31.386 inv0x7f9c44629  ....Sending Request msg BYE/cseq=8837 (tdta0x7f9c46ce4e00)
13:50:31.386 dlg0x7f9c44629  .....Sending Request msg BYE/cseq=8837 (tdta0x7f9c46ce4e00)
13:50:31.386 tsx0x7f9c46ce5  ......Transaction created for Request msg BYE/cseq=8836 (tdta0x7f9c46ce4e00)
13:50:31.386 tsx0x7f9c46ce5  .....Sending Request msg BYE/cseq=8836 (tdta0x7f9c46ce4e00) in state Null
13:50:31.386  sip_resolve.c  ......Target '<sip_route_ip>:0' type=Unspecified resolved to '<sip_route_ip>:5060' type=UDP (UDP transport)
13:50:31.386   pjsua_core.c  ......TX 409 bytes Request msg BYE/cseq=8836 (tdta0x7f9c46ce4e00) to UDP <sip_route_ip>:5060:
BYE sip:<sip_caller_uri>;ob SIP/2.0
Via: SIP/2.0/UDP <sip_server>;rport;branch=z9hG4bKPjJhoM78f-pBFNkdzrx3qXysMSWhLhgto8
Max-Forwards: 70
From: <sip:<callee account>>;tag=n1HHSdGPkEDw3EppCeHuzi1KlUTfk12h
To: <sip:<caller account>>;tag=s0UvzHTONEIeBumrXH8Fs5YAOTB2ziu6
Call-ID: pMyYSVqb7a-.aWwQ8jyc-g.JMiSdZe0T
CSeq: 8836 BYE
Route: <sip:<sip_route_ip>;lr>
Content-Length:  0


--end msg--
13:50:31.386 tsx0x7f9c46ce5  ......State changed from Null to Calling, event=TX_MSG
13:50:31.386 dlg0x7f9c44629  .......Transaction tsx0x7f9c46ce5ea8 state changed to Calling
13:50:31.391 tsx0x7f9c47dd5  Timeout timer event
13:50:31.391 tsx0x7f9c47dd5  .State changed from Terminated to Destroyed, event=TIMER
13:50:31.391 tdta0x7f9c498d  ..Destroying txdata Response msg 200/INVITE/cseq=31685 (tdta0x7f9c498d8e00)
13:50:31.391 tsx0x7f9c47dd5  Transaction destroyed!
13:50:31.888 tsx0x7f9c46ce5  Retransmit timer event
13:50:31.888 tsx0x7f9c46ce5  .Retransmiting Request msg BYE/cseq=8836 (tdta0x7f9c46ce4e00), count=0, restart?=1
13:50:31.888   pjsua_core.c  .TX 409 bytes Request msg BYE/cseq=8836 (tdta0x7f9c46ce4e00) to UDP <sip_route_ip>:5060:
BYE sip:<sip_caller_uri>;ob SIP/2.0
Via: SIP/2.0/UDP <sip_server>;rport;branch=z9hG4bKPjJhoM78f-pBFNkdzrx3qXysMSWhLhgto8
Max-Forwards: 70
From: <sip:<callee account>>;tag=n1HHSdGPkEDw3EppCeHuzi1KlUTfk12h
To: <sip:<caller account>>;tag=s0UvzHTONEIeBumrXH8Fs5YAOTB2ziu6
Call-ID: pMyYSVqb7a-.aWwQ8jyc-g.JMiSdZe0T
CSeq: 8836 BYE
Route: <sip:<sip_route_ip>;lr>
Content-Length:  0


--end msg--
13:50:32.889 tsx0x7f9c46ce5  Retransmit timer event
13:50:32.889 tsx0x7f9c46ce5  .Retransmiting Request msg BYE/cseq=8836 (tdta0x7f9c46ce4e00), count=1, restart?=1
13:50:32.889   pjsua_core.c  .TX 409 bytes Request msg BYE/cseq=8836 (tdta0x7f9c46ce4e00) to UDP <sip_route_ip>:5060:
BYE sip:<sip_caller_uri>;ob SIP/2.0
Via: SIP/2.0/UDP <sip_server>;rport;branch=z9hG4bKPjJhoM78f-pBFNkdzrx3qXysMSWhLhgto8
Max-Forwards: 70
From: <sip:<callee account>>;tag=n1HHSdGPkEDw3EppCeHuzi1KlUTfk12h
To: <sip:<caller account>>;tag=s0UvzHTONEIeBumrXH8Fs5YAOTB2ziu6
Call-ID: pMyYSVqb7a-.aWwQ8jyc-g.JMiSdZe0T
CSeq: 8836 BYE
Route: <sip:<sip_route_ip>;lr>
Content-Length:  0


--end msg--
13:50:32.962   wav_player.c !File port /var/folders/6l/hrzdzgpn36l8f5ck9qf9__yr0000gn/T/c12ff594-5ab2-4a46-a2d0-bd405e6f373f.wav EOF
13:50:32.963   wav_player.c  File port /var/folders/6l/hrzdzgpn36l8f5ck9qf9__yr0000gn/T/c12ff594-5ab2-4a46-a2d0-bd405e6f373f.wav rewinding..
13:50:34.891 tsx0x7f9c46ce5 !Retransmit timer event
13:50:34.891 tsx0x7f9c46ce5  .Retransmiting Request msg BYE/cseq=8836 (tdta0x7f9c46ce4e00), count=2, restart?=1
13:50:34.891   pjsua_core.c  .TX 409 bytes Request msg BYE/cseq=8836 (tdta0x7f9c46ce4e00) to UDP <sip_route_ip>:5060:
BYE sip:<sip_caller_uri>;ob SIP/2.0
Via: SIP/2.0/UDP <sip_server>;rport;branch=z9hG4bKPjJhoM78f-pBFNkdzrx3qXysMSWhLhgto8
Max-Forwards: 70
From: <sip:<callee account>>;tag=n1HHSdGPkEDw3EppCeHuzi1KlUTfk12h
To: <sip:<caller account>>;tag=s0UvzHTONEIeBumrXH8Fs5YAOTB2ziu6
Call-ID: pMyYSVqb7a-.aWwQ8jyc-g.JMiSdZe0T
CSeq: 8836 BYE
Route: <sip:<sip_route_ip>;lr>
Content-Length:  0


--end msg--
13:50:36.004   wav_player.c !File port /var/folders/6l/hrzdzgpn36l8f5ck9qf9__yr0000gn/T/c12ff594-5ab2-4a46-a2d0-bd405e6f373f.wav EOF
13:50:36.004   wav_player.c  File port /var/folders/6l/hrzdzgpn36l8f5ck9qf9__yr0000gn/T/c12ff594-5ab2-4a46-a2d0-bd405e6f373f.wav rewinding..
13:50:37.557    pjsua_acc.c !Sending 2 bytes keep-alive packet for acc 0 to <sip_server_ip>:5060
13:50:37.557 tdta0x7f9c498d  Destroying txdata raw
13:50:38.891 tsx0x7f9c46ce5  Retransmit timer event
13:50:38.891 tsx0x7f9c46ce5  .Retransmiting Request msg BYE/cseq=8836 (tdta0x7f9c46ce4e00), count=3, restart?=1
13:50:38.891   pjsua_core.c  .TX 409 bytes Request msg BYE/cseq=8836 (tdta0x7f9c46ce4e00) to UDP <sip_route_ip>:5060:
BYE sip:<sip_caller_uri>;ob SIP/2.0
Via: SIP/2.0/UDP <sip_server>;rport;branch=z9hG4bKPjJhoM78f-pBFNkdzrx3qXysMSWhLhgto8
Max-Forwards: 70
From: <sip:<callee account>>;tag=n1HHSdGPkEDw3EppCeHuzi1KlUTfk12h
To: <sip:<caller account>>;tag=s0UvzHTONEIeBumrXH8Fs5YAOTB2ziu6
Call-ID: pMyYSVqb7a-.aWwQ8jyc-g.JMiSdZe0T
CSeq: 8836 BYE
Route: <sip:<sip_route_ip>;lr>
Content-Length:  0


--end msg--
13:50:39.069   wav_player.c !File port /var/folders/6l/hrzdzgpn36l8f5ck9qf9__yr0000gn/T/c12ff594-5ab2-4a46-a2d0-bd405e6f373f.wav EOF
13:50:39.069   wav_player.c  File port /var/folders/6l/hrzdzgpn36l8f5ck9qf9__yr0000gn/T/c12ff594-5ab2-4a46-a2d0-bd405e6f373f.wav rewinding..
13:50:42.111   wav_player.c  File port /var/folders/6l/hrzdzgpn36l8f5ck9qf9__yr0000gn/T/c12ff594-5ab2-4a46-a2d0-bd405e6f373f.wav EOF
13:50:42.112   wav_player.c  File port /var/folders/6l/hrzdzgpn36l8f5ck9qf9__yr0000gn/T/c12ff594-5ab2-4a46-a2d0-bd405e6f373f.wav rewinding..
13:50:42.892 tsx0x7f9c46ce5 !Retransmit timer event
13:50:42.893 tsx0x7f9c46ce5  .Retransmiting Request msg BYE/cseq=8836 (tdta0x7f9c46ce4e00), count=4, restart?=1
13:50:42.893   pjsua_core.c  .TX 409 bytes Request msg BYE/cseq=8836 (tdta0x7f9c46ce4e00) to UDP <sip_route_ip>:5060:
BYE sip:<sip_caller_uri>;ob SIP/2.0
Via: SIP/2.0/UDP <sip_server>;rport;branch=z9hG4bKPjJhoM78f-pBFNkdzrx3qXysMSWhLhgto8
Max-Forwards: 70
From: <sip:<callee account>>;tag=n1HHSdGPkEDw3EppCeHuzi1KlUTfk12h
To: <sip:<caller account>>;tag=s0UvzHTONEIeBumrXH8Fs5YAOTB2ziu6
Call-ID: pMyYSVqb7a-.aWwQ8jyc-g.JMiSdZe0T
CSeq: 8836 BYE
Route: <sip:<sip_route_ip>;lr>
Content-Length:  0


--end msg--
13:50:45.142   wav_player.c !File port /var/folders/6l/hrzdzgpn36l8f5ck9qf9__yr0000gn/T/c12ff594-5ab2-4a46-a2d0-bd405e6f373f.wav EOF
13:50:45.142   wav_player.c  File port /var/folders/6l/hrzdzgpn36l8f5ck9qf9__yr0000gn/T/c12ff594-5ab2-4a46-a2d0-bd405e6f373f.wav rewinding..
13:50:46.894 tsx0x7f9c46ce5 !Retransmit timer event
13:50:46.894 tsx0x7f9c46ce5  .Retransmiting Request msg BYE/cseq=8836 (tdta0x7f9c46ce4e00), count=5, restart?=1
13:50:46.894   pjsua_core.c  .TX 409 bytes Request msg BYE/cseq=8836 (tdta0x7f9c46ce4e00) to UDP <sip_route_ip>:5060:
BYE sip:<sip_caller_uri>;ob SIP/2.0
Via: SIP/2.0/UDP <sip_server>;rport;branch=z9hG4bKPjJhoM78f-pBFNkdzrx3qXysMSWhLhgto8
Max-Forwards: 70
From: <sip:<callee account>>;tag=n1HHSdGPkEDw3EppCeHuzi1KlUTfk12h
To: <sip:<caller account>>;tag=s0UvzHTONEIeBumrXH8Fs5YAOTB2ziu6
Call-ID: pMyYSVqb7a-.aWwQ8jyc-g.JMiSdZe0T
CSeq: 8836 BYE
Route: <sip:<sip_route_ip>;lr>
Content-Length:  0


--end msg--
13:50:48.183   wav_player.c !File port /var/folders/6l/hrzdzgpn36l8f5ck9qf9__yr0000gn/T/c12ff594-5ab2-4a46-a2d0-bd405e6f373f.wav EOF
13:50:48.184   wav_player.c  File port /var/folders/6l/hrzdzgpn36l8f5ck9qf9__yr0000gn/T/c12ff594-5ab2-4a46-a2d0-bd405e6f373f.wav rewinding..
13:50:50.894 tsx0x7f9c46ce5 !Retransmit timer event
13:50:50.894 tsx0x7f9c46ce5  .Retransmiting Request msg BYE/cseq=8836 (tdta0x7f9c46ce4e00), count=6, restart?=1
13:50:50.894   pjsua_core.c  .TX 409 bytes Request msg BYE/cseq=8836 (tdta0x7f9c46ce4e00) to UDP <sip_route_ip>:5060:
BYE sip:<sip_caller_uri>;ob SIP/2.0
Via: SIP/2.0/UDP <sip_server>;rport;branch=z9hG4bKPjJhoM78f-pBFNkdzrx3qXysMSWhLhgto8
Max-Forwards: 70
From: <sip:<callee account>>;tag=n1HHSdGPkEDw3EppCeHuzi1KlUTfk12h
To: <sip:<caller account>>;tag=s0UvzHTONEIeBumrXH8Fs5YAOTB2ziu6
Call-ID: pMyYSVqb7a-.aWwQ8jyc-g.JMiSdZe0T
CSeq: 8836 BYE
Route: <sip:<sip_route_ip>;lr>
Content-Length:  0


--end msg--
13:50:51.249   wav_player.c !File port /var/folders/6l/hrzdzgpn36l8f5ck9qf9__yr0000gn/T/c12ff594-5ab2-4a46-a2d0-bd405e6f373f.wav EOF
13:50:51.249   wav_player.c  File port /var/folders/6l/hrzdzgpn36l8f5ck9qf9__yr0000gn/T/c12ff594-5ab2-4a46-a2d0-bd405e6f373f.wav rewinding..
13:50:52.559    pjsua_acc.c !Sending 2 bytes keep-alive packet for acc 0 to <sip_server_ip>:5060
13:50:52.559 tdta0x7f9c44c8  Destroying txdata raw
13:50:54.291   wav_player.c !File port /var/folders/6l/hrzdzgpn36l8f5ck9qf9__yr0000gn/T/c12ff594-5ab2-4a46-a2d0-bd405e6f373f.wav EOF
13:50:54.291   wav_player.c  File port /var/folders/6l/hrzdzgpn36l8f5ck9qf9__yr0000gn/T/c12ff594-5ab2-4a46-a2d0-bd405e6f373f.wav rewinding..
13:50:54.895 tsx0x7f9c46ce5 !Retransmit timer event
13:50:54.895 tsx0x7f9c46ce5  .Retransmiting Request msg BYE/cseq=8836 (tdta0x7f9c46ce4e00), count=7, restart?=1
13:50:54.895   pjsua_core.c  .TX 409 bytes Request msg BYE/cseq=8836 (tdta0x7f9c46ce4e00) to UDP <sip_route_ip>:5060:
BYE sip:<sip_caller_uri>;ob SIP/2.0
Via: SIP/2.0/UDP <sip_server>;rport;branch=z9hG4bKPjJhoM78f-pBFNkdzrx3qXysMSWhLhgto8
Max-Forwards: 70
From: <sip:<callee account>>;tag=n1HHSdGPkEDw3EppCeHuzi1KlUTfk12h
To: <sip:<caller account>>;tag=s0UvzHTONEIeBumrXH8Fs5YAOTB2ziu6
Call-ID: pMyYSVqb7a-.aWwQ8jyc-g.JMiSdZe0T
CSeq: 8836 BYE
Route: <sip:<sip_route_ip>;lr>
Content-Length:  0


--end msg--
13:50:57.333   wav_player.c !File port /var/folders/6l/hrzdzgpn36l8f5ck9qf9__yr0000gn/T/c12ff594-5ab2-4a46-a2d0-bd405e6f373f.wav EOF
13:50:57.334   wav_player.c  File port /var/folders/6l/hrzdzgpn36l8f5ck9qf9__yr0000gn/T/c12ff594-5ab2-4a46-a2d0-bd405e6f373f.wav rewinding..
13:50:58.896 tsx0x7f9c46ce5 !Retransmit timer event
13:50:58.896 tsx0x7f9c46ce5  .Retransmiting Request msg BYE/cseq=8836 (tdta0x7f9c46ce4e00), count=8, restart?=1
13:50:58.896   pjsua_core.c  .TX 409 bytes Request msg BYE/cseq=8836 (tdta0x7f9c46ce4e00) to UDP <sip_route_ip>:5060:
BYE sip:<sip_caller_uri>;ob SIP/2.0
Via: SIP/2.0/UDP <sip_server>;rport;branch=z9hG4bKPjJhoM78f-pBFNkdzrx3qXysMSWhLhgto8
Max-Forwards: 70
From: <sip:<callee account>>;tag=n1HHSdGPkEDw3EppCeHuzi1KlUTfk12h
To: <sip:<caller account>>;tag=s0UvzHTONEIeBumrXH8Fs5YAOTB2ziu6
Call-ID: pMyYSVqb7a-.aWwQ8jyc-g.JMiSdZe0T
CSeq: 8836 BYE
Route: <sip:<sip_route_ip>;lr>
Content-Length:  0


--end msg--
13:51:00.363   wav_player.c !File port .wav EOF
13:51:00.363   wav_player.c  File port .wav rewinding..
13:51:02.898 tsx0x7f9c46ce5 !Retransmit timer event
13:51:02.898 tsx0x7f9c46ce5  .Retransmiting Request msg BYE/cseq=8836 (tdta0x7f9c46ce4e00), count=9, restart?=1
13:51:02.898   pjsua_core.c  .TX 409 bytes Request msg BYE/cseq=8836 (tdta0x7f9c46ce4e00) to UDP <sip_route_ip>:5060:
BYE sip:<caller>;ob SIP/2.0
Via: SIP/2.0/UDP <sip_server>;rport;branch=z9hG4bKPjJhoM78f-pBFNkdzrx3qXysMSWhLhgto8
Max-Forwards: 70
From: <sip:<callee account>>;tag=n1HHSdGPkEDw3EppCeHuzi1KlUTfk12h
To: <sip:<caller account>>;tag=s0UvzHTONEIeBumrXH8Fs5YAOTB2ziu6
Call-ID: pMyYSVqb7a-.aWwQ8jyc-g.JMiSdZe0T
CSeq: 8836 BYE
Route: <sip:<sip_route_ip>;lr>
Content-Length:  0


--end msg--
13:51:03.387 tsx0x7f9c46ce5  Timeout timer event
13:51:03.387 tsx0x7f9c46ce5  .State changed from Calling to Terminated, event=TIMER
13:51:03.387 dlg0x7f9c44629  ..Transaction tsx0x7f9c46ce5ea8 state changed to Terminated
13:51:03.397    pjsua_aud.c  ....Destroying player 0..
13:51:03.397  pjsua_media.c  ....Call 0: deinitializing media..
13:51:03.397 strm0x7f9c4982  ......JB summary:
  size=50/eff=50 prefetch=0 level=0
  delay (min/max/avg/dev)=0/0/0/0 ms
  burst (min/max/avg/dev)=0/0/0/0 frames
  lost=0 discard=6340 empty=0
13:51:03.397  pjsua_media.c  ......Media stream call00:0 is destroyed
13:51:03.398 dlg0x7f9c44629  ....Session count dec to 1 by mod-invite
13:51:03.398 dlg0x7f9c44629  ...Dialog destroyed
13:51:03.410 tsx0x7f9c46ce5  Timeout timer event
13:51:03.410 tsx0x7f9c46ce5  .State changed from Terminated to Destroyed, event=TIMER
13:51:03.410 tdta0x7f9c46ce  ..Destroying txdata Request msg BYE/cseq=8836 (tdta0x7f9c46ce4e00)
13:51:03.410 tsx0x7f9c46ce5  Transaction destroyed!


Vitold S

unread,
Mar 6, 2018, 12:25:33 PM3/6/18
to PJSIP experts
It look like your PBX system does not ACK-ed your call.

You send 9 times "200 OK" to approve your dialog to server and does not recevie ACK response.
I think that PJ think that transaction was not confirmed and raise Timer B after timeout.


13:50:30.892 tsx0x7f9c47dd5  .Retransmiting Response msg 200/INVITE/cseq=31685 (tdta0x7f9c498d8e00), count=9, restart?=1

Let's I show you image from internet describe dialog establish process:
Картинки по запросу invite sip example
Reply all
Reply to author
Forward
0 new messages