[Sep 3 16:58:59] DEBUG[21424] res_pjsip_session.c: Method is INVITE [Sep 3 16:58:59] DEBUG[21424] pjsip: inv0x272eb68 .Delaying CANCEL since no provisional response is received yet [Sep 3 16:58:59] DEBUG[21424] res_pjsip_session.c: Method is INVITE, Response is 486 Busy Here [Sep 3 16:58:59] DEBUG[21424] pjsip: inv0x2642048 .Sending Response msg 486/INVITE/cseq=1 (tdta0x7f1d842c6d90) [Sep 3 16:58:59] DEBUG[21424] pjsip: dlg0x2642048 ..Sending Response msg 486/INVITE/cseq=1 (tdta0x7f1d842c6d90) [Sep 3 16:58:59] DEBUG[21424] pjsip: tsx0x2662bb8 ..Sending Response msg 486/INVITE/cseq=1 (tdta0x7f1d842c6d90) in state Proceeding [Sep 3 16:58:59] DEBUG[21424] netsock2.c: Splitting '0.0.0.0:5060' into... [Sep 3 16:58:59] DEBUG[21424] netsock2.c: ...host '0.0.0.0' and port '5060'. [Sep 3 16:58:59] DEBUG[21424] netsock2.c: Splitting '62.210.250.141:5104' into... [Sep 3 16:58:59] DEBUG[21424] netsock2.c: ...host '62.210.250.141' and port '5104'. [Sep 3 16:58:59] VERBOSE[21424] res_pjsip_logger.c: <--- Transmitting SIP response (548 bytes) to UDP:62.210.250.141:5104 ---> SIP/2.0 486 Busy Here Via: SIP/2.0/UDP 62.210.250.141:5104;rport=5104;received=62.210.250.141;branch=z9hG4bK-8272d6c33827f4048f59de640b1f8e1d Call-ID: 8272d6c33827f4048f59de640b1f8e1d From: "10" ;tag=ad72f6fb To: "701141445209952" ;tag=9e54d872-2d5e-4834-a90d-b0b4e02d80de CSeq: 1 INVITE Server: Asterisk PBX GIT-13-2733638M Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, MESSAGE, REFER Reason: Q.850;cause=17 Content-Length: 0 [Sep 3 16:58:59] DEBUG[21424] pjsip: tsx0x2662bb8 ...State changed from Proceeding to Completed, event=TX_MSG [Sep 3 16:58:59] DEBUG[21424] pjsip: dlg0x2642048 ....Transaction tsx0x2662bb8 state changed to Completed [Sep 3 16:58:59] DEBUG[21424] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Sep 3 16:58:59] DEBUG[21424] res_pjsip_session.c: The state change pertains to the endpoint 'anonymous(PJSIP/anonymous-000000dd)' [Sep 3 16:58:59] DEBUG[21424] res_pjsip_session.c: The inv session still has an invite_tsx (0x2662bb8) [Sep 3 16:58:59] DEBUG[21424] res_pjsip_session.c: There is no transaction involved in this state change [Sep 3 16:58:59] DEBUG[21424] res_pjsip_session.c: The current inv state is DISCONNCTD [Sep 3 16:58:59] DEBUG[21424] res_pjsip_session.c: Source of transaction state change is TX_MSG [Sep 3 16:58:59] DEBUG[21424] res_pjsip_session.c: Sending response [Sep 3 16:58:59] DEBUG[21424] res_pjsip_session.c: Method is INVITE, Response is 486 Busy Here [Sep 3 16:58:59] DEBUG[21424] pjsip: dlg0x2642048 ......Session count dec to 3 by mod-invite [Sep 3 16:58:59] DEBUG[21424] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Sep 3 16:58:59] DEBUG[21424] res_pjsip_session.c: The state change pertains to the endpoint 'anonymous(PJSIP/anonymous-000000dd)' [Sep 3 16:58:59] DEBUG[21424] res_pjsip_session.c: The inv session still has an invite_tsx (0x2662bb8) [Sep 3 16:58:59] DEBUG[21424] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x2662bb8 [Sep 3 16:58:59] DEBUG[21424] res_pjsip_session.c: The current transaction state is Completed [Sep 3 16:58:59] DEBUG[21424] res_pjsip_session.c: The transaction state change event is TX_MSG [Sep 3 16:58:59] DEBUG[21424] res_pjsip_session.c: The current inv state is DISCONNCTD [Sep 3 16:58:59] DEBUG[21424] res_pjsip_session.c: Sending response [Sep 3 16:58:59] DEBUG[21424] res_pjsip_session.c: Method is INVITE, Response is 486 Busy Here [Sep 3 16:58:59] DEBUG[20294] devicestate.c: No provider found, checking channel drivers for PJSIP - 100 [Sep 3 16:58:59] DEBUG[20294] devicestate.c: Changing state for PJSIP/100 - state 6 (Ringing) [Sep 3 16:58:59] DEBUG[20294] devicestate.c: No provider found, checking channel drivers for PJSIP - anonymous [Sep 3 16:58:59] DEBUG[20294] devicestate.c: Changing state for PJSIP/anonymous - state 2 (In use) [Sep 3 16:58:59] DEBUG[20296] cdr.c: Finalized CDR for PJSIP/100-000000e6 - start 1441317539.802132 answer 0.000000 end 1441317539.804782 dispo FAILED [Sep 3 16:58:59] DEBUG[20296] cdr.c: CDR for PJSIP/100-000000e6 is dialed and has no Party B; discarding [Sep 3 16:58:59] DEBUG[20296] res_config_sqlite.c: SQL query: INSERT INTO ast_cdr (clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,start,end,duration,billsec,disposition,amaflags,uniqueid) VALUES ('"10" <10>','10','701141445209952','from-anonymous','PJSIP/anonymous-000000dd','PJSIP/100-000000de','Dial','PJSIP/100,6','2015-09-03 16:58:53','2015-09-03 16:58:59','6','0','NO ANSWER','DOCUMENTATION','1441317533.364') [Sep 3 16:58:59] DEBUG[20296] res_config_sqlite.c: SQL query: INSERT INTO ast_cdr (clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,start,end,duration,billsec,disposition,amaflags,uniqueid) VALUES ('"10" <10>','10','701141445209952','from-anonymous','PJSIP/anonymous-000000dd','PJSIP/100-000000e6','Hangup','17','2015-09-03 16:58:59','2015-09-03 16:58:59','0','0','NO ANSWER','DOCUMENTATION','1441317533.364') [Sep 3 16:58:59] DEBUG[20309] pjsip: sip_endpoint.c Processing incoming message: Response msg 180/INVITE/cseq=21773 (rdata0x7f1d840009b8) [Sep 3 16:58:59] VERBOSE[20309] res_pjsip_logger.c: <--- Received SIP response (575 bytes) from UDP:216.207.245.55:5062 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 104.236.91.141:5060;rport;branch=z9hG4bKPj55a76574-cd6a-4934-bda5-905b0c6a8634 From: "10" ;tag=386fdc79-d013-4a15-92cc-bce663406f66 To: ;tag=827751994 Call-ID: 55941bad-87f2-486a-aa99-f976fbf6168c CSeq: 21773 INVITE Contact: Allow: INVITE, INFO, PRACK, ACK, BYE, CANCEL, OPTIONS, NOTIFY, REGISTER, SUBSCRIBE, REFER, PUBLISH, UPDATE, MESSAGE User-Agent: Yealink SIP-T28P 2.61.0.80 Allow-Events: talk,hold,conference,refer,check-sync Content-Length: 0 [Sep 3 16:58:59] DEBUG[20309] netsock2.c: Splitting '216.207.245.55:5062' into... [Sep 3 16:58:59] DEBUG[20309] netsock2.c: ...host '216.207.245.55' and port '5062'. [Sep 3 16:58:59] DEBUG[20309] netsock2.c: Splitting '0.0.0.0:5060' into... [Sep 3 16:58:59] DEBUG[20309] netsock2.c: ...host '0.0.0.0' and port '5060'. [Sep 3 16:58:59] DEBUG[21424] pjsip: sip_endpoint.c Distributing rdata to modules: Response msg 180/INVITE/cseq=21773 (rdata0x7f1d842ca998) [Sep 3 16:58:59] DEBUG[21424] pjsip: tsx0x269f4f8 .Incoming Response msg 180/INVITE/cseq=21773 (rdata0x7f1d842ca998) in state Proceeding [Sep 3 16:58:59] DEBUG[21424] pjsip: tsx0x269f4f8 ..State changed from Proceeding to Proceeding, event=RX_MSG [Sep 3 16:58:59] DEBUG[21424] pjsip: dlg0x272f8b8 ...Received Response msg 180/INVITE/cseq=21773 (rdata0x7f1d842ca998) [Sep 3 16:58:59] DEBUG[21424] pjsip: dlg0x272f8b8 ...Transaction tsx0x269f4f8 state changed to Proceeding [Sep 3 16:58:59] DEBUG[21424] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Sep 3 16:58:59] DEBUG[21424] res_pjsip_session.c: The state change pertains to the endpoint '100(PJSIP/100-000000e4)' [Sep 3 16:58:59] DEBUG[21424] res_pjsip_session.c: The inv session still has an invite_tsx (0x269f4f8) [Sep 3 16:58:59] DEBUG[21424] res_pjsip_session.c: There is no transaction involved in this state change [Sep 3 16:58:59] DEBUG[21424] res_pjsip_session.c: The current inv state is EARLY [Sep 3 16:58:59] DEBUG[21424] res_pjsip_session.c: Source of transaction state change is RX_MSG [Sep 3 16:58:59] DEBUG[21424] res_pjsip_session.c: Received response [Sep 3 16:58:59] DEBUG[21424] res_pjsip_session.c: Response is 180 Ringing [Sep 3 16:58:59] DEBUG[21424] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Sep 3 16:58:59] DEBUG[21424] res_pjsip_session.c: The state change pertains to the endpoint '100(PJSIP/100-000000e4)' [Sep 3 16:58:59] DEBUG[21424] res_pjsip_session.c: The inv session still has an invite_tsx (0x269f4f8) [Sep 3 16:58:59] DEBUG[21424] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x269f4f8 [Sep 3 16:58:59] DEBUG[21424] res_pjsip_session.c: The current transaction state is Proceeding [Sep 3 16:58:59] DEBUG[21424] res_pjsip_session.c: The transaction state change event is RX_MSG [Sep 3 16:58:59] DEBUG[21424] res_pjsip_session.c: The current inv state is EARLY [Sep 3 16:58:59] DEBUG[21424] res_pjsip_session.c: Received response [Sep 3 16:58:59] DEBUG[21424] res_pjsip_session.c: Response is 180 Ringing [Sep 3 16:58:59] VERBOSE[24558][C-0000004e] app_dial.c: PJSIP/100-000000e4 is ringing [Sep 3 16:58:59] DEBUG[20309] pjsip: sip_endpoint.c Processing incoming message: Response msg 200/CANCEL/cseq=446 (rdata0x7f1d840009b8) [Sep 3 16:58:59] VERBOSE[20309] res_pjsip_logger.c: <--- Received SIP response (361 bytes) from UDP:216.207.245.55:5062 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 104.236.91.141:5060;rport;branch=z9hG4bKPjb7697ce2-b729-4cc4-9d2e-3b1a299c6683 From: "10" ;tag=86853df9-231f-4ddd-a6ec-e0b666a2a88a To: ;tag=1014556814 Call-ID: c876fcb5-6843-491f-865c-d235542168a3 CSeq: 446 CANCEL User-Agent: Yealink SIP-T28P 2.61.0.80 Content-Length: 0 [Sep 3 16:58:59] DEBUG[20309] netsock2.c: Splitting '216.207.245.55:5062' into... [Sep 3 16:58:59] DEBUG[20309] netsock2.c: ...host '216.207.245.55' and port '5062'. [Sep 3 16:58:59] DEBUG[20309] netsock2.c: Splitting '0.0.0.0:5060' into... [Sep 3 16:58:59] DEBUG[20309] netsock2.c: ...host '0.0.0.0' and port '5060'. [Sep 3 16:58:59] DEBUG[22208] pjsip: sip_endpoint.c Distributing rdata to modules: Response msg 200/CANCEL/cseq=446 (rdata0x7f1d842ca998) [Sep 3 16:58:59] DEBUG[22208] pjsip: tsx0x7f1d9403f .Incoming Response msg 200/CANCEL/cseq=446 (rdata0x7f1d842ca998) in state Completed [Sep 3 16:58:59] DEBUG[20309] pjsip: sip_endpoint.c Processing incoming message: Response msg 200/CANCEL/cseq=31783 (rdata0x7f1d840009b8) [Sep 3 16:58:59] VERBOSE[20309] res_pjsip_logger.c: <--- Received SIP response (363 bytes) from UDP:216.207.245.55:5062 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 104.236.91.141:5060;rport;branch=z9hG4bKPj44098dbd-1c02-4deb-8525-f12f73adc9f3 From: "10" ;tag=86c31053-87cf-4f2e-94ac-0ae196238ca1 To: ;tag=1995983909 Call-ID: 0652ab77-52f7-45b4-87a9-8cbc8463dac8 CSeq: 31783 CANCEL User-Agent: Yealink SIP-T28P 2.61.0.80 Content-Length: 0 [Sep 3 16:58:59] DEBUG[20309] netsock2.c: Splitting '216.207.245.55:5062' into... [Sep 3 16:58:59] DEBUG[20309] netsock2.c: ...host '216.207.245.55' and port '5062'. [Sep 3 16:58:59] DEBUG[20309] netsock2.c: Splitting '0.0.0.0:5060' into... [Sep 3 16:58:59] DEBUG[20309] netsock2.c: ...host '0.0.0.0' and port '5060'. [Sep 3 16:58:59] DEBUG[21424] pjsip: sip_endpoint.c Distributing rdata to modules: Response msg 200/CANCEL/cseq=31783 (rdata0x7f1d842ca998) [Sep 3 16:58:59] DEBUG[21424] pjsip: tsx0x263b268 .Incoming Response msg 200/CANCEL/cseq=31783 (rdata0x7f1d842ca998) in state Calling [Sep 3 16:58:59] DEBUG[21424] pjsip: tsx0x263b268 ..State changed from Calling to Completed, event=RX_MSG [Sep 3 16:58:59] DEBUG[21424] pjsip: dlg0x7f1d7c04b ...Received Response msg 200/CANCEL/cseq=31783 (rdata0x7f1d842ca998) [Sep 3 16:58:59] DEBUG[21424] pjsip: dlg0x7f1d7c04b ...Transaction tsx0x263b268 state changed to Completed [Sep 3 16:58:59] DEBUG[20309] pjsip: sip_endpoint.c Processing incoming message: Response msg 487/INVITE/cseq=31783 (rdata0x7f1d840009b8) [Sep 3 16:58:59] VERBOSE[20309] res_pjsip_logger.c: <--- Received SIP response (379 bytes) from UDP:216.207.245.55:5062 ---> SIP/2.0 487 Request Terminated Via: SIP/2.0/UDP 104.236.91.141:5060;rport;branch=z9hG4bKPj44098dbd-1c02-4deb-8525-f12f73adc9f3 From: "10" ;tag=86c31053-87cf-4f2e-94ac-0ae196238ca1 To: ;tag=1995983909 Call-ID: 0652ab77-52f7-45b4-87a9-8cbc8463dac8 CSeq: 31783 INVITE User-Agent: Yealink SIP-T28P 2.61.0.80 Content-Length: 0 [Sep 3 16:58:59] DEBUG[20309] netsock2.c: Splitting '216.207.245.55:5062' into... [Sep 3 16:58:59] DEBUG[20309] netsock2.c: ...host '216.207.245.55' and port '5062'. [Sep 3 16:58:59] DEBUG[20309] netsock2.c: Splitting '0.0.0.0:5060' into... [Sep 3 16:58:59] DEBUG[20309] netsock2.c: ...host '0.0.0.0' and port '5060'. [Sep 3 16:58:59] DEBUG[22208] pjsip: sip_endpoint.c Distributing rdata to modules: Response msg 487/INVITE/cseq=31783 (rdata0x7f1d842ca998) [Sep 3 16:58:59] DEBUG[22208] pjsip: tsx0x2707f58 .Incoming Response msg 487/INVITE/cseq=31783 (rdata0x7f1d842ca998) in state Proceeding [Sep 3 16:58:59] DEBUG[22208] pjsip: endpoint ..Request msg ACK/cseq=31783 (tdta0x7f1d94025820) created. [Sep 3 16:58:59] DEBUG[22208] netsock2.c: Splitting '0.0.0.0:5060' into... [Sep 3 16:58:59] DEBUG[22208] netsock2.c: ...host '0.0.0.0' and port '5060'. [Sep 3 16:58:59] DEBUG[22208] netsock2.c: Splitting '216.207.245.55:5062' into... [Sep 3 16:58:59] DEBUG[22208] netsock2.c: ...host '216.207.245.55' and port '5062'. [Sep 3 16:58:59] VERBOSE[22208] res_pjsip_logger.c: <--- Transmitting SIP request (406 bytes) to UDP:216.207.245.55:5062 ---> ACK sip:100@216.207.245.55:5062 SIP/2.0 Via: SIP/2.0/UDP 104.236.91.141:5060;rport;branch=z9hG4bKPj44098dbd-1c02-4deb-8525-f12f73adc9f3 From: "10" ;tag=86c31053-87cf-4f2e-94ac-0ae196238ca1 To: ;tag=1995983909 Call-ID: 0652ab77-52f7-45b4-87a9-8cbc8463dac8 CSeq: 31783 ACK Max-Forwards: 70 User-Agent: Asterisk PBX GIT-13-2733638M Content-Length: 0 [Sep 3 16:58:59] DEBUG[22208] pjsip: tsx0x2707f58 ..State changed from Proceeding to Completed, event=RX_MSG [Sep 3 16:58:59] DEBUG[22208] pjsip: dlg0x7f1d7c04b ...Received Response msg 487/INVITE/cseq=31783 (rdata0x7f1d842ca998) [Sep 3 16:58:59] DEBUG[22208] pjsip: dlg0x7f1d7c04b ...Transaction tsx0x2707f58 state changed to Completed [Sep 3 16:58:59] DEBUG[22208] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Sep 3 16:58:59] DEBUG[22208] res_pjsip_session.c: The state change pertains to the endpoint '100()' [Sep 3 16:58:59] DEBUG[22208] res_pjsip_session.c: The inv session still has an invite_tsx (0x2707f58) [Sep 3 16:58:59] DEBUG[22208] res_pjsip_session.c: There is no transaction involved in this state change [Sep 3 16:58:59] DEBUG[22208] res_pjsip_session.c: The current inv state is DISCONNCTD [Sep 3 16:58:59] DEBUG[22208] res_pjsip_session.c: Source of transaction state change is RX_MSG [Sep 3 16:58:59] DEBUG[22208] res_pjsip_session.c: Received response [Sep 3 16:58:59] DEBUG[22208] res_pjsip_session.c: Response is 487 Request Terminated [Sep 3 16:58:59] DEBUG[22208] pjsip: dlg0x7f1d7c04b .....Session count dec to 2 by mod-invite [Sep 3 16:58:59] DEBUG[22208] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Sep 3 16:58:59] DEBUG[22208] res_pjsip_session.c: The state change pertains to the endpoint '100()' [Sep 3 16:58:59] DEBUG[22208] res_pjsip_session.c: The inv session still has an invite_tsx (0x2707f58) [Sep 3 16:58:59] DEBUG[22208] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x2707f58 [Sep 3 16:58:59] DEBUG[22208] res_pjsip_session.c: The current transaction state is Completed [Sep 3 16:58:59] DEBUG[22208] res_pjsip_session.c: The transaction state change event is RX_MSG [Sep 3 16:58:59] DEBUG[22208] res_pjsip_session.c: The current inv state is DISCONNCTD [Sep 3 16:58:59] DEBUG[22208] res_pjsip_session.c: Received response [Sep 3 16:58:59] DEBUG[22208] res_pjsip_session.c: Response is 487 Request Terminated [Sep 3 16:58:59] DEBUG[22208] pjsip: tdta0x2677f10 ..Destroying txdata Request msg INVITE/cseq=31783 (tdta0x2677f10) [Sep 3 16:59:00] DEBUG[20309] pjsip: sip_endpoint.c Processing incoming message: Response msg 100/INVITE/cseq=21703 (rdata0x7f1d840009b8) [Sep 3 16:59:00] VERBOSE[20309] res_pjsip_logger.c: <--- Received SIP response (352 bytes) from UDP:216.207.245.55:5062 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 104.236.91.141:5060;rport;branch=z9hG4bKPj57afe773-01ec-4303-a70d-a29d93e98ef6 From: "10" ;tag=04ac5709-9664-4015-a36b-ccae72514ee8 To: Call-ID: 36354359-cbe9-42fb-94eb-8012a23c8a6f CSeq: 21703 INVITE User-Agent: Yealink SIP-T28P 2.61.0.80 Content-Length: 0 [Sep 3 16:59:00] DEBUG[20309] netsock2.c: Splitting '216.207.245.55:5062' into... [Sep 3 16:59:00] DEBUG[20309] netsock2.c: ...host '216.207.245.55' and port '5062'. [Sep 3 16:59:00] DEBUG[20309] netsock2.c: Splitting '0.0.0.0:5060' into... [Sep 3 16:59:00] DEBUG[20309] netsock2.c: ...host '0.0.0.0' and port '5060'. [Sep 3 16:59:00] DEBUG[21424] pjsip: sip_endpoint.c Distributing rdata to modules: Response msg 100/INVITE/cseq=21703 (rdata0x7f1d842ca998) [Sep 3 16:59:00] DEBUG[21424] pjsip: tsx0x26eb538 .Incoming Response msg 100/INVITE/cseq=21703 (rdata0x7f1d842ca998) in state Calling [Sep 3 16:59:00] DEBUG[21424] pjsip: tsx0x26eb538 ..State changed from Calling to Proceeding, event=RX_MSG [Sep 3 16:59:00] DEBUG[21424] pjsip: dlg0x263c1b8 ...Received Response msg 100/INVITE/cseq=21703 (rdata0x7f1d842ca998) [Sep 3 16:59:00] DEBUG[21424] pjsip: dlg0x263c1b8 ...Transaction tsx0x26eb538 state changed to Proceeding [Sep 3 16:59:00] DEBUG[21424] pjsip: endpoint .....Request msg CANCEL/cseq=21703 (tdta0x2677f10) created. [Sep 3 16:59:00] DEBUG[21424] pjsip: inv0x263c1b8 .....Sending Request msg CANCEL/cseq=21703 (tdta0x2677f10) [Sep 3 16:59:00] DEBUG[21424] pjsip: dlg0x263c1b8 ......Sending Request msg CANCEL/cseq=21703 (tdta0x2677f10) [Sep 3 16:59:00] DEBUG[21424] pjsip: tsx0x2692ef8 .......Transaction created for Request msg CANCEL/cseq=21703 (tdta0x2677f10) [Sep 3 16:59:00] DEBUG[21424] pjsip: tsx0x2692ef8 ......Sending Request msg CANCEL/cseq=21703 (tdta0x2677f10) in state Null [Sep 3 16:59:00] DEBUG[21424] pjsip: endpoint .......Request msg CANCEL/cseq=21703 (tdta0x2677f10): skipping target resolution because address is already set [Sep 3 16:59:00] DEBUG[21424] netsock2.c: Splitting '0.0.0.0:5060' into... [Sep 3 16:59:00] DEBUG[21424] netsock2.c: ...host '0.0.0.0' and port '5060'. [Sep 3 16:59:00] DEBUG[21424] netsock2.c: Splitting '216.207.245.55:5062' into... [Sep 3 16:59:00] DEBUG[21424] netsock2.c: ...host '216.207.245.55' and port '5062'. [Sep 3 16:59:00] VERBOSE[21424] res_pjsip_logger.c: <--- Transmitting SIP request (397 bytes) to UDP:216.207.245.55:5062 ---> CANCEL sip:100@216.207.245.55:5062 SIP/2.0 Via: SIP/2.0/UDP 104.236.91.141:5060;rport;branch=z9hG4bKPj57afe773-01ec-4303-a70d-a29d93e98ef6 From: "10" ;tag=04ac5709-9664-4015-a36b-ccae72514ee8 To: Call-ID: 36354359-cbe9-42fb-94eb-8012a23c8a6f CSeq: 21703 CANCEL Max-Forwards: 70 User-Agent: Asterisk PBX GIT-13-2733638M Content-Length: 0 [Sep 3 16:59:00] DEBUG[21424] pjsip: tsx0x2692ef8 .......State changed from Null to Calling, event=TX_MSG [Sep 3 16:59:00] DEBUG[21424] pjsip: dlg0x263c1b8 ........Transaction tsx0x2692ef8 state changed to Calling [Sep 3 16:59:00] DEBUG[21424] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Sep 3 16:59:00] DEBUG[21424] res_pjsip_session.c: The state change pertains to the endpoint '100()' [Sep 3 16:59:00] DEBUG[21424] res_pjsip_session.c: The inv session still has an invite_tsx (0x26eb538) [Sep 3 16:59:00] DEBUG[21424] res_pjsip_session.c: The UAC CANCEL transaction involved in this state change is 0x2692ef8 [Sep 3 16:59:00] DEBUG[21424] res_pjsip_session.c: The current transaction state is Calling [Sep 3 16:59:00] DEBUG[21424] res_pjsip_session.c: The transaction state change event is TX_MSG [Sep 3 16:59:00] DEBUG[21424] res_pjsip_session.c: The current inv state is CALLING [Sep 3 16:59:00] DEBUG[21424] res_pjsip_session.c: Sending request [Sep 3 16:59:00] DEBUG[21424] res_pjsip_session.c: Method is CANCEL [Sep 3 16:59:00] DEBUG[21424] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Sep 3 16:59:00] DEBUG[21424] res_pjsip_session.c: The state change pertains to the endpoint '100()' [Sep 3 16:59:00] DEBUG[21424] res_pjsip_session.c: The inv session still has an invite_tsx (0x26eb538) [Sep 3 16:59:00] DEBUG[21424] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x26eb538 [Sep 3 16:59:00] DEBUG[21424] res_pjsip_session.c: The current transaction state is Proceeding [Sep 3 16:59:00] DEBUG[21424] res_pjsip_session.c: The transaction state change event is RX_MSG [Sep 3 16:59:00] DEBUG[21424] res_pjsip_session.c: The current inv state is CALLING [Sep 3 16:59:00] DEBUG[21424] res_pjsip_session.c: Received response [Sep 3 16:59:00] DEBUG[21424] res_pjsip_session.c: Response is 100 Trying [Sep 3 16:59:00] DEBUG[20309] pjsip: tsx0x26e6aa8 Retransmit timer event [Sep 3 16:59:00] DEBUG[20309] pjsip: tsx0x26e6aa8 .Retransmiting Response msg 486/INVITE/cseq=1 (tdta0x7f1d8469ddf0), count=2, restart?=1 [Sep 3 16:59:00] DEBUG[20309] netsock2.c: Splitting '0.0.0.0:5060' into... [Sep 3 16:59:00] DEBUG[20309] netsock2.c: ...host '0.0.0.0' and port '5060'. [Sep 3 16:59:00] DEBUG[20309] netsock2.c: Splitting '62.210.250.141:5092' into... [Sep 3 16:59:00] DEBUG[20309] netsock2.c: ...host '62.210.250.141' and port '5092'. [Sep 3 16:59:00] VERBOSE[20309] res_pjsip_logger.c: <--- Transmitting SIP response (548 bytes) to UDP:62.210.250.141:5092 ---> SIP/2.0 486 Busy Here Via: SIP/2.0/UDP 62.210.250.141:5092;rport=5092;received=62.210.250.141;branch=z9hG4bK-d2521dccdb15f96367ea2cddfe704056 Call-ID: d2521dccdb15f96367ea2cddfe704056 From: "10" ;tag=c4f757db To: "901141445209952" ;tag=0df24d29-3d71-4ca4-941a-dcd9d755aab8 CSeq: 1 INVITE Server: Asterisk PBX GIT-13-2733638M Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, MESSAGE, REFER Reason: Q.850;cause=17 Content-Length: 0 [Sep 3 16:59:00] DEBUG[20309] pjsip: tsx0x264ff38 Retransmit timer event [Sep 3 16:59:00] DEBUG[20309] pjsip: tsx0x264ff38 .Retransmiting Request msg CANCEL/cseq=28856 (tdta0x26c3d90), count=0, restart?=1 [Sep 3 16:59:00] DEBUG[20309] netsock2.c: Splitting '0.0.0.0:5060' into... [Sep 3 16:59:00] DEBUG[20309] netsock2.c: ...host '0.0.0.0' and port '5060'. [Sep 3 16:59:00] DEBUG[20309] netsock2.c: Splitting '216.207.245.55:5062' into... [Sep 3 16:59:00] DEBUG[20309] netsock2.c: ...host '216.207.245.55' and port '5062'. [Sep 3 16:59:00] VERBOSE[20309] res_pjsip_logger.c: <--- Transmitting SIP request (443 bytes) to UDP:216.207.245.55:5062 ---> CANCEL sip:100@216.207.245.55:5062 SIP/2.0 Via: SIP/2.0/UDP 104.236.91.141:5060;rport;branch=z9hG4bKPja1274184-4bea-4ea6-8b43-a6a10de167cd From: "10" ;tag=61da471f-a968-41b1-a173-c8abf41f1a9b To: Call-ID: a661c813-8f12-414e-85f0-b0b171a1158c CSeq: 28856 CANCEL Reason: Q.850;cause=0 Max-Forwards: 70 User-Agent: Asterisk PBX GIT-13-2733638M Reason: Q.850;cause=0 Content-Length: 0 [Sep 3 16:59:00] DEBUG[20309] pjsip: tsx0x7f1d94041 Retransmit timer event [Sep 3 16:59:00] DEBUG[20309] pjsip: tsx0x7f1d94041 .Retransmiting Request msg INVITE/cseq=9786 (tdta0x7f1d8469cde0), count=0, restart?=1 [Sep 3 16:59:00] DEBUG[20309] res_pjsip_multihomed.c: Re-wrote Contact URI host/port to 104.236.91.141:5060 [Sep 3 16:59:00] DEBUG[20309] netsock2.c: Splitting '0.0.0.0:5060' into... [Sep 3 16:59:00] DEBUG[20309] netsock2.c: ...host '0.0.0.0' and port '5060'. [Sep 3 16:59:00] DEBUG[20309] netsock2.c: Splitting '216.207.245.55:5062' into... [Sep 3 16:59:00] DEBUG[20309] netsock2.c: ...host '216.207.245.55' and port '5062'. [Sep 3 16:59:00] VERBOSE[20309] res_pjsip_logger.c: <--- Transmitting SIP request (934 bytes) to UDP:216.207.245.55:5062 ---> INVITE sip:100@216.207.245.55:5062 SIP/2.0 Via: SIP/2.0/UDP 104.236.91.141:5060;rport;branch=z9hG4bKPjb3790e57-4a3a-4e4c-b6f8-d974e6b3ae3f From: "10" ;tag=b43243bb-083f-4e0b-b563-5b3f5439572f To: Contact: Call-ID: e1acc1c1-12b1-40bb-8617-1b281a4a1bcb CSeq: 9786 INVITE Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, MESSAGE, REFER Supported: 100rel, timer, replaces, norefersub Session-Expires: 1800 Min-SE: 90 Max-Forwards: 70 User-Agent: Asterisk PBX GIT-13-2733638M Content-Type: application/sdp Content-Length: 237 v=0 o=- 20965212 20965212 IN IP4 104.236.91.141 s=Asterisk c=IN IP4 104.236.91.141 t=0 0 m=audio 15320 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=maxptime:150 a=sendrecv [Sep 3 16:59:00] DEBUG[20309] pjsip: tsx0x2662bb8 Retransmit timer event [Sep 3 16:59:00] DEBUG[20309] pjsip: tsx0x2662bb8 .Retransmiting Response msg 486/INVITE/cseq=1 (tdta0x7f1d842c6d90), count=0, restart?=1 [Sep 3 16:59:00] DEBUG[20309] netsock2.c: Splitting '0.0.0.0:5060' into... [Sep 3 16:59:00] DEBUG[20309] netsock2.c: ...host '0.0.0.0' and port '5060'. [Sep 3 16:59:00] DEBUG[20309] netsock2.c: Splitting '62.210.250.141:5104' into... [Sep 3 16:59:00] DEBUG[20309] netsock2.c: ...host '62.210.250.141' and port '5104'. [Sep 3 16:59:00] VERBOSE[20309] res_pjsip_logger.c: <--- Transmitting SIP response (548 bytes) to UDP:62.210.250.141:5104 ---> SIP/2.0 486 Busy Here Via: SIP/2.0/UDP 62.210.250.141:5104;rport=5104;received=62.210.250.141;branch=z9hG4bK-8272d6c33827f4048f59de640b1f8e1d Call-ID: 8272d6c33827f4048f59de640b1f8e1d From: "10" ;tag=ad72f6fb To: "701141445209952" ;tag=9e54d872-2d5e-4834-a90d-b0b4e02d80de CSeq: 1 INVITE Server: Asterisk PBX GIT-13-2733638M Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, MESSAGE, REFER Reason: Q.850;cause=17 Content-Length: 0 [Sep 3 16:59:00] DEBUG[20309] pjsip: tsx0x2692ef8 Retransmit timer event [Sep 3 16:59:00] DEBUG[20309] pjsip: tsx0x2692ef8 .Retransmiting Request msg CANCEL/cseq=21703 (tdta0x2677f10), count=0, restart?=1 [Sep 3 16:59:00] DEBUG[20309] netsock2.c: Splitting '0.0.0.0:5060' into... [Sep 3 16:59:00] DEBUG[20309] netsock2.c: ...host '0.0.0.0' and port '5060'. [Sep 3 16:59:00] DEBUG[20309] netsock2.c: Splitting '216.207.245.55:5062' into... [Sep 3 16:59:00] DEBUG[20309] netsock2.c: ...host '216.207.245.55' and port '5062'. [Sep 3 16:59:00] VERBOSE[20309] res_pjsip_logger.c: <--- Transmitting SIP request (397 bytes) to UDP:216.207.245.55:5062 ---> CANCEL sip:100@216.207.245.55:5062 SIP/2.0 Via: SIP/2.0/UDP 104.236.91.141:5060;rport;branch=z9hG4bKPj57afe773-01ec-4303-a70d-a29d93e98ef6 From: "10" ;tag=04ac5709-9664-4015-a36b-ccae72514ee8 To: Call-ID: 36354359-cbe9-42fb-94eb-8012a23c8a6f CSeq: 21703 CANCEL Max-Forwards: 70 User-Agent: Asterisk PBX GIT-13-2733638M Content-Length: 0 [Sep 3 16:59:00] DEBUG[20309] pjsip: tsx0x2708768 Timeout timer event [Sep 3 16:59:00] DEBUG[20309] pjsip: tsx0x2708768 .State changed from Completed to Terminated, event=TIMER [Sep 3 16:59:00] DEBUG[20309] pjsip: tsx0x2708768 Timeout timer event [Sep 3 16:59:00] DEBUG[20309] pjsip: tsx0x2708768 .State changed from Terminated to Destroyed, event=TIMER [Sep 3 16:59:00] DEBUG[20309] pjsip: tdta0x265c550 ..Destroying txdata Request msg OPTIONS/cseq=8709 (tdta0x265c550) [Sep 3 16:59:00] DEBUG[20309] pjsip: tsx0x2708768 Transaction destroyed! [Sep 3 16:59:00] DEBUG[20309] pjsip: tsx0x7f1d7c025 Timeout timer event [Sep 3 16:59:00] DEBUG[20309] pjsip: tsx0x7f1d7c025 .State changed from Completed to Terminated, event=TIMER [Sep 3 16:59:00] DEBUG[20309] pjsip: dlg0x2714138 ..Transaction tsx0x7f1d7c0250c8 state changed to Terminated [Sep 3 16:59:00] DEBUG[20309] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Sep 3 16:59:00] DEBUG[20309] res_pjsip_session.c: The state change pertains to the endpoint '100()' [Sep 3 16:59:00] DEBUG[20309] res_pjsip_session.c: The inv session still has an invite_tsx (0x267c8d8) [Sep 3 16:59:00] DEBUG[20309] res_pjsip_session.c: The UAC CANCEL transaction involved in this state change is 0x7f1d7c0250c8 [Sep 3 16:59:00] DEBUG[20309] res_pjsip_session.c: The current transaction state is Terminated [Sep 3 16:59:00] DEBUG[20309] res_pjsip_session.c: The transaction state change event is TIMER [Sep 3 16:59:00] DEBUG[20309] res_pjsip_session.c: The current inv state is DISCONNCTD [Sep 3 16:59:00] DEBUG[20309] pjsip: tsx0x7f1d7c025 Timeout timer event [Sep 3 16:59:00] DEBUG[20309] pjsip: tsx0x7f1d7c025 .State changed from Terminated to Destroyed, event=TIMER [Sep 3 16:59:00] DEBUG[20309] pjsip: tdta0x7f1d8469 ..Destroying txdata Request msg CANCEL/cseq=26261 (tdta0x7f1d8469bdd0) [Sep 3 16:59:00] DEBUG[20309] pjsip: tsx0x7f1d7c025 Transaction destroyed! [Sep 3 16:59:00] DEBUG[22208] res_pjsip_session.c: Destroying SIP session with endpoint 100 [Sep 3 16:59:00] DEBUG[22208] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7f1d7c0938f8' [Sep 3 16:59:00] DEBUG[22208] rtp_engine.c: Destroyed RTP instance '0x7f1d7c0938f8' [Sep 3 16:59:00] DEBUG[22208] pjsip: dlg0x2714138 .Session count dec to 0 by Session Module [Sep 3 16:59:00] DEBUG[22208] taskprocessor.c: destroying taskprocessor '69dff69e-3de6-41b9-be26-de4b34e41b75' [Sep 3 16:59:00] DEBUG[20309] pjsip: tsx0x26ea908 Retransmit timer event [Sep 3 16:59:00] DEBUG[20309] pjsip: tsx0x26ea908 .Retransmiting Response msg 486/INVITE/cseq=1 (tdta0x7f1d7c0fc6b0), count=3, restart?=1 [Sep 3 16:59:00] DEBUG[20309] netsock2.c: Splitting '0.0.0.0:5060' into... [Sep 3 16:59:00] DEBUG[20309] netsock2.c: ...host '0.0.0.0' and port '5060'. [Sep 3 16:59:00] DEBUG[20309] netsock2.c: Splitting '62.210.250.141:5090' into... [Sep 3 16:59:00] DEBUG[20309] netsock2.c: ...host '62.210.250.141' and port '5090'. [Sep 3 16:59:00] VERBOSE[20309] res_pjsip_logger.c: <--- Transmitting SIP response (544 bytes) to UDP:62.210.250.141:5090 ---> SIP/2.0 486 Busy Here Via: SIP/2.0/UDP 62.210.250.141:5090;rport=5090;received=62.210.250.141;branch=z9hG4bK-e8219817386b4d48ab35c4f26587a722 Call-ID: e8219817386b4d48ab35c4f26587a722 From: "10" ;tag=f29bff17 To: "0041445209952" ;tag=15236277-ac5a-4ede-a54e-43cb8eab9c48 CSeq: 1 INVITE Server: Asterisk PBX GIT-13-2733638M Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, MESSAGE, REFER Reason: Q.850;cause=17 Content-Length: 0 [Sep 3 16:59:01] DEBUG[20309] pjsip: sip_endpoint.c Processing incoming message: Response msg 487/INVITE/cseq=31783 (rdata0x7f1d840009b8) [Sep 3 16:59:01] VERBOSE[20309] res_pjsip_logger.c: <--- Received SIP response (379 bytes) from UDP:216.207.245.55:5062 ---> SIP/2.0 487 Request Terminated Via: SIP/2.0/UDP 104.236.91.141:5060;rport;branch=z9hG4bKPj44098dbd-1c02-4deb-8525-f12f73adc9f3 From: "10" ;tag=86c31053-87cf-4f2e-94ac-0ae196238ca1 To: ;tag=1995983909 Call-ID: 0652ab77-52f7-45b4-87a9-8cbc8463dac8 CSeq: 31783 INVITE User-Agent: Yealink SIP-T28P 2.61.0.80 Content-Length: 0 [Sep 3 16:59:01] DEBUG[20309] netsock2.c: Splitting '216.207.245.55:5062' into... [Sep 3 16:59:01] DEBUG[20309] netsock2.c: ...host '216.207.245.55' and port '5062'. [Sep 3 16:59:01] DEBUG[20309] netsock2.c: Splitting '0.0.0.0:5060' into... [Sep 3 16:59:01] DEBUG[20309] netsock2.c: ...host '0.0.0.0' and port '5060'. [Sep 3 16:59:01] DEBUG[21424] pjsip: sip_endpoint.c Distributing rdata to modules: Response msg 487/INVITE/cseq=31783 (rdata0x7f1d842ca998) [Sep 3 16:59:01] DEBUG[21424] pjsip: tsx0x2707f58 .Incoming Response msg 487/INVITE/cseq=31783 (rdata0x7f1d842ca998) in state Completed [Sep 3 16:59:01] DEBUG[21424] pjsip: tsx0x2707f58 ..Retransmiting Request msg ACK/cseq=31783 (tdta0x7f1d94025820), count=0, restart?=0 [Sep 3 16:59:01] DEBUG[21424] netsock2.c: Splitting '0.0.0.0:5060' into... [Sep 3 16:59:01] DEBUG[21424] netsock2.c: ...host '0.0.0.0' and port '5060'. [Sep 3 16:59:01] DEBUG[21424] netsock2.c: Splitting '216.207.245.55:5062' into... [Sep 3 16:59:01] DEBUG[21424] netsock2.c: ...host '216.207.245.55' and port '5062'. [Sep 3 16:59:01] VERBOSE[21424] res_pjsip_logger.c: <--- Transmitting SIP request (406 bytes) to UDP:216.207.245.55:5062 ---> ACK sip:100@216.207.245.55:5062 SIP/2.0 Via: SIP/2.0/UDP 104.236.91.141:5060;rport;branch=z9hG4bKPj44098dbd-1c02-4deb-8525-f12f73adc9f3 From: "10" ;tag=86c31053-87cf-4f2e-94ac-0ae196238ca1 To: ;tag=1995983909 Call-ID: 0652ab77-52f7-45b4-87a9-8cbc8463dac8 CSeq: 31783 ACK Max-Forwards: 70 User-Agent: Asterisk PBX GIT-13-2733638M Content-Length: 0 [Sep 3 16:59:01] DEBUG[20309] pjsip: sip_endpoint.c Processing incoming message: Response msg 487/INVITE/cseq=446 (rdata0x7f1d840009b8) [Sep 3 16:59:01] VERBOSE[20309] res_pjsip_logger.c: <--- Received SIP response (377 bytes) from UDP:216.207.245.55:5062 ---> SIP/2.0 487 Request Terminated Via: SIP/2.0/UDP 104.236.91.141:5060;rport;branch=z9hG4bKPjb7697ce2-b729-4cc4-9d2e-3b1a299c6683 From: "10" ;tag=86853df9-231f-4ddd-a6ec-e0b666a2a88a To: ;tag=1014556814 Call-ID: c876fcb5-6843-491f-865c-d235542168a3 CSeq: 446 INVITE User-Agent: Yealink SIP-T28P 2.61.0.80 Content-Length: 0 [Sep 3 16:59:01] DEBUG[20309] netsock2.c: Splitting '216.207.245.55:5062' into... [Sep 3 16:59:01] DEBUG[20309] netsock2.c: ...host '216.207.245.55' and port '5062'. [Sep 3 16:59:01] DEBUG[20309] netsock2.c: Splitting '0.0.0.0:5060' into... [Sep 3 16:59:01] DEBUG[20309] netsock2.c: ...host '0.0.0.0' and port '5060'. [Sep 3 16:59:01] DEBUG[22208] pjsip: sip_endpoint.c Distributing rdata to modules: Response msg 487/INVITE/cseq=446 (rdata0x7f1d842ca998) [Sep 3 16:59:01] DEBUG[22208] pjsip: tsx0x2648ab8 .Incoming Response msg 487/INVITE/cseq=446 (rdata0x7f1d842ca998) in state Completed [Sep 3 16:59:01] DEBUG[22208] pjsip: tsx0x2648ab8 ..Retransmiting Request msg ACK/cseq=446 (tdta0x2684d10), count=1, restart?=0 [Sep 3 16:59:01] DEBUG[22208] netsock2.c: Splitting '0.0.0.0:5060' into... [Sep 3 16:59:01] DEBUG[22208] netsock2.c: ...host '0.0.0.0' and port '5060'. [Sep 3 16:59:01] DEBUG[22208] netsock2.c: Splitting '216.207.245.55:5062' into... [Sep 3 16:59:01] DEBUG[22208] netsock2.c: ...host '216.207.245.55' and port '5062'. [Sep 3 16:59:01] VERBOSE[22208] res_pjsip_logger.c: <--- Transmitting SIP request (404 bytes) to UDP:216.207.245.55:5062 ---> ACK sip:100@216.207.245.55:5062 SIP/2.0 Via: SIP/2.0/UDP 104.236.91.141:5060;rport;branch=z9hG4bKPjb7697ce2-b729-4cc4-9d2e-3b1a299c6683 From: "10" ;tag=86853df9-231f-4ddd-a6ec-e0b666a2a88a To: ;tag=1014556814 Call-ID: c876fcb5-6843-491f-865c-d235542168a3 CSeq: 446 ACK Max-Forwards: 70 User-Agent: Asterisk PBX GIT-13-2733638M Content-Length: 0 [Sep 3 16:59:01] DEBUG[20309] pjsip: sip_endpoint.c Processing incoming message: Response msg 180/INVITE/cseq=21703 (rdata0x7f1d840009b8) [Sep 3 16:59:01] VERBOSE[20309] res_pjsip_logger.c: <--- Received SIP response (575 bytes) from UDP:216.207.245.55:5062 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 104.236.91.141:5060;rport;branch=z9hG4bKPj57afe773-01ec-4303-a70d-a29d93e98ef6 From: "10" ;tag=04ac5709-9664-4015-a36b-ccae72514ee8 To: ;tag=745272603 Call-ID: 36354359-cbe9-42fb-94eb-8012a23c8a6f CSeq: 21703 INVITE Contact: Allow: INVITE, INFO, PRACK, ACK, BYE, CANCEL, OPTIONS, NOTIFY, REGISTER, SUBSCRIBE, REFER, PUBLISH, UPDATE, MESSAGE User-Agent: Yealink SIP-T28P 2.61.0.80 Allow-Events: talk,hold,conference,refer,check-sync Content-Length: 0 [Sep 3 16:59:01] DEBUG[20309] netsock2.c: Splitting '216.207.245.55:5062' into... [Sep 3 16:59:01] DEBUG[20309] netsock2.c: ...host '216.207.245.55' and port '5062'. [Sep 3 16:59:01] DEBUG[20309] netsock2.c: Splitting '0.0.0.0:5060' into... [Sep 3 16:59:01] DEBUG[20309] netsock2.c: ...host '0.0.0.0' and port '5060'. [Sep 3 16:59:01] DEBUG[21424] pjsip: sip_endpoint.c Distributing rdata to modules: Response msg 180/INVITE/cseq=21703 (rdata0x7f1d842ca998) [Sep 3 16:59:01] DEBUG[21424] pjsip: tsx0x26eb538 .Incoming Response msg 180/INVITE/cseq=21703 (rdata0x7f1d842ca998) in state Proceeding [Sep 3 16:59:01] DEBUG[21424] pjsip: tsx0x26eb538 ..State changed from Proceeding to Proceeding, event=RX_MSG [Sep 3 16:59:01] DEBUG[21424] pjsip: dlg0x263c1b8 ...Received Response msg 180/INVITE/cseq=21703 (rdata0x7f1d842ca998) [Sep 3 16:59:01] DEBUG[21424] pjsip: dlg0x263c1b8 ....Route-set updated [Sep 3 16:59:01] DEBUG[21424] pjsip: dlg0x263c1b8 ...Transaction tsx0x26eb538 state changed to Proceeding [Sep 3 16:59:01] DEBUG[21424] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Sep 3 16:59:01] DEBUG[21424] res_pjsip_session.c: The state change pertains to the endpoint '100()' [Sep 3 16:59:01] DEBUG[21424] res_pjsip_session.c: The inv session still has an invite_tsx (0x26eb538) [Sep 3 16:59:01] DEBUG[21424] res_pjsip_session.c: There is no transaction involved in this state change [Sep 3 16:59:01] DEBUG[21424] res_pjsip_session.c: The current inv state is EARLY [Sep 3 16:59:01] DEBUG[21424] res_pjsip_session.c: Source of transaction state change is RX_MSG [Sep 3 16:59:01] DEBUG[21424] res_pjsip_session.c: Received response [Sep 3 16:59:01] DEBUG[21424] res_pjsip_session.c: Response is 180 Ringing [Sep 3 16:59:01] DEBUG[21424] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Sep 3 16:59:01] DEBUG[21424] res_pjsip_session.c: The state change pertains to the endpoint '100()' [Sep 3 16:59:01] DEBUG[21424] res_pjsip_session.c: The inv session still has an invite_tsx (0x26eb538) [Sep 3 16:59:01] DEBUG[21424] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x26eb538 [Sep 3 16:59:01] DEBUG[21424] res_pjsip_session.c: The current transaction state is Proceeding [Sep 3 16:59:01] DEBUG[21424] res_pjsip_session.c: The transaction state change event is RX_MSG [Sep 3 16:59:01] DEBUG[21424] res_pjsip_session.c: The current inv state is EARLY [Sep 3 16:59:01] DEBUG[21424] res_pjsip_session.c: Received response [Sep 3 16:59:01] DEBUG[21424] res_pjsip_session.c: Response is 180 Ringing [Sep 3 16:59:01] DEBUG[20309] pjsip: sip_endpoint.c Processing incoming message: Response msg 200/CANCEL/cseq=31783 (rdata0x7f1d840009b8) [Sep 3 16:59:01] VERBOSE[20309] res_pjsip_logger.c: <--- Received SIP response (363 bytes) from UDP:216.207.245.55:5062 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 104.236.91.141:5060;rport;branch=z9hG4bKPj44098dbd-1c02-4deb-8525-f12f73adc9f3 From: "10" ;tag=86c31053-87cf-4f2e-94ac-0ae196238ca1 To: ;tag=1995983909 Call-ID: 0652ab77-52f7-45b4-87a9-8cbc8463dac8 CSeq: 31783 CANCEL User-Agent: Yealink SIP-T28P 2.61.0.80 Content-Length: 0 [Sep 3 16:59:01] DEBUG[20309] netsock2.c: Splitting '216.207.245.55:5062' into... [Sep 3 16:59:01] DEBUG[20309] netsock2.c: ...host '216.207.245.55' and port '5062'. [Sep 3 16:59:01] DEBUG[20309] netsock2.c: Splitting '0.0.0.0:5060' into... [Sep 3 16:59:01] DEBUG[20309] netsock2.c: ...host '0.0.0.0' and port '5060'. [Sep 3 16:59:01] DEBUG[22208] pjsip: sip_endpoint.c Distributing rdata to modules: Response msg 200/CANCEL/cseq=31783 (rdata0x7f1d842ca998) [Sep 3 16:59:01] DEBUG[22208] pjsip: tsx0x263b268 .Incoming Response msg 200/CANCEL/cseq=31783 (rdata0x7f1d842ca998) in state Completed [Sep 3 16:59:01] DEBUG[20309] pjsip: sip_endpoint.c Processing incoming message: Response msg 180/INVITE/cseq=21703 (rdata0x7f1d840009b8) [Sep 3 16:59:01] VERBOSE[20309] res_pjsip_logger.c: <--- Received SIP response (575 bytes) from UDP:216.207.245.55:5062 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 104.236.91.141:5060;rport;branch=z9hG4bKPj57afe773-01ec-4303-a70d-a29d93e98ef6 From: "10" ;tag=04ac5709-9664-4015-a36b-ccae72514ee8 To: ;tag=745272603 Call-ID: 36354359-cbe9-42fb-94eb-8012a23c8a6f CSeq: 21703 INVITE Contact: Allow: INVITE, INFO, PRACK, ACK, BYE, CANCEL, OPTIONS, NOTIFY, REGISTER, SUBSCRIBE, REFER, PUBLISH, UPDATE, MESSAGE User-Agent: Yealink SIP-T28P 2.61.0.80 Allow-Events: talk,hold,conference,refer,check-sync Content-Length: 0 [Sep 3 16:59:01] DEBUG[20309] netsock2.c: Splitting '216.207.245.55:5062' into... [Sep 3 16:59:01] DEBUG[20309] netsock2.c: ...host '216.207.245.55' and port '5062'. [Sep 3 16:59:01] DEBUG[20309] netsock2.c: Splitting '0.0.0.0:5060' into... [Sep 3 16:59:01] DEBUG[20309] netsock2.c: ...host '0.0.0.0' and port '5060'. [Sep 3 16:59:01] DEBUG[21424] pjsip: sip_endpoint.c Distributing rdata to modules: Response msg 180/INVITE/cseq=21703 (rdata0x7f1d842ca998) [Sep 3 16:59:01] DEBUG[21424] pjsip: tsx0x26eb538 .Incoming Response msg 180/INVITE/cseq=21703 (rdata0x7f1d842ca998) in state Proceeding [Sep 3 16:59:01] DEBUG[21424] pjsip: tsx0x26eb538 ..State changed from Proceeding to Proceeding, event=RX_MSG [Sep 3 16:59:01] DEBUG[21424] pjsip: dlg0x263c1b8 ...Received Response msg 180/INVITE/cseq=21703 (rdata0x7f1d842ca998) [Sep 3 16:59:01] DEBUG[21424] pjsip: dlg0x263c1b8 ...Transaction tsx0x26eb538 state changed to Proceeding [Sep 3 16:59:01] DEBUG[21424] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Sep 3 16:59:01] DEBUG[21424] res_pjsip_session.c: The state change pertains to the endpoint '100()' [Sep 3 16:59:01] DEBUG[21424] res_pjsip_session.c: The inv session still has an invite_tsx (0x26eb538) [Sep 3 16:59:01] DEBUG[21424] res_pjsip_session.c: There is no transaction involved in this state change [Sep 3 16:59:01] DEBUG[21424] res_pjsip_session.c: The current inv state is EARLY [Sep 3 16:59:01] DEBUG[21424] res_pjsip_session.c: Source of transaction state change is RX_MSG [Sep 3 16:59:01] DEBUG[21424] res_pjsip_session.c: Received response [Sep 3 16:59:01] DEBUG[21424] res_pjsip_session.c: Response is 180 Ringing [Sep 3 16:59:01] DEBUG[21424] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Sep 3 16:59:01] DEBUG[21424] res_pjsip_session.c: The state change pertains to the endpoint '100()' [Sep 3 16:59:01] DEBUG[21424] res_pjsip_session.c: The inv session still has an invite_tsx (0x26eb538) [Sep 3 16:59:01] DEBUG[21424] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x26eb538 [Sep 3 16:59:01] DEBUG[21424] res_pjsip_session.c: The current transaction state is Proceeding [Sep 3 16:59:01] DEBUG[21424] res_pjsip_session.c: The transaction state change event is RX_MSG [Sep 3 16:59:01] DEBUG[21424] res_pjsip_session.c: The current inv state is EARLY [Sep 3 16:59:01] DEBUG[21424] res_pjsip_session.c: Received response [Sep 3 16:59:01] DEBUG[21424] res_pjsip_session.c: Response is 180 Ringing [Sep 3 16:59:01] DEBUG[20309] pjsip: sip_endpoint.c Processing incoming message: Response msg 180/INVITE/cseq=21773 (rdata0x7f1d840009b8) [Sep 3 16:59:01] VERBOSE[20309] res_pjsip_logger.c: <--- Received SIP response (575 bytes) from UDP:216.207.245.55:5062 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 104.236.91.141:5060;rport;branch=z9hG4bKPj55a76574-cd6a-4934-bda5-905b0c6a8634 From: "10" ;tag=386fdc79-d013-4a15-92cc-bce663406f66 To: ;tag=827751994 Call-ID: 55941bad-87f2-486a-aa99-f976fbf6168c CSeq: 21773 INVITE Contact: Allow: INVITE, INFO, PRACK, ACK, BYE, CANCEL, OPTIONS, NOTIFY, REGISTER, SUBSCRIBE, REFER, PUBLISH, UPDATE, MESSAGE User-Agent: Yealink SIP-T28P 2.61.0.80 Allow-Events: talk,hold,conference,refer,check-sync Content-Length: 0 [Sep 3 16:59:01] DEBUG[20309] netsock2.c: Splitting '216.207.245.55:5062' into... [Sep 3 16:59:01] DEBUG[20309] netsock2.c: ...host '216.207.245.55' and port '5062'. [Sep 3 16:59:01] DEBUG[20309] netsock2.c: Splitting '0.0.0.0:5060' into... [Sep 3 16:59:01] DEBUG[20309] netsock2.c: ...host '0.0.0.0' and port '5060'. [Sep 3 16:59:01] DEBUG[22208] pjsip: sip_endpoint.c Distributing rdata to modules: Response msg 180/INVITE/cseq=21773 (rdata0x7f1d842ca998) [Sep 3 16:59:01] DEBUG[22208] pjsip: tsx0x269f4f8 .Incoming Response msg 180/INVITE/cseq=21773 (rdata0x7f1d842ca998) in state Proceeding [Sep 3 16:59:01] DEBUG[22208] pjsip: tsx0x269f4f8 ..State changed from Proceeding to Proceeding, event=RX_MSG [Sep 3 16:59:01] DEBUG[22208] pjsip: dlg0x272f8b8 ...Received Response msg 180/INVITE/cseq=21773 (rdata0x7f1d842ca998) [Sep 3 16:59:01] DEBUG[22208] pjsip: dlg0x272f8b8 ...Transaction tsx0x269f4f8 state changed to Proceeding [Sep 3 16:59:01] DEBUG[22208] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Sep 3 16:59:01] DEBUG[22208] res_pjsip_session.c: The state change pertains to the endpoint '100(PJSIP/100-000000e4)' [Sep 3 16:59:01] DEBUG[22208] res_pjsip_session.c: The inv session still has an invite_tsx (0x269f4f8) [Sep 3 16:59:01] DEBUG[22208] res_pjsip_session.c: There is no transaction involved in this state change [Sep 3 16:59:01] DEBUG[22208] res_pjsip_session.c: The current inv state is EARLY [Sep 3 16:59:01] DEBUG[22208] res_pjsip_session.c: Source of transaction state change is RX_MSG [Sep 3 16:59:01] DEBUG[22208] res_pjsip_session.c: Received response [Sep 3 16:59:01] DEBUG[22208] res_pjsip_session.c: Response is 180 Ringing [Sep 3 16:59:01] DEBUG[22208] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Sep 3 16:59:01] DEBUG[22208] res_pjsip_session.c: The state change pertains to the endpoint '100(PJSIP/100-000000e4)' [Sep 3 16:59:01] DEBUG[22208] res_pjsip_session.c: The inv session still has an invite_tsx (0x269f4f8) [Sep 3 16:59:01] DEBUG[22208] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x269f4f8 [Sep 3 16:59:01] DEBUG[22208] res_pjsip_session.c: The current transaction state is Proceeding [Sep 3 16:59:01] DEBUG[22208] res_pjsip_session.c: The transaction state change event is RX_MSG [Sep 3 16:59:01] DEBUG[22208] res_pjsip_session.c: The current inv state is EARLY [Sep 3 16:59:01] DEBUG[22208] res_pjsip_session.c: Received response [Sep 3 16:59:01] DEBUG[22208] res_pjsip_session.c: Response is 180 Ringing [Sep 3 16:59:01] VERBOSE[24558][C-0000004e] app_dial.c: PJSIP/100-000000e4 is ringing [Sep 3 16:59:01] DEBUG[20309] pjsip: sip_endpoint.c Processing incoming message: Response msg 200/CANCEL/cseq=446 (rdata0x7f1d840009b8) [Sep 3 16:59:01] VERBOSE[20309] res_pjsip_logger.c: <--- Received SIP response (361 bytes) from UDP:216.207.245.55:5062 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 104.236.91.141:5060;rport;branch=z9hG4bKPjb7697ce2-b729-4cc4-9d2e-3b1a299c6683 From: "10" ;tag=86853df9-231f-4ddd-a6ec-e0b666a2a88a To: ;tag=1014556814 Call-ID: c876fcb5-6843-491f-865c-d235542168a3 CSeq: 446 CANCEL User-Agent: Yealink SIP-T28P 2.61.0.80 Content-Length: 0 [Sep 3 16:59:01] DEBUG[20309] netsock2.c: Splitting '216.207.245.55:5062' into... [Sep 3 16:59:01] DEBUG[20309] netsock2.c: ...host '216.207.245.55' and port '5062'. [Sep 3 16:59:01] DEBUG[20309] netsock2.c: Splitting '0.0.0.0:5060' into... [Sep 3 16:59:01] DEBUG[20309] netsock2.c: ...host '0.0.0.0' and port '5060'. [Sep 3 16:59:01] DEBUG[21424] pjsip: sip_endpoint.c Distributing rdata to modules: Response msg 200/CANCEL/cseq=446 (rdata0x7f1d842ca998) [Sep 3 16:59:01] DEBUG[21424] pjsip: tsx0x7f1d9403f .Incoming Response msg 200/CANCEL/cseq=446 (rdata0x7f1d842ca998) in state Completed [Sep 3 16:59:01] DEBUG[20309] pjsip: sip_endpoint.c Processing incoming message: Response msg 200/CANCEL/cseq=31783 (rdata0x7f1d840009b8) [Sep 3 16:59:01] VERBOSE[20309] res_pjsip_logger.c: <--- Received SIP response (363 bytes) from UDP:216.207.245.55:5062 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 104.236.91.141:5060;rport;branch=z9hG4bKPj44098dbd-1c02-4deb-8525-f12f73adc9f3 From: "10" ;tag=86c31053-87cf-4f2e-94ac-0ae196238ca1 To: ;tag=1995983909 Call-ID: 0652ab77-52f7-45b4-87a9-8cbc8463dac8 CSeq: 31783 CANCEL User-Agent: Yealink SIP-T28P 2.61.0.80 Content-Length: 0 [Sep 3 16:59:01] DEBUG[20309] netsock2.c: Splitting '216.207.245.55:5062' into... [Sep 3 16:59:01] DEBUG[20309] netsock2.c: ...host '216.207.245.55' and port '5062'. [Sep 3 16:59:01] DEBUG[20309] netsock2.c: Splitting '0.0.0.0:5060' into... [Sep 3 16:59:01] DEBUG[20309] netsock2.c: ...host '0.0.0.0' and port '5060'. [Sep 3 16:59:01] DEBUG[22208] pjsip: sip_endpoint.c Distributing rdata to modules: Response msg 200/CANCEL/cseq=31783 (rdata0x7f1d842ca998) [Sep 3 16:59:01] DEBUG[22208] pjsip: tsx0x263b268 .Incoming Response msg 200/CANCEL/cseq=31783 (rdata0x7f1d842ca998) in state Completed [Sep 3 16:59:01] DEBUG[20309] pjsip: sip_endpoint.c Processing incoming message: Response msg 180/INVITE/cseq=21703 (rdata0x7f1d840009b8) [Sep 3 16:59:01] VERBOSE[20309] res_pjsip_logger.c: <--- Received SIP response (575 bytes) from UDP:216.207.245.55:5062 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 104.236.91.141:5060;rport;branch=z9hG4bKPj57afe773-01ec-4303-a70d-a29d93e98ef6 From: "10" ;tag=04ac5709-9664-4015-a36b-ccae72514ee8 To: ;tag=745272603 Call-ID: 36354359-cbe9-42fb-94eb-8012a23c8a6f CSeq: 21703 INVITE Contact: Allow: INVITE, INFO, PRACK, ACK, BYE, CANCEL, OPTIONS, NOTIFY, REGISTER, SUBSCRIBE, REFER, PUBLISH, UPDATE, MESSAGE User-Agent: Yealink SIP-T28P 2.61.0.80 Allow-Events: talk,hold,conference,refer,check-sync Content-Length: 0 [Sep 3 16:59:01] DEBUG[20309] netsock2.c: Splitting '216.207.245.55:5062' into... [Sep 3 16:59:01] DEBUG[20309] netsock2.c: ...host '216.207.245.55' and port '5062'. [Sep 3 16:59:01] DEBUG[20309] netsock2.c: Splitting '0.0.0.0:5060' into... [Sep 3 16:59:01] DEBUG[20309] netsock2.c: ...host '0.0.0.0' and port '5060'. [Sep 3 16:59:01] DEBUG[21424] pjsip: sip_endpoint.c Distributing rdata to modules: Response msg 180/INVITE/cseq=21703 (rdata0x7f1d842ca998) [Sep 3 16:59:01] DEBUG[21424] pjsip: tsx0x26eb538 .Incoming Response msg 180/INVITE/cseq=21703 (rdata0x7f1d842ca998) in state Proceeding [Sep 3 16:59:01] DEBUG[21424] pjsip: tsx0x26eb538 ..State changed from Proceeding to Proceeding, event=RX_MSG [Sep 3 16:59:01] DEBUG[21424] pjsip: dlg0x263c1b8 ...Received Response msg 180/INVITE/cseq=21703 (rdata0x7f1d842ca998) [Sep 3 16:59:01] DEBUG[21424] pjsip: dlg0x263c1b8 ...Transaction tsx0x26eb538 state changed to Proceeding [Sep 3 16:59:01] DEBUG[21424] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Sep 3 16:59:01] DEBUG[21424] res_pjsip_session.c: The state change pertains to the endpoint '100()' [Sep 3 16:59:01] DEBUG[21424] res_pjsip_session.c: The inv session still has an invite_tsx (0x26eb538) [Sep 3 16:59:01] DEBUG[21424] res_pjsip_session.c: There is no transaction involved in this state change [Sep 3 16:59:01] DEBUG[21424] res_pjsip_session.c: The current inv state is EARLY [Sep 3 16:59:01] DEBUG[21424] res_pjsip_session.c: Source of transaction state change is RX_MSG [Sep 3 16:59:01] DEBUG[21424] res_pjsip_session.c: Received response [Sep 3 16:59:01] DEBUG[21424] res_pjsip_session.c: Response is 180 Ringing [Sep 3 16:59:01] DEBUG[21424] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Sep 3 16:59:01] DEBUG[21424] res_pjsip_session.c: The state change pertains to the endpoint '100()' [Sep 3 16:59:01] DEBUG[21424] res_pjsip_session.c: The inv session still has an invite_tsx (0x26eb538) [Sep 3 16:59:01] DEBUG[21424] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x26eb538 [Sep 3 16:59:01] DEBUG[21424] res_pjsip_session.c: The current transaction state is Proceeding [Sep 3 16:59:01] DEBUG[21424] res_pjsip_session.c: The transaction state change event is RX_MSG [Sep 3 16:59:01] DEBUG[21424] res_pjsip_session.c: The current inv state is EARLY [Sep 3 16:59:01] DEBUG[21424] res_pjsip_session.c: Received response [Sep 3 16:59:01] DEBUG[21424] res_pjsip_session.c: Response is 180 Ringing [Sep 3 16:59:01] DEBUG[20309] pjsip: sip_endpoint.c Processing incoming message: Response msg 200/CANCEL/cseq=28856 (rdata0x7f1d840009b8) [Sep 3 16:59:01] VERBOSE[20309] res_pjsip_logger.c: <--- Received SIP response (362 bytes) from UDP:216.207.245.55:5062 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 104.236.91.141:5060;rport;branch=z9hG4bKPja1274184-4bea-4ea6-8b43-a6a10de167cd From: "10" ;tag=61da471f-a968-41b1-a173-c8abf41f1a9b To: ;tag=977799224 Call-ID: a661c813-8f12-414e-85f0-b0b171a1158c CSeq: 28856 CANCEL User-Agent: Yealink SIP-T28P 2.61.0.80 Content-Length: 0 [Sep 3 16:59:01] DEBUG[20309] netsock2.c: Splitting '216.207.245.55:5062' into... [Sep 3 16:59:01] DEBUG[20309] netsock2.c: ...host '216.207.245.55' and port '5062'. [Sep 3 16:59:01] DEBUG[20309] netsock2.c: Splitting '0.0.0.0:5060' into... [Sep 3 16:59:01] DEBUG[20309] netsock2.c: ...host '0.0.0.0' and port '5060'. [Sep 3 16:59:01] DEBUG[22208] pjsip: sip_endpoint.c Distributing rdata to modules: Response msg 200/CANCEL/cseq=28856 (rdata0x7f1d842ca998) [Sep 3 16:59:01] DEBUG[22208] pjsip: tsx0x264ff38 .Incoming Response msg 200/CANCEL/cseq=28856 (rdata0x7f1d842ca998) in state Calling [Sep 3 16:59:01] DEBUG[22208] pjsip: tsx0x264ff38 ..State changed from Calling to Completed, event=RX_MSG [Sep 3 16:59:01] DEBUG[22208] pjsip: dlg0x7f1d94027 ...Received Response msg 200/CANCEL/cseq=28856 (rdata0x7f1d842ca998) [Sep 3 16:59:01] DEBUG[22208] pjsip: dlg0x7f1d94027 ...Transaction tsx0x264ff38 state changed to Completed [Sep 3 16:59:01] DEBUG[20309] pjsip: sip_endpoint.c Processing incoming message: Response msg 487/INVITE/cseq=28856 (rdata0x7f1d840009b8) [Sep 3 16:59:01] VERBOSE[20309] res_pjsip_logger.c: <--- Received SIP response (378 bytes) from UDP:216.207.245.55:5062 ---> SIP/2.0 487 Request Terminated Via: SIP/2.0/UDP 104.236.91.141:5060;rport;branch=z9hG4bKPja1274184-4bea-4ea6-8b43-a6a10de167cd From: "10" ;tag=61da471f-a968-41b1-a173-c8abf41f1a9b To: ;tag=977799224 Call-ID: a661c813-8f12-414e-85f0-b0b171a1158c CSeq: 28856 INVITE User-Agent: Yealink SIP-T28P 2.61.0.80 Content-Length: 0 [Sep 3 16:59:01] DEBUG[20309] netsock2.c: Splitting '216.207.245.55:5062' into... [Sep 3 16:59:01] DEBUG[20309] netsock2.c: ...host '216.207.245.55' and port '5062'. [Sep 3 16:59:01] DEBUG[20309] netsock2.c: Splitting '0.0.0.0:5060' into... [Sep 3 16:59:01] DEBUG[20309] netsock2.c: ...host '0.0.0.0' and port '5060'. [Sep 3 16:59:01] DEBUG[21424] pjsip: sip_endpoint.c Distributing rdata to modules: Response msg 487/INVITE/cseq=28856 (rdata0x7f1d842ca998) [Sep 3 16:59:01] DEBUG[21424] pjsip: tsx0x26a28f8 .Incoming Response msg 487/INVITE/cseq=28856 (rdata0x7f1d842ca998) in state Proceeding [Sep 3 16:59:01] DEBUG[21424] pjsip: endpoint ..Request msg ACK/cseq=28856 (tdta0x265c550) created. [Sep 3 16:59:01] DEBUG[21424] netsock2.c: Splitting '0.0.0.0:5060' into... [Sep 3 16:59:01] DEBUG[21424] netsock2.c: ...host '0.0.0.0' and port '5060'. [Sep 3 16:59:01] DEBUG[21424] netsock2.c: Splitting '216.207.245.55:5062' into... [Sep 3 16:59:01] DEBUG[21424] netsock2.c: ...host '216.207.245.55' and port '5062'. [Sep 3 16:59:01] VERBOSE[21424] res_pjsip_logger.c: <--- Transmitting SIP request (405 bytes) to UDP:216.207.245.55:5062 ---> ACK sip:100@216.207.245.55:5062 SIP/2.0 Via: SIP/2.0/UDP 104.236.91.141:5060;rport;branch=z9hG4bKPja1274184-4bea-4ea6-8b43-a6a10de167cd From: "10" ;tag=61da471f-a968-41b1-a173-c8abf41f1a9b To: ;tag=977799224 Call-ID: a661c813-8f12-414e-85f0-b0b171a1158c CSeq: 28856 ACK Max-Forwards: 70 User-Agent: Asterisk PBX GIT-13-2733638M Content-Length: 0 [Sep 3 16:59:01] DEBUG[21424] pjsip: tsx0x26a28f8 ..State changed from Proceeding to Completed, event=RX_MSG [Sep 3 16:59:01] DEBUG[21424] pjsip: dlg0x7f1d94027 ...Received Response msg 487/INVITE/cseq=28856 (rdata0x7f1d842ca998) [Sep 3 16:59:01] DEBUG[21424] pjsip: dlg0x7f1d94027 ...Transaction tsx0x26a28f8 state changed to Completed [Sep 3 16:59:01] DEBUG[21424] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Sep 3 16:59:01] DEBUG[21424] res_pjsip_session.c: The state change pertains to the endpoint '100()' [Sep 3 16:59:01] DEBUG[21424] res_pjsip_session.c: The inv session still has an invite_tsx (0x26a28f8) [Sep 3 16:59:01] DEBUG[21424] res_pjsip_session.c: There is no transaction involved in this state change [Sep 3 16:59:01] DEBUG[21424] res_pjsip_session.c: The current inv state is DISCONNCTD [Sep 3 16:59:01] DEBUG[21424] res_pjsip_session.c: Source of transaction state change is RX_MSG [Sep 3 16:59:01] DEBUG[21424] res_pjsip_session.c: Received response [Sep 3 16:59:01] DEBUG[21424] res_pjsip_session.c: Response is 487 Request Terminated [Sep 3 16:59:01] DEBUG[21424] pjsip: dlg0x7f1d94027 .....Session count dec to 2 by mod-invite [Sep 3 16:59:01] DEBUG[21424] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Sep 3 16:59:01] DEBUG[21424] res_pjsip_session.c: The state change pertains to the endpoint '100()' [Sep 3 16:59:01] DEBUG[21424] res_pjsip_session.c: The inv session still has an invite_tsx (0x26a28f8) [Sep 3 16:59:01] DEBUG[21424] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x26a28f8 [Sep 3 16:59:01] DEBUG[21424] res_pjsip_session.c: The current transaction state is Completed [Sep 3 16:59:01] DEBUG[21424] res_pjsip_session.c: The transaction state change event is RX_MSG [Sep 3 16:59:01] DEBUG[21424] res_pjsip_session.c: The current inv state is DISCONNCTD [Sep 3 16:59:01] DEBUG[21424] res_pjsip_session.c: Received response [Sep 3 16:59:01] DEBUG[21424] res_pjsip_session.c: Response is 487 Request Terminated [Sep 3 16:59:01] DEBUG[21424] pjsip: tdta0x7f1d842c ..Destroying txdata Request msg INVITE/cseq=28856 (tdta0x7f1d842c9960) [Sep 3 16:59:01] DEBUG[20309] pjsip: tsx0x7f1d94041 Retransmit timer event [Sep 3 16:59:01] DEBUG[20309] pjsip: tsx0x7f1d94041 .Retransmiting Request msg INVITE/cseq=9786 (tdta0x7f1d8469cde0), count=1, restart?=1 [Sep 3 16:59:01] DEBUG[20309] res_pjsip_multihomed.c: Re-wrote Contact URI host/port to 104.236.91.141:5060 [Sep 3 16:59:01] DEBUG[20309] netsock2.c: Splitting '0.0.0.0:5060' into... [Sep 3 16:59:01] DEBUG[20309] netsock2.c: ...host '0.0.0.0' and port '5060'. [Sep 3 16:59:01] DEBUG[20309] netsock2.c: Splitting '216.207.245.55:5062' into... [Sep 3 16:59:01] DEBUG[20309] netsock2.c: ...host '216.207.245.55' and port '5062'. [Sep 3 16:59:01] VERBOSE[20309] res_pjsip_logger.c: <--- Transmitting SIP request (934 bytes) to UDP:216.207.245.55:5062 ---> INVITE sip:100@216.207.245.55:5062 SIP/2.0 Via: SIP/2.0/UDP 104.236.91.141:5060;rport;branch=z9hG4bKPjb3790e57-4a3a-4e4c-b6f8-d974e6b3ae3f From: "10" ;tag=b43243bb-083f-4e0b-b563-5b3f5439572f To: Contact: Call-ID: e1acc1c1-12b1-40bb-8617-1b281a4a1bcb CSeq: 9786 INVITE Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, MESSAGE, REFER Supported: 100rel, timer, replaces, norefersub Session-Expires: 1800 Min-SE: 90 Max-Forwards: 70 User-Agent: Asterisk PBX GIT-13-2733638M Content-Type: application/sdp Content-Length: 237 v=0 o=- 20965212 20965212 IN IP4 104.236.91.141 s=Asterisk c=IN IP4 104.236.91.141 t=0 0 m=audio 15320 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=maxptime:150 a=sendrecv [Sep 3 16:59:01] DEBUG[20309] pjsip: tsx0x2662bb8 Retransmit timer event [Sep 3 16:59:01] DEBUG[20309] pjsip: tsx0x2662bb8 .Retransmiting Response msg 486/INVITE/cseq=1 (tdta0x7f1d842c6d90), count=1, restart?=1 [Sep 3 16:59:01] DEBUG[20309] netsock2.c: Splitting '0.0.0.0:5060' into... [Sep 3 16:59:01] DEBUG[20309] netsock2.c: ...host '0.0.0.0' and port '5060'. [Sep 3 16:59:01] DEBUG[20309] netsock2.c: Splitting '62.210.250.141:5104' into... [Sep 3 16:59:01] DEBUG[20309] netsock2.c: ...host '62.210.250.141' and port '5104'. [Sep 3 16:59:01] VERBOSE[20309] res_pjsip_logger.c: <--- Transmitting SIP response (548 bytes) to UDP:62.210.250.141:5104 ---> SIP/2.0 486 Busy Here Via: SIP/2.0/UDP 62.210.250.141:5104;rport=5104;received=62.210.250.141;branch=z9hG4bK-8272d6c33827f4048f59de640b1f8e1d Call-ID: 8272d6c33827f4048f59de640b1f8e1d From: "10" ;tag=ad72f6fb To: "701141445209952" ;tag=9e54d872-2d5e-4834-a90d-b0b4e02d80de CSeq: 1 INVITE Server: Asterisk PBX GIT-13-2733638M Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, MESSAGE, REFER Reason: Q.850;cause=17 Content-Length: 0 [Sep 3 16:59:01] VERBOSE[20283] asterisk.c: Remote UNIX connection [Sep 3 16:59:01] VERBOSE[24566] asterisk.c: Remote UNIX connection disconnected [Sep 3 16:59:01] DEBUG[20309] pjsip: tsx0x2692ef8 Retransmit timer event [Sep 3 16:59:01] DEBUG[20309] pjsip: tsx0x2692ef8 .Retransmiting Request msg CANCEL/cseq=21703 (tdta0x2677f10), count=1, restart?=1 [Sep 3 16:59:01] DEBUG[20309] netsock2.c: Splitting '0.0.0.0:5060' into... [Sep 3 16:59:01] DEBUG[20309] netsock2.c: ...host '0.0.0.0' and port '5060'. [Sep 3 16:59:01] DEBUG[20309] netsock2.c: Splitting '216.207.245.55:5062' into... [Sep 3 16:59:01] DEBUG[20309] netsock2.c: ...host '216.207.245.55' and port '5062'. [Sep 3 16:59:01] VERBOSE[20309] res_pjsip_logger.c: <--- Transmitting SIP request (397 bytes) to UDP:216.207.245.55:5062 ---> CANCEL sip:100@216.207.245.55:5062 SIP/2.0 Via: SIP/2.0/UDP 104.236.91.141:5060;rport;branch=z9hG4bKPj57afe773-01ec-4303-a70d-a29d93e98ef6 From: "10" ;tag=04ac5709-9664-4015-a36b-ccae72514ee8 To: Call-ID: 36354359-cbe9-42fb-94eb-8012a23c8a6f CSeq: 21703 CANCEL Max-Forwards: 70 User-Agent: Asterisk PBX GIT-13-2733638M Content-Length: 0 [Sep 3 16:59:01] DEBUG[20309] pjsip: sip_endpoint.c Processing incoming message: Response msg 100/INVITE/cseq=9786 (rdata0x7f1d840009b8) [Sep 3 16:59:01] VERBOSE[20309] res_pjsip_logger.c: <--- Received SIP response (351 bytes) from UDP:216.207.245.55:5062 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 104.236.91.141:5060;rport;branch=z9hG4bKPjb3790e57-4a3a-4e4c-b6f8-d974e6b3ae3f From: "10" ;tag=b43243bb-083f-4e0b-b563-5b3f5439572f To: Call-ID: e1acc1c1-12b1-40bb-8617-1b281a4a1bcb CSeq: 9786 INVITE User-Agent: Yealink SIP-T28P 2.61.0.80 Content-Length: 0 [Sep 3 16:59:01] DEBUG[20309] netsock2.c: Splitting '216.207.245.55:5062' into... [Sep 3 16:59:01] DEBUG[20309] netsock2.c: ...host '216.207.245.55' and port '5062'. [Sep 3 16:59:01] DEBUG[20309] netsock2.c: Splitting '0.0.0.0:5060' into... [Sep 3 16:59:01] DEBUG[20309] netsock2.c: ...host '0.0.0.0' and port '5060'. [Sep 3 16:59:01] DEBUG[22208] pjsip: sip_endpoint.c Distributing rdata to modules: Response msg 100/INVITE/cseq=9786 (rdata0x7f1d842ca998) [Sep 3 16:59:01] DEBUG[22208] pjsip: tsx0x7f1d94041 .Incoming Response msg 100/INVITE/cseq=9786 (rdata0x7f1d842ca998) in state Calling [Sep 3 16:59:01] DEBUG[22208] pjsip: tsx0x7f1d94041 ..State changed from Calling to Proceeding, event=RX_MSG [Sep 3 16:59:01] DEBUG[22208] pjsip: dlg0x272eb68 ...Received Response msg 100/INVITE/cseq=9786 (rdata0x7f1d842ca998) [Sep 3 16:59:01] DEBUG[22208] pjsip: dlg0x272eb68 ...Transaction tsx0x7f1d94041498 state changed to Proceeding [Sep 3 16:59:01] DEBUG[22208] pjsip: endpoint .....Request msg CANCEL/cseq=9786 (tdta0x7f1d842c9960) created. [Sep 3 16:59:01] DEBUG[22208] pjsip: inv0x272eb68 .....Sending Request msg CANCEL/cseq=9786 (tdta0x7f1d842c9960) [Sep 3 16:59:01] DEBUG[22208] pjsip: dlg0x272eb68 ......Sending Request msg CANCEL/cseq=9786 (tdta0x7f1d842c9960) [Sep 3 16:59:01] DEBUG[22208] pjsip: tsx0x7f1d7c025 .......Transaction created for Request msg CANCEL/cseq=9786 (tdta0x7f1d842c9960) [Sep 3 16:59:01] DEBUG[22208] pjsip: tsx0x7f1d7c025 ......Sending Request msg CANCEL/cseq=9786 (tdta0x7f1d842c9960) in state Null [Sep 3 16:59:01] DEBUG[22208] pjsip: endpoint .......Request msg CANCEL/cseq=9786 (tdta0x7f1d842c9960): skipping target resolution because address is already set [Sep 3 16:59:01] DEBUG[22208] netsock2.c: Splitting '0.0.0.0:5060' into... [Sep 3 16:59:01] DEBUG[22208] netsock2.c: ...host '0.0.0.0' and port '5060'. [Sep 3 16:59:01] DEBUG[22208] netsock2.c: Splitting '216.207.245.55:5062' into... [Sep 3 16:59:01] DEBUG[22208] netsock2.c: ...host '216.207.245.55' and port '5062'. [Sep 3 16:59:01] VERBOSE[22208] res_pjsip_logger.c: <--- Transmitting SIP request (396 bytes) to UDP:216.207.245.55:5062 ---> CANCEL sip:100@216.207.245.55:5062 SIP/2.0 Via: SIP/2.0/UDP 104.236.91.141:5060;rport;branch=z9hG4bKPjb3790e57-4a3a-4e4c-b6f8-d974e6b3ae3f From: "10" ;tag=b43243bb-083f-4e0b-b563-5b3f5439572f To: Call-ID: e1acc1c1-12b1-40bb-8617-1b281a4a1bcb CSeq: 9786 CANCEL Max-Forwards: 70 User-Agent: Asterisk PBX GIT-13-2733638M Content-Length: 0 [Sep 3 16:59:01] DEBUG[22208] pjsip: tsx0x7f1d7c025 .......State changed from Null to Calling, event=TX_MSG [Sep 3 16:59:01] DEBUG[22208] pjsip: dlg0x272eb68 ........Transaction tsx0x7f1d7c0250c8 state changed to Calling [Sep 3 16:59:01] DEBUG[22208] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Sep 3 16:59:01] DEBUG[22208] res_pjsip_session.c: The state change pertains to the endpoint '100()' [Sep 3 16:59:01] DEBUG[22208] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f1d94041498) [Sep 3 16:59:01] DEBUG[22208] res_pjsip_session.c: The UAC CANCEL transaction involved in this state change is 0x7f1d7c0250c8 [Sep 3 16:59:01] DEBUG[22208] res_pjsip_session.c: The current transaction state is Calling [Sep 3 16:59:01] DEBUG[22208] res_pjsip_session.c: The transaction state change event is TX_MSG [Sep 3 16:59:01] DEBUG[22208] res_pjsip_session.c: The current inv state is CALLING [Sep 3 16:59:01] DEBUG[22208] res_pjsip_session.c: Sending request [Sep 3 16:59:01] DEBUG[22208] res_pjsip_session.c: Method is CANCEL [Sep 3 16:59:01] DEBUG[22208] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Sep 3 16:59:01] DEBUG[22208] res_pjsip_session.c: The state change pertains to the endpoint '100()' [Sep 3 16:59:01] DEBUG[22208] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f1d94041498) [Sep 3 16:59:01] DEBUG[22208] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x7f1d94041498 [Sep 3 16:59:01] DEBUG[22208] res_pjsip_session.c: The current transaction state is Proceeding [Sep 3 16:59:01] DEBUG[22208] res_pjsip_session.c: The transaction state change event is RX_MSG [Sep 3 16:59:01] DEBUG[22208] res_pjsip_session.c: The current inv state is CALLING [Sep 3 16:59:01] DEBUG[22208] res_pjsip_session.c: Received response [Sep 3 16:59:01] DEBUG[22208] res_pjsip_session.c: Response is 100 Trying [Sep 3 16:59:01] DEBUG[20309] pjsip: tsx0x267bd38 Retransmit timer event [Sep 3 16:59:01] DEBUG[20309] pjsip: tsx0x267bd38 .Retransmiting Response msg 486/INVITE/cseq=1 (tdta0x7f1d8410ff50), count=2, restart?=1 [Sep 3 16:59:01] DEBUG[20309] netsock2.c: Splitting '0.0.0.0:5060' into... [Sep 3 16:59:01] DEBUG[20309] netsock2.c: ...host '0.0.0.0' and port '5060'. [Sep 3 16:59:01] DEBUG[20309] netsock2.c: Splitting '62.210.250.141:5080' into... [Sep 3 16:59:01] DEBUG[20309] netsock2.c: ...host '62.210.250.141' and port '5080'. [Sep 3 16:59:01] VERBOSE[20309] res_pjsip_logger.c: <--- Transmitting SIP response (548 bytes) to UDP:62.210.250.141:5080 ---> SIP/2.0 486 Busy Here Via: SIP/2.0/UDP 62.210.250.141:5080;rport=5080;received=62.210.250.141;branch=z9hG4bK-9cd9bfcce8a0da0e757258cdee193cb1 Call-ID: 9cd9bfcce8a0da0e757258cdee193cb1 From: "10" ;tag=91008de4 To: "801141445209952" ;tag=0c75e388-895b-4263-b6b1-f66bbf0b4c9e CSeq: 1 INVITE Server: Asterisk PBX GIT-13-2733638M Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, MESSAGE, REFER Reason: Q.850;cause=17 Content-Length: 0 [Sep 3 16:59:01] VERBOSE[24556][C-0000004d] app_dial.c: Nobody picked up in 6000 ms [Sep 3 16:59:01] DEBUG[24556][C-0000004d] channel.c: Hanging up channel 'PJSIP/100-000000e1' [Sep 3 16:59:01] DEBUG[24556][C-0000004d] chan_pjsip.c: AST hangup cause 0 (no match found in PJSIP) [Sep 3 16:59:01] DEBUG[24556][C-0000004d] app_dial.c: Exiting with DIALSTATUS=NOANSWER. [Sep 3 16:59:01] DEBUG[24556][C-0000004d] pbx.c: Launching 'Hangup' [Sep 3 16:59:01] VERBOSE[24556][C-0000004d] pbx.c: Executing [+41445209952@from-anonymous:2] Hangup("PJSIP/anonymous-000000e0", "17") in new stack [Sep 3 16:59:01] DEBUG[24556][C-0000004d] channel.c: Soft-Hanging (0x20) up channel 'PJSIP/anonymous-000000e0' [Sep 3 16:59:01] DEBUG[24556][C-0000004d] pbx.c: Spawn extension (from-anonymous,+41445209952,2) exited non-zero on 'PJSIP/anonymous-000000e0' [Sep 3 16:59:01] VERBOSE[24556][C-0000004d] pbx.c: Spawn extension (from-anonymous, +41445209952, 2) exited non-zero on 'PJSIP/anonymous-000000e0' [Sep 3 16:59:01] DEBUG[24556][C-0000004d] channel.c: Soft-Hanging (0x10) up channel 'PJSIP/anonymous-000000e0' [Sep 3 16:59:01] DEBUG[24556][C-0000004d] channel.c: Soft-Hanging (0x80) up channel 'PJSIP/anonymous-000000e0' [Sep 3 16:59:01] DEBUG[24556][C-0000004d] pbx.c: Launching 'Dial' [Sep 3 16:59:01] VERBOSE[24556][C-0000004d] pbx.c: Executing [h@from-anonymous:1] Dial("PJSIP/anonymous-000000e0", "PJSIP/100,6") in new stack [Sep 3 16:59:01] DEBUG[20296] cdr.c: Finalized CDR for PJSIP/anonymous-000000e0 - start 1441317535.693203 answer 0.000000 end 1441317541.702928 dispo NO ANSWER [Sep 3 16:59:01] DEBUG[21424] pjsip: endpoint .Request msg CANCEL/cseq=2941 (tdta0x7f1d8469bdd0) created. [Sep 3 16:59:01] DEBUG[21424] res_pjsip_session.c: Method is CANCEL [Sep 3 16:59:01] DEBUG[21424] pjsip: inv0x2716f98 .Sending Request msg CANCEL/cseq=2941 (tdta0x7f1d8469bdd0) [Sep 3 16:59:01] DEBUG[21424] pjsip: dlg0x2716f98 ..Sending Request msg CANCEL/cseq=2941 (tdta0x7f1d8469bdd0) [Sep 3 16:59:01] DEBUG[21424] pjsip: tsx0x2708768 ...Transaction created for Request msg CANCEL/cseq=2941 (tdta0x7f1d8469bdd0) [Sep 3 16:59:01] DEBUG[21424] pjsip: tsx0x2708768 ..Sending Request msg CANCEL/cseq=2941 (tdta0x7f1d8469bdd0) in state Null [Sep 3 16:59:01] DEBUG[21424] pjsip: endpoint ...Request msg CANCEL/cseq=2941 (tdta0x7f1d8469bdd0): skipping target resolution because address is already set [Sep 3 16:59:01] DEBUG[21424] netsock2.c: Splitting '0.0.0.0:5060' into... [Sep 3 16:59:01] DEBUG[21424] netsock2.c: ...host '0.0.0.0' and port '5060'. [Sep 3 16:59:01] DEBUG[21424] netsock2.c: Splitting '216.207.245.55:5062' into... [Sep 3 16:59:01] DEBUG[21424] netsock2.c: ...host '216.207.245.55' and port '5062'. [Sep 3 16:59:01] VERBOSE[21424] res_pjsip_logger.c: <--- Transmitting SIP request (419 bytes) to UDP:216.207.245.55:5062 ---> CANCEL sip:100@216.207.245.55:5062 SIP/2.0 Via: SIP/2.0/UDP 104.236.91.141:5060;rport;branch=z9hG4bKPj585e4c7c-d3c8-4876-9abb-f19ffbd81f1c From: "10" ;tag=62a332e0-b945-4c97-bd84-afce4b1eca09 To: Call-ID: 2aa8055e-0c6a-4d58-b3f5-dfb7c9572157 CSeq: 2941 CANCEL Reason: Q.850;cause=0 Max-Forwards: 70 User-Agent: Asterisk PBX GIT-13-2733638M Content-Length: 0 [Sep 3 16:59:01] DEBUG[21424] pjsip: tsx0x2708768 ...State changed from Null to Calling, event=TX_MSG [Sep 3 16:59:01] DEBUG[21424] pjsip: dlg0x2716f98 ....Transaction tsx0x2708768 state changed to Calling [Sep 3 16:59:01] DEBUG[21424] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Sep 3 16:59:01] DEBUG[21424] res_pjsip_session.c: The state change pertains to the endpoint '100(PJSIP/100-000000e1)' [Sep 3 16:59:01] DEBUG[21424] res_pjsip_session.c: The inv session still has an invite_tsx (0x26579f8) [Sep 3 16:59:01] DEBUG[21424] res_pjsip_session.c: The UAC CANCEL transaction involved in this state change is 0x2708768 [Sep 3 16:59:01] DEBUG[21424] res_pjsip_session.c: The current transaction state is Calling [Sep 3 16:59:01] DEBUG[21424] res_pjsip_session.c: The transaction state change event is TX_MSG [Sep 3 16:59:01] DEBUG[21424] res_pjsip_session.c: The current inv state is EARLY [Sep 3 16:59:01] DEBUG[21424] res_pjsip_session.c: Sending request [Sep 3 16:59:01] DEBUG[21424] res_pjsip_session.c: Method is CANCEL [Sep 3 16:59:01] DEBUG[21424] config.c: extract double from [3.0] in [-inf, inf] gives [3.000000](0) [Sep 3 16:59:01] DEBUG[21424] config.c: extract int from [15] in [0, 86400] gives [15](0) [Sep 3 16:59:01] DEBUG[21424] config.c: extract double from [3.000000] in [-inf, inf] gives [3.000000](0) [Sep 3 16:59:01] DEBUG[21424] pjsip: dlg0x267a578 UAC dialog created [Sep 3 16:59:01] DEBUG[21424] pjsip: dlg0x267a578 Module Outbound INVITE Auth added as dialog usage, data=(nil) [Sep 3 16:59:01] DEBUG[21424] pjsip: dlg0x267a578 Module mod-invite added as dialog usage, data=0x7f1d7c04f7a8 [Sep 3 16:59:01] DEBUG[21424] pjsip: dlg0x267a578 .Session count inc to 2 by mod-invite [Sep 3 16:59:01] DEBUG[21424] pjsip: dlg0x267a578 Module mod-100rel added as dialog usage, data=0x7f1d7c04f968 [Sep 3 16:59:01] DEBUG[21424] pjsip: dlg0x267a578 100rel module attached [Sep 3 16:59:01] DEBUG[21424] pjsip: inv0x267a578 UAC invite session created for dialog dlg0x267a578 [Sep 3 16:59:01] DEBUG[21424] pjsip: dlg0x267a578 .Session count inc to 2 by Session Module [Sep 3 16:59:01] DEBUG[21424] pjsip: dlg0x267a578 Module Session Module added as dialog usage, data=(nil) [Sep 3 16:59:01] DEBUG[20294] devicestate.c: No provider found, checking channel drivers for PJSIP - 100 [Sep 3 16:59:01] DEBUG[20294] devicestate.c: Changing state for PJSIP/100 - state 6 (Ringing) [Sep 3 16:59:01] DEBUG[20296] cdr.c: Finalized CDR for PJSIP/100-000000e1 - start 1441317535.697002 answer 0.000000 end 1441317541.706089 dispo FAILED [Sep 3 16:59:01] DEBUG[20296] cdr.c: CDR for PJSIP/100-000000e1 is dialed and has no Party B; discarding