[Aug 26 13:35:11] DEBUG[14644] pjsip: dlg0x7f6c5c054 ..Sending Response msg 486/INVITE/cseq=1 (tdta0x7f6c58007ed0) [Aug 26 13:35:11] DEBUG[14644] pjsip: tsx0x7f6c44014 ..Sending Response msg 486/INVITE/cseq=1 (tdta0x7f6c58007ed0) in state Proceeding [Aug 26 13:35:11] DEBUG[14644] netsock2.c: Splitting '0.0.0.0:5060' into... [Aug 26 13:35:11] DEBUG[14644] netsock2.c: ...host '0.0.0.0' and port '5060'. [Aug 26 13:35:11] DEBUG[14644] netsock2.c: Splitting '46.165.249.3:5076' into... [Aug 26 13:35:11] DEBUG[14644] netsock2.c: ...host '46.165.249.3' and port '5076'. [Aug 26 13:35:11] VERBOSE[14644] res_pjsip_logger.c: <--- Transmitting SIP response (546 bytes) to UDP:46.165.249.3:5076 ---> SIP/2.0 486 Busy Here Via: SIP/2.0/UDP 46.165.249.3:5076;rport=5076;received=46.165.249.3;branch=z9hG4bK-d2fa58bd6654176b0ab9cc64c04606cb Call-ID: d2fa58bd6654176b0ab9cc64c04606cb From: "11004" ;tag=d27d69c0 To: "+970595706746" ;tag=311e6beb-8aa0-416c-b7ae-45e654988a0e CSeq: 1 INVITE Server: Asterisk PBX GIT-13-d238cf3M Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, MESSAGE, REFER Reason: Q.850;cause=17 Content-Length: 0 [Aug 26 13:35:11] DEBUG[14644] pjsip: tsx0x7f6c44014 ...State changed from Proceeding to Completed, event=TX_MSG [Aug 26 13:35:11] DEBUG[14644] pjsip: dlg0x7f6c5c054 ....Transaction tsx0x7f6c44014ac8 state changed to Completed [Aug 26 13:35:11] DEBUG[14644] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Aug 26 13:35:11] DEBUG[14644] res_pjsip_session.c: The state change pertains to the endpoint 'anonymous(PJSIP/anonymous-00000018)' [Aug 26 13:35:11] DEBUG[14644] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f6c44014ac8) [Aug 26 13:35:11] DEBUG[14644] res_pjsip_session.c: There is no transaction involved in this state change [Aug 26 13:35:11] DEBUG[14644] res_pjsip_session.c: The current inv state is DISCONNCTD [Aug 26 13:35:11] DEBUG[14644] res_pjsip_session.c: Source of transaction state change is TX_MSG [Aug 26 13:35:11] DEBUG[14644] res_pjsip_session.c: Sending response [Aug 26 13:35:11] DEBUG[14644] res_pjsip_session.c: Method is INVITE, Response is 486 Busy Here [Aug 26 13:35:11] DEBUG[14644] pjsip: dlg0x7f6c5c054 ......Session count dec to 3 by mod-invite [Aug 26 13:35:11] DEBUG[14644] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Aug 26 13:35:11] DEBUG[14644] res_pjsip_session.c: The state change pertains to the endpoint 'anonymous(PJSIP/anonymous-00000018)' [Aug 26 13:35:11] DEBUG[14644] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f6c44014ac8) [Aug 26 13:35:11] DEBUG[14644] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7f6c44014ac8 [Aug 26 13:35:11] DEBUG[14644] res_pjsip_session.c: The current transaction state is Completed [Aug 26 13:35:11] DEBUG[14644] res_pjsip_session.c: The transaction state change event is TX_MSG [Aug 26 13:35:11] DEBUG[14644] res_pjsip_session.c: The current inv state is DISCONNCTD [Aug 26 13:35:11] DEBUG[14644] res_pjsip_session.c: Sending response [Aug 26 13:35:11] DEBUG[14644] res_pjsip_session.c: Method is INVITE, Response is 486 Busy Here [Aug 26 13:35:11] DEBUG[12743] devicestate.c: No provider found, checking channel drivers for PJSIP - 100 [Aug 26 13:35:11] DEBUG[12743] devicestate.c: Changing state for PJSIP/100 - state 1 (Not in use) [Aug 26 13:35:11] DEBUG[12743] devicestate.c: No provider found, checking channel drivers for PJSIP - anonymous [Aug 26 13:35:11] DEBUG[12743] devicestate.c: Changing state for PJSIP/anonymous - state 5 (Unavailable) [Aug 26 13:35:11] DEBUG[12839] app_queue.c: Device 'PJSIP/anonymous' changed to state '5' (Unavailable) but we don't care because they're not a member of any queue. [Aug 26 13:35:11] DEBUG[12745] cdr.c: Finalized CDR for PJSIP/anonymous-00000018 - start 1440610511.293909 answer 0.000000 end 1440610511.302662 dispo NO ANSWER [Aug 26 13:35:11] DEBUG[12745] cdr.c: Finalized CDR for PJSIP/100-0000001a - start 1440610511.302544 answer 0.000000 end 1440610511.302704 dispo FAILED [Aug 26 13:35:11] DEBUG[12745] cdr.c: CDR for PJSIP/100-0000001a is dialed and has no Party B; discarding [Aug 26 13:35:11] DEBUG[12745] 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 ('"11004" <11004>','11004','+970595706746','from-anonymous','PJSIP/anonymous-00000018','PJSIP/100-00000019','Dial','PJSIP/100,6','2015-08-26 13:35:05','2015-08-26 13:35:11','6','0','NO ANSWER','DOCUMENTATION','1440610505.40') [Aug 26 13:35:11] DEBUG[12745] 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 ('"11004" <11004>','11004','+970595706746','from-anonymous','PJSIP/anonymous-00000018','PJSIP/100-0000001a','Hangup','17','2015-08-26 13:35:11','2015-08-26 13:35:11','0','0','NO ANSWER','DOCUMENTATION','1440610505.40') [Aug 26 13:35:11] DEBUG[12758] pjsip: sip_endpoint.c Processing incoming message: Response msg 200/CANCEL/cseq=8608 (rdata0x7f6c58004618) [Aug 26 13:35:11] VERBOSE[12758] res_pjsip_logger.c: <--- Received SIP response (366 bytes) from UDP:216.207.245.1:5062 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 104.236.91.141:5060;rport;branch=z9hG4bKPje55a477b-1365-431c-8483-4aa1f5d86138 From: "11004" ;tag=cf4a2475-b3d1-49a6-8cb7-535b2e600653 To: ;tag=194377510 Call-ID: cb3a36eb-42da-4225-a369-72adafa0a4d8 CSeq: 8608 CANCEL User-Agent: Yealink SIP-T28P 2.61.0.80 Content-Length: 0 [Aug 26 13:35:11] DEBUG[12758] netsock2.c: Splitting '216.207.245.1:5062' into... [Aug 26 13:35:11] DEBUG[12758] netsock2.c: ...host '216.207.245.1' and port '5062'. [Aug 26 13:35:11] DEBUG[12758] netsock2.c: Splitting '0.0.0.0:5060' into... [Aug 26 13:35:11] DEBUG[12758] netsock2.c: ...host '0.0.0.0' and port '5060'. [Aug 26 13:35:11] DEBUG[14644] pjsip: sip_endpoint.c Distributing rdata to modules: Response msg 200/CANCEL/cseq=8608 (rdata0x7f6c5800ce58) [Aug 26 13:35:11] DEBUG[14644] pjsip: tsx0x7f6c5c02e .Incoming Response msg 200/CANCEL/cseq=8608 (rdata0x7f6c5800ce58) in state Calling [Aug 26 13:35:11] DEBUG[14644] pjsip: tsx0x7f6c5c02e ..State changed from Calling to Completed, event=RX_MSG [Aug 26 13:35:11] DEBUG[14644] pjsip: dlg0x7f6c5c04a ...Received Response msg 200/CANCEL/cseq=8608 (rdata0x7f6c5800ce58) [Aug 26 13:35:11] DEBUG[14644] pjsip: dlg0x7f6c5c04a ...Transaction tsx0x7f6c5c02e118 state changed to Completed [Aug 26 13:35:11] DEBUG[12758] pjsip: sip_endpoint.c Processing incoming message: Response msg 487/INVITE/cseq=8608 (rdata0x7f6c58004618) [Aug 26 13:35:11] VERBOSE[12758] res_pjsip_logger.c: <--- Received SIP response (382 bytes) from UDP:216.207.245.1:5062 ---> SIP/2.0 487 Request Terminated Via: SIP/2.0/UDP 104.236.91.141:5060;rport;branch=z9hG4bKPje55a477b-1365-431c-8483-4aa1f5d86138 From: "11004" ;tag=cf4a2475-b3d1-49a6-8cb7-535b2e600653 To: ;tag=194377510 Call-ID: cb3a36eb-42da-4225-a369-72adafa0a4d8 CSeq: 8608 INVITE User-Agent: Yealink SIP-T28P 2.61.0.80 Content-Length: 0 [Aug 26 13:35:11] DEBUG[12758] netsock2.c: Splitting '216.207.245.1:5062' into... [Aug 26 13:35:11] DEBUG[12758] netsock2.c: ...host '216.207.245.1' and port '5062'. [Aug 26 13:35:11] DEBUG[12758] netsock2.c: Splitting '0.0.0.0:5060' into... [Aug 26 13:35:11] DEBUG[12758] netsock2.c: ...host '0.0.0.0' and port '5060'. [Aug 26 13:35:11] DEBUG[13834] pjsip: sip_endpoint.c Distributing rdata to modules: Response msg 487/INVITE/cseq=8608 (rdata0x7f6c5800ce58) [Aug 26 13:35:11] DEBUG[13834] pjsip: tsx0x7f6c4402f .Incoming Response msg 487/INVITE/cseq=8608 (rdata0x7f6c5800ce58) in state Proceeding [Aug 26 13:35:11] DEBUG[13834] pjsip: endpoint ..Request msg ACK/cseq=8608 (tdta0x7f6c58009ef0) created. [Aug 26 13:35:11] DEBUG[13834] netsock2.c: Splitting '0.0.0.0:5060' into... [Aug 26 13:35:11] DEBUG[13834] netsock2.c: ...host '0.0.0.0' and port '5060'. [Aug 26 13:35:11] DEBUG[13834] netsock2.c: Splitting '216.207.245.1:5062' into... [Aug 26 13:35:11] DEBUG[13834] netsock2.c: ...host '216.207.245.1' and port '5062'. [Aug 26 13:35:11] VERBOSE[13834] res_pjsip_logger.c: <--- Transmitting SIP request (408 bytes) to UDP:216.207.245.1:5062 ---> ACK sip:100@216.207.245.1:5062 SIP/2.0 Via: SIP/2.0/UDP 104.236.91.141:5060;rport;branch=z9hG4bKPje55a477b-1365-431c-8483-4aa1f5d86138 From: "11004" ;tag=cf4a2475-b3d1-49a6-8cb7-535b2e600653 To: ;tag=194377510 Call-ID: cb3a36eb-42da-4225-a369-72adafa0a4d8 CSeq: 8608 ACK Max-Forwards: 70 User-Agent: Asterisk PBX GIT-13-d238cf3M Content-Length: 0 [Aug 26 13:35:11] DEBUG[13834] pjsip: tsx0x7f6c4402f ..State changed from Proceeding to Completed, event=RX_MSG [Aug 26 13:35:11] DEBUG[13834] pjsip: dlg0x7f6c5c04a ...Received Response msg 487/INVITE/cseq=8608 (rdata0x7f6c5800ce58) [Aug 26 13:35:11] DEBUG[13834] pjsip: dlg0x7f6c5c04a ...Transaction tsx0x7f6c4402f2f8 state changed to Completed [Aug 26 13:35:11] DEBUG[13834] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Aug 26 13:35:11] DEBUG[13834] res_pjsip_session.c: The state change pertains to the endpoint '100()' [Aug 26 13:35:11] DEBUG[13834] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f6c4402f2f8) [Aug 26 13:35:11] DEBUG[13834] res_pjsip_session.c: There is no transaction involved in this state change [Aug 26 13:35:11] DEBUG[13834] res_pjsip_session.c: The current inv state is DISCONNCTD [Aug 26 13:35:11] DEBUG[13834] res_pjsip_session.c: Source of transaction state change is RX_MSG [Aug 26 13:35:11] DEBUG[13834] res_pjsip_session.c: Received response [Aug 26 13:35:11] DEBUG[13834] res_pjsip_session.c: Response is 487 Request Terminated [Aug 26 13:35:11] DEBUG[13834] pjsip: dlg0x7f6c5c04a .....Session count dec to 2 by mod-invite [Aug 26 13:35:11] DEBUG[13834] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Aug 26 13:35:11] DEBUG[13834] res_pjsip_session.c: The state change pertains to the endpoint '100()' [Aug 26 13:35:11] DEBUG[13834] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f6c4402f2f8) [Aug 26 13:35:11] DEBUG[13834] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x7f6c4402f2f8 [Aug 26 13:35:11] DEBUG[13834] res_pjsip_session.c: The current transaction state is Completed [Aug 26 13:35:11] DEBUG[13834] res_pjsip_session.c: The transaction state change event is RX_MSG [Aug 26 13:35:11] DEBUG[13834] res_pjsip_session.c: The current inv state is DISCONNCTD [Aug 26 13:35:11] DEBUG[13834] res_pjsip_session.c: Received response [Aug 26 13:35:11] DEBUG[13834] res_pjsip_session.c: Response is 487 Request Terminated [Aug 26 13:35:11] DEBUG[13834] pjsip: tdta0x7f6c5800 ..Destroying txdata Request msg INVITE/cseq=8608 (tdta0x7f6c58008ee0) [Aug 26 13:35:11] DEBUG[12758] pjsip: sip_endpoint.c Processing incoming message: Response msg 100/INVITE/cseq=28049 (rdata0x7f6c58004618) [Aug 26 13:35:11] VERBOSE[12758] res_pjsip_logger.c: <--- Received SIP response (357 bytes) from UDP:216.207.245.1:5062 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 104.236.91.141:5060;rport;branch=z9hG4bKPja1a21f49-c19c-4cd0-ad17-1f66204092be From: "11004" ;tag=b9c08176-f99b-49bf-86f9-71e3359d10d0 To: Call-ID: 2c89ac7e-24f5-4a2e-b318-df5fccf83f76 CSeq: 28049 INVITE User-Agent: Yealink SIP-T28P 2.61.0.80 Content-Length: 0 [Aug 26 13:35:11] DEBUG[12758] netsock2.c: Splitting '216.207.245.1:5062' into... [Aug 26 13:35:11] DEBUG[12758] netsock2.c: ...host '216.207.245.1' and port '5062'. [Aug 26 13:35:11] DEBUG[12758] netsock2.c: Splitting '0.0.0.0:5060' into... [Aug 26 13:35:11] DEBUG[12758] netsock2.c: ...host '0.0.0.0' and port '5060'. [Aug 26 13:35:11] DEBUG[14644] pjsip: sip_endpoint.c Distributing rdata to modules: Response msg 100/INVITE/cseq=28049 (rdata0x7f6c5800ce58) [Aug 26 13:35:11] DEBUG[14644] pjsip: tsx0x7f6c4402c .Incoming Response msg 100/INVITE/cseq=28049 (rdata0x7f6c5800ce58) in state Calling [Aug 26 13:35:11] DEBUG[14644] pjsip: tsx0x7f6c4402c ..State changed from Calling to Proceeding, event=RX_MSG [Aug 26 13:35:11] DEBUG[14644] pjsip: dlg0x7f6c4400c ...Received Response msg 100/INVITE/cseq=28049 (rdata0x7f6c5800ce58) [Aug 26 13:35:11] DEBUG[14644] pjsip: dlg0x7f6c4400c ...Transaction tsx0x7f6c4402cee8 state changed to Proceeding [Aug 26 13:35:11] DEBUG[14644] pjsip: endpoint .....Request msg CANCEL/cseq=28049 (tdta0x7f6c58008ee0) created. [Aug 26 13:35:11] DEBUG[14644] pjsip: inv0x7f6c4400c .....Sending Request msg CANCEL/cseq=28049 (tdta0x7f6c58008ee0) [Aug 26 13:35:11] DEBUG[14644] pjsip: dlg0x7f6c4400c ......Sending Request msg CANCEL/cseq=28049 (tdta0x7f6c58008ee0) [Aug 26 13:35:11] DEBUG[14644] pjsip: tsx0x7f6c4401c .......Transaction created for Request msg CANCEL/cseq=28049 (tdta0x7f6c58008ee0) [Aug 26 13:35:11] DEBUG[14644] pjsip: tsx0x7f6c4401c ......Sending Request msg CANCEL/cseq=28049 (tdta0x7f6c58008ee0) in state Null [Aug 26 13:35:11] DEBUG[14644] pjsip: endpoint .......Request msg CANCEL/cseq=28049 (tdta0x7f6c58008ee0): skipping target resolution because address is already set [Aug 26 13:35:11] DEBUG[14644] netsock2.c: Splitting '0.0.0.0:5060' into... [Aug 26 13:35:11] DEBUG[14644] netsock2.c: ...host '0.0.0.0' and port '5060'. [Aug 26 13:35:11] DEBUG[14644] netsock2.c: Splitting '216.207.245.1:5062' into... [Aug 26 13:35:11] DEBUG[14644] netsock2.c: ...host '216.207.245.1' and port '5062'. [Aug 26 13:35:11] VERBOSE[14644] res_pjsip_logger.c: <--- Transmitting SIP request (401 bytes) to UDP:216.207.245.1:5062 ---> CANCEL sip:100@216.207.245.1:5062 SIP/2.0 Via: SIP/2.0/UDP 104.236.91.141:5060;rport;branch=z9hG4bKPja1a21f49-c19c-4cd0-ad17-1f66204092be From: "11004" ;tag=b9c08176-f99b-49bf-86f9-71e3359d10d0 To: Call-ID: 2c89ac7e-24f5-4a2e-b318-df5fccf83f76 CSeq: 28049 CANCEL Max-Forwards: 70 User-Agent: Asterisk PBX GIT-13-d238cf3M Content-Length: 0 [Aug 26 13:35:11] DEBUG[14644] pjsip: tsx0x7f6c4401c .......State changed from Null to Calling, event=TX_MSG [Aug 26 13:35:11] DEBUG[14644] pjsip: dlg0x7f6c4400c ........Transaction tsx0x7f6c4401cee8 state changed to Calling [Aug 26 13:35:11] DEBUG[14644] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Aug 26 13:35:11] DEBUG[14644] res_pjsip_session.c: The state change pertains to the endpoint '100()' [Aug 26 13:35:11] DEBUG[14644] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f6c4402cee8) [Aug 26 13:35:11] DEBUG[14644] res_pjsip_session.c: The UAC CANCEL transaction involved in this state change is 0x7f6c4401cee8 [Aug 26 13:35:11] DEBUG[14644] res_pjsip_session.c: The current transaction state is Calling [Aug 26 13:35:11] DEBUG[14644] res_pjsip_session.c: The transaction state change event is TX_MSG [Aug 26 13:35:11] DEBUG[14644] res_pjsip_session.c: The current inv state is CALLING [Aug 26 13:35:11] DEBUG[14644] res_pjsip_session.c: Sending request [Aug 26 13:35:11] DEBUG[14644] res_pjsip_session.c: Method is CANCEL [Aug 26 13:35:11] DEBUG[14644] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Aug 26 13:35:11] DEBUG[14644] res_pjsip_session.c: The state change pertains to the endpoint '100()' [Aug 26 13:35:11] DEBUG[14644] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f6c4402cee8) [Aug 26 13:35:11] DEBUG[14644] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x7f6c4402cee8 [Aug 26 13:35:11] DEBUG[14644] res_pjsip_session.c: The current transaction state is Proceeding [Aug 26 13:35:11] DEBUG[14644] res_pjsip_session.c: The transaction state change event is RX_MSG [Aug 26 13:35:11] DEBUG[14644] res_pjsip_session.c: The current inv state is CALLING [Aug 26 13:35:11] DEBUG[14644] res_pjsip_session.c: Received response [Aug 26 13:35:11] DEBUG[14644] res_pjsip_session.c: Response is 100 Trying [Aug 26 13:35:11] DEBUG[12758] pjsip: tsx0x7f6c44014 Retransmit timer event [Aug 26 13:35:11] DEBUG[12758] pjsip: tsx0x7f6c44014 .Retransmiting Response msg 486/INVITE/cseq=1 (tdta0x7f6c58007ed0), count=0, restart?=1 [Aug 26 13:35:11] DEBUG[12758] netsock2.c: Splitting '0.0.0.0:5060' into... [Aug 26 13:35:11] DEBUG[12758] netsock2.c: ...host '0.0.0.0' and port '5060'. [Aug 26 13:35:11] DEBUG[12758] netsock2.c: Splitting '46.165.249.3:5076' into... [Aug 26 13:35:11] DEBUG[12758] netsock2.c: ...host '46.165.249.3' and port '5076'. [Aug 26 13:35:11] VERBOSE[12758] res_pjsip_logger.c: <--- Transmitting SIP response (546 bytes) to UDP:46.165.249.3:5076 ---> SIP/2.0 486 Busy Here Via: SIP/2.0/UDP 46.165.249.3:5076;rport=5076;received=46.165.249.3;branch=z9hG4bK-d2fa58bd6654176b0ab9cc64c04606cb Call-ID: d2fa58bd6654176b0ab9cc64c04606cb From: "11004" ;tag=d27d69c0 To: "+970595706746" ;tag=311e6beb-8aa0-416c-b7ae-45e654988a0e CSeq: 1 INVITE Server: Asterisk PBX GIT-13-d238cf3M Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, MESSAGE, REFER Reason: Q.850;cause=17 Content-Length: 0 [Aug 26 13:35:12] DEBUG[12758] pjsip: tsx0x7f6c4401c Retransmit timer event [Aug 26 13:35:12] DEBUG[12758] pjsip: tsx0x7f6c4401c .Retransmiting Request msg CANCEL/cseq=28049 (tdta0x7f6c58008ee0), count=0, restart?=1 [Aug 26 13:35:12] DEBUG[12758] netsock2.c: Splitting '0.0.0.0:5060' into... [Aug 26 13:35:12] DEBUG[12758] netsock2.c: ...host '0.0.0.0' and port '5060'. [Aug 26 13:35:12] DEBUG[12758] netsock2.c: Splitting '216.207.245.1:5062' into... [Aug 26 13:35:12] DEBUG[12758] netsock2.c: ...host '216.207.245.1' and port '5062'. [Aug 26 13:35:12] VERBOSE[12758] res_pjsip_logger.c: <--- Transmitting SIP request (401 bytes) to UDP:216.207.245.1:5062 ---> CANCEL sip:100@216.207.245.1:5062 SIP/2.0 Via: SIP/2.0/UDP 104.236.91.141:5060;rport;branch=z9hG4bKPja1a21f49-c19c-4cd0-ad17-1f66204092be From: "11004" ;tag=b9c08176-f99b-49bf-86f9-71e3359d10d0 To: Call-ID: 2c89ac7e-24f5-4a2e-b318-df5fccf83f76 CSeq: 28049 CANCEL Max-Forwards: 70 User-Agent: Asterisk PBX GIT-13-d238cf3M Content-Length: 0 [Aug 26 13:35:12] DEBUG[12758] pjsip: sip_endpoint.c Processing incoming message: Response msg 180/INVITE/cseq=28049 (rdata0x7f6c58004618) [Aug 26 13:35:12] VERBOSE[12758] res_pjsip_logger.c: <--- Received SIP response (581 bytes) from UDP:216.207.245.1:5062 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 104.236.91.141:5060;rport;branch=z9hG4bKPja1a21f49-c19c-4cd0-ad17-1f66204092be From: "11004" ;tag=b9c08176-f99b-49bf-86f9-71e3359d10d0 To: ;tag=1163187496 Call-ID: 2c89ac7e-24f5-4a2e-b318-df5fccf83f76 CSeq: 28049 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 [Aug 26 13:35:12] DEBUG[12758] netsock2.c: Splitting '216.207.245.1:5062' into... [Aug 26 13:35:12] DEBUG[12758] netsock2.c: ...host '216.207.245.1' and port '5062'. [Aug 26 13:35:12] DEBUG[12758] netsock2.c: Splitting '0.0.0.0:5060' into... [Aug 26 13:35:12] DEBUG[12758] netsock2.c: ...host '0.0.0.0' and port '5060'. [Aug 26 13:35:12] DEBUG[13834] pjsip: sip_endpoint.c Distributing rdata to modules: Response msg 180/INVITE/cseq=28049 (rdata0x7f6c5800ce58) [Aug 26 13:35:12] DEBUG[13834] pjsip: tsx0x7f6c4402c .Incoming Response msg 180/INVITE/cseq=28049 (rdata0x7f6c5800ce58) in state Proceeding [Aug 26 13:35:12] DEBUG[13834] pjsip: tsx0x7f6c4402c ..State changed from Proceeding to Proceeding, event=RX_MSG [Aug 26 13:35:12] DEBUG[13834] pjsip: dlg0x7f6c4400c ...Received Response msg 180/INVITE/cseq=28049 (rdata0x7f6c5800ce58) [Aug 26 13:35:12] DEBUG[13834] pjsip: dlg0x7f6c4400c ....Route-set updated [Aug 26 13:35:12] DEBUG[13834] pjsip: dlg0x7f6c4400c ...Transaction tsx0x7f6c4402cee8 state changed to Proceeding [Aug 26 13:35:12] DEBUG[13834] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Aug 26 13:35:12] DEBUG[13834] res_pjsip_session.c: The state change pertains to the endpoint '100()' [Aug 26 13:35:12] DEBUG[13834] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f6c4402cee8) [Aug 26 13:35:12] DEBUG[13834] res_pjsip_session.c: There is no transaction involved in this state change [Aug 26 13:35:12] DEBUG[13834] res_pjsip_session.c: The current inv state is EARLY [Aug 26 13:35:12] DEBUG[13834] res_pjsip_session.c: Source of transaction state change is RX_MSG [Aug 26 13:35:12] DEBUG[13834] res_pjsip_session.c: Received response [Aug 26 13:35:12] DEBUG[13834] res_pjsip_session.c: Response is 180 Ringing [Aug 26 13:35:12] DEBUG[13834] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Aug 26 13:35:12] DEBUG[13834] res_pjsip_session.c: The state change pertains to the endpoint '100()' [Aug 26 13:35:12] DEBUG[13834] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f6c4402cee8) [Aug 26 13:35:12] DEBUG[13834] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x7f6c4402cee8 [Aug 26 13:35:12] DEBUG[13834] res_pjsip_session.c: The current transaction state is Proceeding [Aug 26 13:35:12] DEBUG[13834] res_pjsip_session.c: The transaction state change event is RX_MSG [Aug 26 13:35:12] DEBUG[13834] res_pjsip_session.c: The current inv state is EARLY [Aug 26 13:35:12] DEBUG[13834] res_pjsip_session.c: Received response [Aug 26 13:35:12] DEBUG[13834] res_pjsip_session.c: Response is 180 Ringing [Aug 26 13:35:12] DEBUG[12758] pjsip: sip_endpoint.c Processing incoming message: Response msg 200/CANCEL/cseq=28049 (rdata0x7f6c58004618) [Aug 26 13:35:12] VERBOSE[12758] res_pjsip_logger.c: <--- Received SIP response (368 bytes) from UDP:216.207.245.1:5062 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 104.236.91.141:5060;rport;branch=z9hG4bKPja1a21f49-c19c-4cd0-ad17-1f66204092be From: "11004" ;tag=b9c08176-f99b-49bf-86f9-71e3359d10d0 To: ;tag=1163187496 Call-ID: 2c89ac7e-24f5-4a2e-b318-df5fccf83f76 CSeq: 28049 CANCEL User-Agent: Yealink SIP-T28P 2.61.0.80 Content-Length: 0 [Aug 26 13:35:12] DEBUG[12758] netsock2.c: Splitting '216.207.245.1:5062' into... [Aug 26 13:35:12] DEBUG[12758] netsock2.c: ...host '216.207.245.1' and port '5062'. [Aug 26 13:35:12] DEBUG[12758] netsock2.c: Splitting '0.0.0.0:5060' into... [Aug 26 13:35:12] DEBUG[12758] netsock2.c: ...host '0.0.0.0' and port '5060'. [Aug 26 13:35:12] DEBUG[14644] pjsip: sip_endpoint.c Distributing rdata to modules: Response msg 200/CANCEL/cseq=28049 (rdata0x7f6c5800ce58) [Aug 26 13:35:12] DEBUG[14644] pjsip: tsx0x7f6c4401c .Incoming Response msg 200/CANCEL/cseq=28049 (rdata0x7f6c5800ce58) in state Calling [Aug 26 13:35:12] DEBUG[14644] pjsip: tsx0x7f6c4401c ..State changed from Calling to Completed, event=RX_MSG [Aug 26 13:35:12] DEBUG[14644] pjsip: dlg0x7f6c4400c ...Received Response msg 200/CANCEL/cseq=28049 (rdata0x7f6c5800ce58) [Aug 26 13:35:12] DEBUG[14644] pjsip: dlg0x7f6c4400c ...Transaction tsx0x7f6c4401cee8 state changed to Completed [Aug 26 13:35:12] DEBUG[12758] pjsip: sip_endpoint.c Processing incoming message: Response msg 487/INVITE/cseq=28049 (rdata0x7f6c58004618) [Aug 26 13:35:12] VERBOSE[12758] res_pjsip_logger.c: <--- Received SIP response (384 bytes) from UDP:216.207.245.1:5062 ---> SIP/2.0 487 Request Terminated Via: SIP/2.0/UDP 104.236.91.141:5060;rport;branch=z9hG4bKPja1a21f49-c19c-4cd0-ad17-1f66204092be From: "11004" ;tag=b9c08176-f99b-49bf-86f9-71e3359d10d0 To: ;tag=1163187496 Call-ID: 2c89ac7e-24f5-4a2e-b318-df5fccf83f76 CSeq: 28049 INVITE User-Agent: Yealink SIP-T28P 2.61.0.80 Content-Length: 0 [Aug 26 13:35:12] DEBUG[12758] netsock2.c: Splitting '216.207.245.1:5062' into... [Aug 26 13:35:12] DEBUG[12758] netsock2.c: ...host '216.207.245.1' and port '5062'. [Aug 26 13:35:12] DEBUG[12758] netsock2.c: Splitting '0.0.0.0:5060' into... [Aug 26 13:35:12] DEBUG[12758] netsock2.c: ...host '0.0.0.0' and port '5060'. [Aug 26 13:35:12] DEBUG[13834] pjsip: sip_endpoint.c Distributing rdata to modules: Response msg 487/INVITE/cseq=28049 (rdata0x7f6c5800ce58) [Aug 26 13:35:12] DEBUG[13834] pjsip: tsx0x7f6c4402c .Incoming Response msg 487/INVITE/cseq=28049 (rdata0x7f6c5800ce58) in state Proceeding [Aug 26 13:35:12] DEBUG[13834] pjsip: endpoint ..Request msg ACK/cseq=28049 (tdta0x7f6c5c055570) created. [Aug 26 13:35:12] DEBUG[13834] netsock2.c: Splitting '0.0.0.0:5060' into... [Aug 26 13:35:12] DEBUG[13834] netsock2.c: ...host '0.0.0.0' and port '5060'. [Aug 26 13:35:12] DEBUG[13834] netsock2.c: Splitting '216.207.245.1:5062' into... [Aug 26 13:35:12] DEBUG[13834] netsock2.c: ...host '216.207.245.1' and port '5062'. [Aug 26 13:35:12] VERBOSE[13834] res_pjsip_logger.c: <--- Transmitting SIP request (410 bytes) to UDP:216.207.245.1:5062 ---> ACK sip:100@216.207.245.1:5062 SIP/2.0 Via: SIP/2.0/UDP 104.236.91.141:5060;rport;branch=z9hG4bKPja1a21f49-c19c-4cd0-ad17-1f66204092be From: "11004" ;tag=b9c08176-f99b-49bf-86f9-71e3359d10d0 To: ;tag=1163187496 Call-ID: 2c89ac7e-24f5-4a2e-b318-df5fccf83f76 CSeq: 28049 ACK Max-Forwards: 70 User-Agent: Asterisk PBX GIT-13-d238cf3M Content-Length: 0 [Aug 26 13:35:12] DEBUG[13834] pjsip: tsx0x7f6c4402c ..State changed from Proceeding to Completed, event=RX_MSG [Aug 26 13:35:12] DEBUG[13834] pjsip: dlg0x7f6c4400c ...Received Response msg 487/INVITE/cseq=28049 (rdata0x7f6c5800ce58) [Aug 26 13:35:12] DEBUG[13834] pjsip: dlg0x7f6c4400c ...Transaction tsx0x7f6c4402cee8 state changed to Completed [Aug 26 13:35:12] DEBUG[13834] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Aug 26 13:35:12] DEBUG[13834] res_pjsip_session.c: The state change pertains to the endpoint '100()' [Aug 26 13:35:12] DEBUG[13834] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f6c4402cee8) [Aug 26 13:35:12] DEBUG[13834] res_pjsip_session.c: There is no transaction involved in this state change [Aug 26 13:35:12] DEBUG[13834] res_pjsip_session.c: The current inv state is DISCONNCTD [Aug 26 13:35:12] DEBUG[13834] res_pjsip_session.c: Source of transaction state change is RX_MSG [Aug 26 13:35:12] DEBUG[13834] res_pjsip_session.c: Received response [Aug 26 13:35:12] DEBUG[13834] res_pjsip_session.c: Response is 487 Request Terminated [Aug 26 13:35:12] DEBUG[13834] pjsip: dlg0x7f6c4400c .....Session count dec to 2 by mod-invite [Aug 26 13:35:12] DEBUG[13834] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Aug 26 13:35:12] DEBUG[13834] res_pjsip_session.c: The state change pertains to the endpoint '100()' [Aug 26 13:35:12] DEBUG[13834] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f6c4402cee8) [Aug 26 13:35:12] DEBUG[13834] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x7f6c4402cee8 [Aug 26 13:35:12] DEBUG[13834] res_pjsip_session.c: The current transaction state is Completed [Aug 26 13:35:12] DEBUG[13834] res_pjsip_session.c: The transaction state change event is RX_MSG [Aug 26 13:35:12] DEBUG[13834] res_pjsip_session.c: The current inv state is DISCONNCTD [Aug 26 13:35:12] DEBUG[13834] res_pjsip_session.c: Received response [Aug 26 13:35:12] DEBUG[13834] res_pjsip_session.c: Response is 487 Request Terminated [Aug 26 13:35:12] DEBUG[13834] pjsip: tdta0x7f6c5c02 ..Destroying txdata Request msg INVITE/cseq=28049 (tdta0x7f6c5c02b6d0) [Aug 26 13:35:12] DEBUG[12758] pjsip: sip_endpoint.c Processing incoming message: Response msg 200/CANCEL/cseq=28049 (rdata0x7f6c58004618) [Aug 26 13:35:12] VERBOSE[12758] res_pjsip_logger.c: <--- Received SIP response (368 bytes) from UDP:216.207.245.1:5062 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 104.236.91.141:5060;rport;branch=z9hG4bKPja1a21f49-c19c-4cd0-ad17-1f66204092be From: "11004" ;tag=b9c08176-f99b-49bf-86f9-71e3359d10d0 To: ;tag=1163187496 Call-ID: 2c89ac7e-24f5-4a2e-b318-df5fccf83f76 CSeq: 28049 CANCEL User-Agent: Yealink SIP-T28P 2.61.0.80 Content-Length: 0 [Aug 26 13:35:12] DEBUG[12758] netsock2.c: Splitting '216.207.245.1:5062' into... [Aug 26 13:35:12] DEBUG[12758] netsock2.c: ...host '216.207.245.1' and port '5062'. [Aug 26 13:35:12] DEBUG[12758] netsock2.c: Splitting '0.0.0.0:5060' into... [Aug 26 13:35:12] DEBUG[12758] netsock2.c: ...host '0.0.0.0' and port '5060'. [Aug 26 13:35:12] DEBUG[14644] pjsip: sip_endpoint.c Distributing rdata to modules: Response msg 200/CANCEL/cseq=28049 (rdata0x7f6c5800ce58) [Aug 26 13:35:12] DEBUG[14644] pjsip: tsx0x7f6c4401c .Incoming Response msg 200/CANCEL/cseq=28049 (rdata0x7f6c5800ce58) in state Completed [Aug 26 13:35:12] DEBUG[12758] pjsip: tsx0x7f6c5c03c Timeout timer event [Aug 26 13:35:12] DEBUG[12758] pjsip: tsx0x7f6c5c03c .State changed from Completed to Terminated, event=TIMER [Aug 26 13:35:12] DEBUG[12758] pjsip: tsx0x7f6c5c03c Timeout timer event [Aug 26 13:35:12] DEBUG[12758] pjsip: tsx0x7f6c5c03c .State changed from Terminated to Destroyed, event=TIMER [Aug 26 13:35:12] DEBUG[12758] pjsip: tdta0x7f6c5800 ..Destroying txdata Request msg OPTIONS/cseq=18011 (tdta0x7f6c58001e60) [Aug 26 13:35:12] DEBUG[12758] pjsip: tsx0x7f6c5c03c Transaction destroyed! [Aug 26 13:35:12] DEBUG[12758] pjsip: tsx0x7f6c44014 Retransmit timer event [Aug 26 13:35:12] DEBUG[12758] pjsip: tsx0x7f6c44014 .Retransmiting Response msg 486/INVITE/cseq=1 (tdta0x7f6c58007ed0), count=1, restart?=1 [Aug 26 13:35:12] DEBUG[12758] netsock2.c: Splitting '0.0.0.0:5060' into... [Aug 26 13:35:12] DEBUG[12758] netsock2.c: ...host '0.0.0.0' and port '5060'. [Aug 26 13:35:12] DEBUG[12758] netsock2.c: Splitting '46.165.249.3:5076' into... [Aug 26 13:35:12] DEBUG[12758] netsock2.c: ...host '46.165.249.3' and port '5076'. [Aug 26 13:35:12] VERBOSE[12758] res_pjsip_logger.c: <--- Transmitting SIP response (546 bytes) to UDP:46.165.249.3:5076 ---> SIP/2.0 486 Busy Here Via: SIP/2.0/UDP 46.165.249.3:5076;rport=5076;received=46.165.249.3;branch=z9hG4bK-d2fa58bd6654176b0ab9cc64c04606cb Call-ID: d2fa58bd6654176b0ab9cc64c04606cb From: "11004" ;tag=d27d69c0 To: "+970595706746" ;tag=311e6beb-8aa0-416c-b7ae-45e654988a0e CSeq: 1 INVITE Server: Asterisk PBX GIT-13-d238cf3M Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, MESSAGE, REFER Reason: Q.850;cause=17 Content-Length: 0 [Aug 26 13:35:14] DEBUG[12758] pjsip: tsx0x7f6c44014 Retransmit timer event [Aug 26 13:35:14] DEBUG[12758] pjsip: tsx0x7f6c44014 .Retransmiting Response msg 486/INVITE/cseq=1 (tdta0x7f6c58007ed0), count=2, restart?=1 [Aug 26 13:35:14] DEBUG[12758] netsock2.c: Splitting '0.0.0.0:5060' into... [Aug 26 13:35:14] DEBUG[12758] netsock2.c: ...host '0.0.0.0' and port '5060'. [Aug 26 13:35:14] DEBUG[12758] netsock2.c: Splitting '46.165.249.3:5076' into... [Aug 26 13:35:14] DEBUG[12758] netsock2.c: ...host '46.165.249.3' and port '5076'. [Aug 26 13:35:14] VERBOSE[12758] res_pjsip_logger.c: <--- Transmitting SIP response (546 bytes) to UDP:46.165.249.3:5076 ---> SIP/2.0 486 Busy Here Via: SIP/2.0/UDP 46.165.249.3:5076;rport=5076;received=46.165.249.3;branch=z9hG4bK-d2fa58bd6654176b0ab9cc64c04606cb Call-ID: d2fa58bd6654176b0ab9cc64c04606cb From: "11004" ;tag=d27d69c0 To: "+970595706746" ;tag=311e6beb-8aa0-416c-b7ae-45e654988a0e CSeq: 1 INVITE Server: Asterisk PBX GIT-13-d238cf3M Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, MESSAGE, REFER Reason: Q.850;cause=17 Content-Length: 0 [Aug 26 13:35:16] DEBUG[12758] pjsip: tsx0x7f6c5c02e Timeout timer event [Aug 26 13:35:16] DEBUG[12758] pjsip: tsx0x7f6c5c02e .State changed from Completed to Terminated, event=TIMER [Aug 26 13:35:16] DEBUG[12758] pjsip: dlg0x7f6c5c04a ..Transaction tsx0x7f6c5c02e118 state changed to Terminated [Aug 26 13:35:16] DEBUG[12758] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Aug 26 13:35:16] DEBUG[12758] res_pjsip_session.c: The state change pertains to the endpoint '100()' [Aug 26 13:35:16] DEBUG[12758] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f6c4402f2f8) [Aug 26 13:35:16] DEBUG[12758] res_pjsip_session.c: The UAC CANCEL transaction involved in this state change is 0x7f6c5c02e118 [Aug 26 13:35:16] DEBUG[12758] res_pjsip_session.c: The current transaction state is Terminated [Aug 26 13:35:16] DEBUG[12758] res_pjsip_session.c: The transaction state change event is TIMER [Aug 26 13:35:16] DEBUG[12758] res_pjsip_session.c: The current inv state is DISCONNCTD [Aug 26 13:35:16] DEBUG[12758] pjsip: tsx0x7f6c5c02e Timeout timer event [Aug 26 13:35:16] DEBUG[12758] pjsip: tsx0x7f6c5c02e .State changed from Terminated to Destroyed, event=TIMER [Aug 26 13:35:16] DEBUG[12758] pjsip: tdta0x7f6c5800 ..Destroying txdata Request msg CANCEL/cseq=8608 (tdta0x7f6c58006ec0) [Aug 26 13:35:16] DEBUG[12758] pjsip: tsx0x7f6c5c02e Transaction destroyed! [Aug 26 13:35:16] DEBUG[13834] res_pjsip_session.c: Destroying SIP session with endpoint 100 [Aug 26 13:35:16] DEBUG[13834] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7f6c5c015298' [Aug 26 13:35:16] DEBUG[13834] rtp_engine.c: Destroyed RTP instance '0x7f6c5c015298' [Aug 26 13:35:16] DEBUG[13834] pjsip: dlg0x7f6c5c04a .Session count dec to 0 by Session Module [Aug 26 13:35:16] DEBUG[13834] taskprocessor.c: destroying taskprocessor '2e1885ea-f677-45a5-907c-f631aa81389e' [Aug 26 13:35:17] DEBUG[12758] pjsip: tsx0x7f6c4401c Timeout timer event [Aug 26 13:35:17] DEBUG[12758] pjsip: tsx0x7f6c4401c .State changed from Completed to Terminated, event=TIMER [Aug 26 13:35:17] DEBUG[12758] pjsip: dlg0x7f6c4400c ..Transaction tsx0x7f6c4401cee8 state changed to Terminated [Aug 26 13:35:17] DEBUG[12758] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Aug 26 13:35:17] DEBUG[12758] res_pjsip_session.c: The state change pertains to the endpoint '100()' [Aug 26 13:35:17] DEBUG[12758] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f6c4402cee8) [Aug 26 13:35:17] DEBUG[12758] res_pjsip_session.c: The UAC CANCEL transaction involved in this state change is 0x7f6c4401cee8 [Aug 26 13:35:17] DEBUG[12758] res_pjsip_session.c: The current transaction state is Terminated [Aug 26 13:35:17] DEBUG[12758] res_pjsip_session.c: The transaction state change event is TIMER [Aug 26 13:35:17] DEBUG[12758] res_pjsip_session.c: The current inv state is DISCONNCTD [Aug 26 13:35:17] DEBUG[12758] pjsip: tsx0x7f6c4401c Timeout timer event [Aug 26 13:35:17] DEBUG[12758] pjsip: tsx0x7f6c4401c .State changed from Terminated to Destroyed, event=TIMER [Aug 26 13:35:17] DEBUG[12758] pjsip: tdta0x7f6c5800 ..Destroying txdata Request msg CANCEL/cseq=28049 (tdta0x7f6c58008ee0) [Aug 26 13:35:17] DEBUG[12758] pjsip: tsx0x7f6c4401c Transaction destroyed! [Aug 26 13:35:17] DEBUG[14644] res_pjsip_session.c: Destroying SIP session with endpoint 100 [Aug 26 13:35:17] DEBUG[14644] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7f6c5c00a198' [Aug 26 13:35:17] DEBUG[14644] rtp_engine.c: Destroyed RTP instance '0x7f6c5c00a198' [Aug 26 13:35:17] DEBUG[14644] pjsip: dlg0x7f6c4400c .Session count dec to 0 by Session Module [Aug 26 13:35:17] DEBUG[14644] taskprocessor.c: destroying taskprocessor 'b84a60eb-6b3c-4e94-b254-c1acc3cac72d' [Aug 26 13:35:18] DEBUG[12758] pjsip: tsx0x7f6c44014 Retransmit timer event [Aug 26 13:35:18] DEBUG[12758] pjsip: tsx0x7f6c44014 .Retransmiting Response msg 486/INVITE/cseq=1 (tdta0x7f6c58007ed0), count=3, restart?=1 [Aug 26 13:35:18] DEBUG[12758] netsock2.c: Splitting '0.0.0.0:5060' into... [Aug 26 13:35:18] DEBUG[12758] netsock2.c: ...host '0.0.0.0' and port '5060'. [Aug 26 13:35:18] DEBUG[12758] netsock2.c: Splitting '46.165.249.3:5076' into... [Aug 26 13:35:18] DEBUG[12758] netsock2.c: ...host '46.165.249.3' and port '5076'. [Aug 26 13:35:18] VERBOSE[12758] res_pjsip_logger.c: <--- Transmitting SIP response (546 bytes) to UDP:46.165.249.3:5076 ---> SIP/2.0 486 Busy Here Via: SIP/2.0/UDP 46.165.249.3:5076;rport=5076;received=46.165.249.3;branch=z9hG4bK-d2fa58bd6654176b0ab9cc64c04606cb Call-ID: d2fa58bd6654176b0ab9cc64c04606cb From: "11004" ;tag=d27d69c0 To: "+970595706746" ;tag=311e6beb-8aa0-416c-b7ae-45e654988a0e CSeq: 1 INVITE Server: Asterisk PBX GIT-13-d238cf3M Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, MESSAGE, REFER Reason: Q.850;cause=17 Content-Length: 0 [Aug 26 13:35:22] DEBUG[13834] pjsip: endpoint Request msg OPTIONS/cseq=53108 (tdta0x7f6c58008ee0) created. [Aug 26 13:35:22] DEBUG[13834] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [Aug 26 13:35:22] DEBUG[13834] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [Aug 26 13:35:22] DEBUG[13834] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [Aug 26 13:35:22] DEBUG[13834] res_pjsip.c: 0x7f6c5c03d610: Wrapper created [Aug 26 13:35:22] DEBUG[13834] res_pjsip.c: 0x7f6c5c03d610: Set timer to 3000 msec [Aug 26 13:35:22] DEBUG[13834] pjsip: tsx0x7f6c4401c .Transaction created for Request msg OPTIONS/cseq=53108 (tdta0x7f6c58008ee0) [Aug 26 13:35:22] DEBUG[13834] pjsip: tsx0x7f6c4401c Sending Request msg OPTIONS/cseq=53108 (tdta0x7f6c58008ee0) in state Null [Aug 26 13:35:22] DEBUG[13834] pjsip: sip_resolve.c .Target '216.207.245.1:5062' type=Unspecified resolved to '216.207.245.1:5062' type=UDP (UDP transport) [Aug 26 13:35:22] DEBUG[13834] res_pjsip_multihomed.c: Re-wrote Contact URI host/port to 104.236.91.141:5060 [Aug 26 13:35:22] DEBUG[13834] netsock2.c: Splitting '0.0.0.0:5060' into... [Aug 26 13:35:22] DEBUG[13834] netsock2.c: ...host '0.0.0.0' and port '5060'. [Aug 26 13:35:22] DEBUG[13834] netsock2.c: Splitting '216.207.245.1:5062' into... [Aug 26 13:35:22] DEBUG[13834] netsock2.c: ...host '216.207.245.1' and port '5062'. [Aug 26 13:35:22] VERBOSE[13834] res_pjsip_logger.c: <--- Transmitting SIP request (499 bytes) to UDP:216.207.245.1:5062 ---> OPTIONS sip:100@216.207.245.1:5062 SIP/2.0 Via: SIP/2.0/UDP 104.236.91.141:5060;rport;branch=z9hG4bKPj151123a8-c067-4724-a1e5-1fe7b476db7d From: ;tag=9bf3683b-951c-4808-88d5-ebcc6fc56463 To: Contact: Call-ID: 0718aef6-09b8-4256-9bfd-58f7205a34e5 CSeq: 53108 OPTIONS Max-Forwards: 70 User-Agent: Asterisk PBX GIT-13-d238cf3M Content-Length: 0 [Aug 26 13:35:22] DEBUG[13834] pjsip: tsx0x7f6c4401c .State changed from Null to Calling, event=TX_MSG [Aug 26 13:35:22] DEBUG[12758] pjsip: sip_endpoint.c Processing incoming message: Response msg 200/OPTIONS/cseq=53108 (rdata0x7f6c58004618) [Aug 26 13:35:22] VERBOSE[12758] res_pjsip_logger.c: <--- Received SIP response (392 bytes) from UDP:216.207.245.1:5062 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 104.236.91.141:5060;rport;branch=z9hG4bKPj151123a8-c067-4724-a1e5-1fe7b476db7d From: ;tag=9bf3683b-951c-4808-88d5-ebcc6fc56463 To: ;tag=1893632195 Call-ID: 0718aef6-09b8-4256-9bfd-58f7205a34e5 CSeq: 53108 OPTIONS User-Agent: Yealink SIP-T28P 2.61.0.80 Content-Length: 0 [Aug 26 13:35:22] DEBUG[12758] netsock2.c: Splitting '216.207.245.1:5062' into... [Aug 26 13:35:22] DEBUG[12758] netsock2.c: ...host '216.207.245.1' and port '5062'. [Aug 26 13:35:22] DEBUG[12758] netsock2.c: Splitting '0.0.0.0:5060' into... [Aug 26 13:35:22] DEBUG[12758] netsock2.c: ...host '0.0.0.0' and port '5060'. [Aug 26 13:35:22] DEBUG[14644] pjsip: sip_endpoint.c Distributing rdata to modules: Response msg 200/OPTIONS/cseq=53108 (rdata0x7f6c5800ce58) [Aug 26 13:35:22] DEBUG[14644] pjsip: tsx0x7f6c4401c .Incoming Response msg 200/OPTIONS/cseq=53108 (rdata0x7f6c5800ce58) in state Calling [Aug 26 13:35:22] DEBUG[14644] pjsip: tsx0x7f6c4401c ..State changed from Calling to Completed, event=RX_MSG [Aug 26 13:35:22] DEBUG[14644] res_pjsip.c: 0x7f6c5c03d610: PJSIP tsx response received [Aug 26 13:35:22] DEBUG[14644] res_pjsip.c: 0x7f6c5c03d610: Cancelling timer [Aug 26 13:35:22] DEBUG[14644] res_pjsip.c: 0x7f6c5c03d610: Timer cancelled [Aug 26 13:35:22] DEBUG[14644] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [Aug 26 13:35:22] DEBUG[14644] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [Aug 26 13:35:22] DEBUG[14644] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [Aug 26 13:35:22] DEBUG[14644] res_pjsip.c: 0x7f6c5c03d610: Callbacks executed [Aug 26 13:35:22] DEBUG[14644] res_pjsip.c: 0x7f6c5c03d610: wrapper destroyed [Aug 26 13:35:22] DEBUG[15645] res_pjsip/pjsip_configuration.c: Contact sip:100@216.207.245.1:5062 status didn't change: Reachable, RTT: 61.023 msec [Aug 26 13:35:22] DEBUG[12758] pjsip: tsx0x7f6c44014 Retransmit timer event [Aug 26 13:35:22] DEBUG[12758] pjsip: tsx0x7f6c44014 .Retransmiting Response msg 486/INVITE/cseq=1 (tdta0x7f6c58007ed0), count=4, restart?=1 [Aug 26 13:35:22] DEBUG[12758] netsock2.c: Splitting '0.0.0.0:5060' into... [Aug 26 13:35:22] DEBUG[12758] netsock2.c: ...host '0.0.0.0' and port '5060'. [Aug 26 13:35:22] DEBUG[12758] netsock2.c: Splitting '46.165.249.3:5076' into... [Aug 26 13:35:22] DEBUG[12758] netsock2.c: ...host '46.165.249.3' and port '5076'. [Aug 26 13:35:22] VERBOSE[12758] res_pjsip_logger.c: <--- Transmitting SIP response (546 bytes) to UDP:46.165.249.3:5076 ---> SIP/2.0 486 Busy Here Via: SIP/2.0/UDP 46.165.249.3:5076;rport=5076;received=46.165.249.3;branch=z9hG4bK-d2fa58bd6654176b0ab9cc64c04606cb Call-ID: d2fa58bd6654176b0ab9cc64c04606cb From: "11004" ;tag=d27d69c0 To: "+970595706746" ;tag=311e6beb-8aa0-416c-b7ae-45e654988a0e CSeq: 1 INVITE Server: Asterisk PBX GIT-13-d238cf3M Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, MESSAGE, REFER Reason: Q.850;cause=17 Content-Length: 0 [Aug 26 13:35:26] DEBUG[12758] pjsip: tsx0x7f6c44014 Retransmit timer event [Aug 26 13:35:26] DEBUG[12758] pjsip: tsx0x7f6c44014 .Retransmiting Response msg 486/INVITE/cseq=1 (tdta0x7f6c58007ed0), count=5, restart?=1 [Aug 26 13:35:26] DEBUG[12758] netsock2.c: Splitting '0.0.0.0:5060' into... [Aug 26 13:35:26] DEBUG[12758] netsock2.c: ...host '0.0.0.0' and port '5060'. [Aug 26 13:35:26] DEBUG[12758] netsock2.c: Splitting '46.165.249.3:5076' into... [Aug 26 13:35:26] DEBUG[12758] netsock2.c: ...host '46.165.249.3' and port '5076'. [Aug 26 13:35:26] VERBOSE[12758] res_pjsip_logger.c: <--- Transmitting SIP response (546 bytes) to UDP:46.165.249.3:5076 ---> SIP/2.0 486 Busy Here Via: SIP/2.0/UDP 46.165.249.3:5076;rport=5076;received=46.165.249.3;branch=z9hG4bK-d2fa58bd6654176b0ab9cc64c04606cb Call-ID: d2fa58bd6654176b0ab9cc64c04606cb From: "11004" ;tag=d27d69c0 To: "+970595706746" ;tag=311e6beb-8aa0-416c-b7ae-45e654988a0e CSeq: 1 INVITE Server: Asterisk PBX GIT-13-d238cf3M Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, MESSAGE, REFER Reason: Q.850;cause=17 Content-Length: 0 [Aug 26 13:35:27] DEBUG[12758] pjsip: tsx0x7f6c4401c Timeout timer event [Aug 26 13:35:27] DEBUG[12758] pjsip: tsx0x7f6c4401c .State changed from Completed to Terminated, event=TIMER [Aug 26 13:35:27] DEBUG[12758] pjsip: tsx0x7f6c4401c Timeout timer event [Aug 26 13:35:27] DEBUG[12758] pjsip: tsx0x7f6c4401c .State changed from Terminated to Destroyed, event=TIMER [Aug 26 13:35:27] DEBUG[12758] pjsip: tdta0x7f6c5800 ..Destroying txdata Request msg OPTIONS/cseq=53108 (tdta0x7f6c58008ee0) [Aug 26 13:35:27] DEBUG[12758] pjsip: tsx0x7f6c4401c Transaction destroyed! [Aug 26 13:35:30] DEBUG[12758] pjsip: tsx0x7f6c44014 Retransmit timer event [Aug 26 13:35:30] DEBUG[12758] pjsip: tsx0x7f6c44014 .Retransmiting Response msg 486/INVITE/cseq=1 (tdta0x7f6c58007ed0), count=6, restart?=1 [Aug 26 13:35:30] DEBUG[12758] netsock2.c: Splitting '0.0.0.0:5060' into... [Aug 26 13:35:30] DEBUG[12758] netsock2.c: ...host '0.0.0.0' and port '5060'. [Aug 26 13:35:30] DEBUG[12758] netsock2.c: Splitting '46.165.249.3:5076' into... [Aug 26 13:35:30] DEBUG[12758] netsock2.c: ...host '46.165.249.3' and port '5076'. [Aug 26 13:35:30] VERBOSE[12758] res_pjsip_logger.c: <--- Transmitting SIP response (546 bytes) to UDP:46.165.249.3:5076 ---> SIP/2.0 486 Busy Here Via: SIP/2.0/UDP 46.165.249.3:5076;rport=5076;received=46.165.249.3;branch=z9hG4bK-d2fa58bd6654176b0ab9cc64c04606cb Call-ID: d2fa58bd6654176b0ab9cc64c04606cb From: "11004" ;tag=d27d69c0 To: "+970595706746" ;tag=311e6beb-8aa0-416c-b7ae-45e654988a0e CSeq: 1 INVITE Server: Asterisk PBX GIT-13-d238cf3M Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, MESSAGE, REFER Reason: Q.850;cause=17 Content-Length: 0 [Aug 26 13:35:31] DEBUG[15726] threadpool.c: Worker thread idle timeout reached. Dying. [Aug 26 13:35:31] DEBUG[12731] threadpool.c: Destroying worker thread 281 [Aug 26 13:35:31] DEBUG[15725] threadpool.c: Worker thread idle timeout reached. Dying. [Aug 26 13:35:31] DEBUG[12731] threadpool.c: Destroying worker thread 280 [Aug 26 13:35:34] DEBUG[12758] pjsip: tsx0x7f6c44014 Retransmit timer event [Aug 26 13:35:34] DEBUG[12758] pjsip: tsx0x7f6c44014 .Retransmiting Response msg 486/INVITE/cseq=1 (tdta0x7f6c58007ed0), count=7, restart?=1 [Aug 26 13:35:34] DEBUG[12758] netsock2.c: Splitting '0.0.0.0:5060' into... [Aug 26 13:35:34] DEBUG[12758] netsock2.c: ...host '0.0.0.0' and port '5060'. [Aug 26 13:35:34] DEBUG[12758] netsock2.c: Splitting '46.165.249.3:5076' into... [Aug 26 13:35:34] DEBUG[12758] netsock2.c: ...host '46.165.249.3' and port '5076'. [Aug 26 13:35:34] VERBOSE[12758] res_pjsip_logger.c: <--- Transmitting SIP response (546 bytes) to UDP:46.165.249.3:5076 ---> SIP/2.0 486 Busy Here Via: SIP/2.0/UDP 46.165.249.3:5076;rport=5076;received=46.165.249.3;branch=z9hG4bK-d2fa58bd6654176b0ab9cc64c04606cb Call-ID: d2fa58bd6654176b0ab9cc64c04606cb From: "11004" ;tag=d27d69c0 To: "+970595706746" ;tag=311e6beb-8aa0-416c-b7ae-45e654988a0e CSeq: 1 INVITE Server: Asterisk PBX GIT-13-d238cf3M Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, MESSAGE, REFER Reason: Q.850;cause=17 Content-Length: 0 [Aug 26 13:35:37] DEBUG[13834] pjsip: endpoint Request msg OPTIONS/cseq=61452 (tdta0x7f6c58008ee0) created. [Aug 26 13:35:37] DEBUG[13834] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [Aug 26 13:35:37] DEBUG[13834] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [Aug 26 13:35:37] DEBUG[13834] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [Aug 26 13:35:37] DEBUG[13834] res_pjsip.c: 0x7f6c5c03d610: Wrapper created [Aug 26 13:35:37] DEBUG[13834] res_pjsip.c: 0x7f6c5c03d610: Set timer to 3000 msec [Aug 26 13:35:37] DEBUG[13834] pjsip: tsx0x7f6c4401c .Transaction created for Request msg OPTIONS/cseq=61452 (tdta0x7f6c58008ee0) [Aug 26 13:35:37] DEBUG[13834] pjsip: tsx0x7f6c4401c Sending Request msg OPTIONS/cseq=61452 (tdta0x7f6c58008ee0) in state Null [Aug 26 13:35:37] DEBUG[13834] pjsip: sip_resolve.c .Target '216.207.245.1:5062' type=Unspecified resolved to '216.207.245.1:5062' type=UDP (UDP transport) [Aug 26 13:35:37] DEBUG[13834] res_pjsip_multihomed.c: Re-wrote Contact URI host/port to 104.236.91.141:5060 [Aug 26 13:35:37] DEBUG[13834] netsock2.c: Splitting '0.0.0.0:5060' into... [Aug 26 13:35:37] DEBUG[13834] netsock2.c: ...host '0.0.0.0' and port '5060'. [Aug 26 13:35:37] DEBUG[13834] netsock2.c: Splitting '216.207.245.1:5062' into... [Aug 26 13:35:37] DEBUG[13834] netsock2.c: ...host '216.207.245.1' and port '5062'. [Aug 26 13:35:37] VERBOSE[13834] res_pjsip_logger.c: <--- Transmitting SIP request (499 bytes) to UDP:216.207.245.1:5062 ---> OPTIONS sip:100@216.207.245.1:5062 SIP/2.0 Via: SIP/2.0/UDP 104.236.91.141:5060;rport;branch=z9hG4bKPje6e5dfb3-80fe-4dbf-9dd7-2f0c12ce0538 From: ;tag=3b45e1bb-c08d-4c16-b08f-bd6e921faa50 To: Contact: Call-ID: 86bff82d-8020-4d6d-b239-5cb65a7fdbf0 CSeq: 61452 OPTIONS Max-Forwards: 70 User-Agent: Asterisk PBX GIT-13-d238cf3M Content-Length: 0 [Aug 26 13:35:37] DEBUG[13834] pjsip: tsx0x7f6c4401c .State changed from Null to Calling, event=TX_MSG [Aug 26 13:35:37] DEBUG[12758] pjsip: sip_endpoint.c Processing incoming message: Response msg 200/OPTIONS/cseq=61452 (rdata0x7f6c58004618) [Aug 26 13:35:37] VERBOSE[12758] res_pjsip_logger.c: <--- Received SIP response (391 bytes) from UDP:216.207.245.1:5062 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 104.236.91.141:5060;rport;branch=z9hG4bKPje6e5dfb3-80fe-4dbf-9dd7-2f0c12ce0538 From: ;tag=3b45e1bb-c08d-4c16-b08f-bd6e921faa50 To: ;tag=981832226 Call-ID: 86bff82d-8020-4d6d-b239-5cb65a7fdbf0 CSeq: 61452 OPTIONS User-Agent: Yealink SIP-T28P 2.61.0.80 Content-Length: 0 [Aug 26 13:35:37] DEBUG[12758] netsock2.c: Splitting '216.207.245.1:5062' into... [Aug 26 13:35:37] DEBUG[12758] netsock2.c: ...host '216.207.245.1' and port '5062'. [Aug 26 13:35:37] DEBUG[12758] netsock2.c: Splitting '0.0.0.0:5060' into... [Aug 26 13:35:37] DEBUG[12758] netsock2.c: ...host '0.0.0.0' and port '5060'. [Aug 26 13:35:37] DEBUG[14644] pjsip: sip_endpoint.c Distributing rdata to modules: Response msg 200/OPTIONS/cseq=61452 (rdata0x7f6c5800ce58) [Aug 26 13:35:37] DEBUG[14644] pjsip: tsx0x7f6c4401c .Incoming Response msg 200/OPTIONS/cseq=61452 (rdata0x7f6c5800ce58) in state Calling [Aug 26 13:35:37] DEBUG[14644] pjsip: tsx0x7f6c4401c ..State changed from Calling to Completed, event=RX_MSG [Aug 26 13:35:37] DEBUG[14644] res_pjsip.c: 0x7f6c5c03d610: PJSIP tsx response received [Aug 26 13:35:37] DEBUG[14644] res_pjsip.c: 0x7f6c5c03d610: Cancelling timer [Aug 26 13:35:37] DEBUG[14644] res_pjsip.c: 0x7f6c5c03d610: Timer cancelled [Aug 26 13:35:37] DEBUG[14644] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [Aug 26 13:35:37] DEBUG[14644] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [Aug 26 13:35:37] DEBUG[14644] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [Aug 26 13:35:37] DEBUG[14644] res_pjsip.c: 0x7f6c5c03d610: Callbacks executed [Aug 26 13:35:37] DEBUG[14644] res_pjsip.c: 0x7f6c5c03d610: wrapper destroyed [Aug 26 13:35:37] DEBUG[15645] res_pjsip/pjsip_configuration.c: Contact sip:100@216.207.245.1:5062 status didn't change: Reachable, RTT: 64.872 msec [Aug 26 13:35:38] DEBUG[12758] pjsip: tsx0x7f6c44014 Retransmit timer event [Aug 26 13:35:38] DEBUG[12758] pjsip: tsx0x7f6c44014 .Retransmiting Response msg 486/INVITE/cseq=1 (tdta0x7f6c58007ed0), count=8, restart?=1 [Aug 26 13:35:38] DEBUG[12758] netsock2.c: Splitting '0.0.0.0:5060' into... [Aug 26 13:35:38] DEBUG[12758] netsock2.c: ...host '0.0.0.0' and port '5060'. [Aug 26 13:35:38] DEBUG[12758] netsock2.c: Splitting '46.165.249.3:5076' into... [Aug 26 13:35:38] DEBUG[12758] netsock2.c: ...host '46.165.249.3' and port '5076'. [Aug 26 13:35:38] VERBOSE[12758] res_pjsip_logger.c: <--- Transmitting SIP response (546 bytes) to UDP:46.165.249.3:5076 ---> SIP/2.0 486 Busy Here Via: SIP/2.0/UDP 46.165.249.3:5076;rport=5076;received=46.165.249.3;branch=z9hG4bK-d2fa58bd6654176b0ab9cc64c04606cb Call-ID: d2fa58bd6654176b0ab9cc64c04606cb From: "11004" ;tag=d27d69c0 To: "+970595706746" ;tag=311e6beb-8aa0-416c-b7ae-45e654988a0e CSeq: 1 INVITE Server: Asterisk PBX GIT-13-d238cf3M Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, MESSAGE, REFER Reason: Q.850;cause=17 Content-Length: 0 [Aug 26 13:35:42] DEBUG[12758] pjsip: tsx0x7f6c4401c Timeout timer event [Aug 26 13:35:42] DEBUG[12758] pjsip: tsx0x7f6c4401c .State changed from Completed to Terminated, event=TIMER [Aug 26 13:35:42] DEBUG[12758] pjsip: tsx0x7f6c4401c Timeout timer event [Aug 26 13:35:42] DEBUG[12758] pjsip: tsx0x7f6c4401c .State changed from Terminated to Destroyed, event=TIMER [Aug 26 13:35:42] DEBUG[12758] pjsip: tdta0x7f6c5800 ..Destroying txdata Request msg OPTIONS/cseq=61452 (tdta0x7f6c58008ee0) [Aug 26 13:35:42] DEBUG[12758] pjsip: tsx0x7f6c4401c Transaction destroyed! [Aug 26 13:35:42] DEBUG[12758] pjsip: tsx0x7f6c44014 Retransmit timer event [Aug 26 13:35:42] DEBUG[12758] pjsip: tsx0x7f6c44014 .Retransmiting Response msg 486/INVITE/cseq=1 (tdta0x7f6c58007ed0), count=9, restart?=1 [Aug 26 13:35:42] DEBUG[12758] netsock2.c: Splitting '0.0.0.0:5060' into... [Aug 26 13:35:42] DEBUG[12758] netsock2.c: ...host '0.0.0.0' and port '5060'. [Aug 26 13:35:42] DEBUG[12758] netsock2.c: Splitting '46.165.249.3:5076' into... [Aug 26 13:35:42] DEBUG[12758] netsock2.c: ...host '46.165.249.3' and port '5076'. [Aug 26 13:35:42] VERBOSE[12758] res_pjsip_logger.c: <--- Transmitting SIP response (546 bytes) to UDP:46.165.249.3:5076 ---> SIP/2.0 486 Busy Here Via: SIP/2.0/UDP 46.165.249.3:5076;rport=5076;received=46.165.249.3;branch=z9hG4bK-d2fa58bd6654176b0ab9cc64c04606cb Call-ID: d2fa58bd6654176b0ab9cc64c04606cb From: "11004" ;tag=d27d69c0 To: "+970595706746" ;tag=311e6beb-8aa0-416c-b7ae-45e654988a0e CSeq: 1 INVITE Server: Asterisk PBX GIT-13-d238cf3M Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, MESSAGE, REFER Reason: Q.850;cause=17 Content-Length: 0 [Aug 26 13:35:43] DEBUG[12758] pjsip: tsx0x7f6c44014 Timeout timer event [Aug 26 13:35:43] DEBUG[12758] pjsip: tsx0x7f6c44014 .State changed from Completed to Terminated, event=TIMER [Aug 26 13:35:43] DEBUG[12758] pjsip: dlg0x7f6c5c054 ..Transaction tsx0x7f6c44014ac8 state changed to Terminated [Aug 26 13:35:43] DEBUG[12758] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Aug 26 13:35:43] DEBUG[12758] res_pjsip_session.c: The state change pertains to the endpoint 'anonymous()' [Aug 26 13:35:43] DEBUG[12758] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Aug 26 13:35:43] DEBUG[12758] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7f6c44014ac8 [Aug 26 13:35:43] DEBUG[12758] res_pjsip_session.c: The current transaction state is Terminated [Aug 26 13:35:43] DEBUG[12758] res_pjsip_session.c: The transaction state change event is TIMER [Aug 26 13:35:43] DEBUG[12758] res_pjsip_session.c: The current inv state is DISCONNCTD [Aug 26 13:35:43] DEBUG[12758] pjsip: tsx0x7f6c44014 Timeout timer event [Aug 26 13:35:43] DEBUG[12758] pjsip: tsx0x7f6c44014 .State changed from Terminated to Destroyed, event=TIMER [Aug 26 13:35:43] DEBUG[12758] pjsip: tdta0x7f6c5800 ..Destroying txdata Response msg 486/INVITE/cseq=1 (tdta0x7f6c58007ed0) [Aug 26 13:35:43] DEBUG[12758] pjsip: tsx0x7f6c44014 Transaction destroyed! [Aug 26 13:35:43] DEBUG[13834] res_pjsip_session.c: Destroying SIP session with endpoint anonymous [Aug 26 13:35:43] DEBUG[13834] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7f6c5c01b5d8' [Aug 26 13:35:43] DEBUG[13834] rtp_engine.c: Destroyed RTP instance '0x7f6c5c01b5d8' [Aug 26 13:35:43] DEBUG[13834] pjsip: dlg0x7f6c5c054 .Session count dec to 0 by Session Module [Aug 26 13:35:43] DEBUG[13834] pjsip: dlg0x7f6c5c054 .Dialog destroyed [Aug 26 13:35:43] DEBUG[13834] taskprocessor.c: destroying taskprocessor '8734d41a-a997-40e1-b6e3-7945fc5463e2' [Aug 26 13:35:43] DEBUG[12758] pjsip: tsx0x7f6c4402f Timeout timer event [Aug 26 13:35:43] DEBUG[12758] pjsip: tsx0x7f6c4402f .State changed from Completed to Terminated, event=TIMER [Aug 26 13:35:43] DEBUG[12758] pjsip: dlg0x7f6c5c04a ..Transaction tsx0x7f6c4402f2f8 state changed to Terminated [Aug 26 13:35:43] DEBUG[12758] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Aug 26 13:35:43] DEBUG[12758] res_pjsip_session.c: inv_session 0x7f6c5c006348 has no ast session [Aug 26 13:35:43] DEBUG[12758] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Aug 26 13:35:43] DEBUG[12758] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x7f6c4402f2f8 [Aug 26 13:35:43] DEBUG[12758] res_pjsip_session.c: The current transaction state is Terminated [Aug 26 13:35:43] DEBUG[12758] res_pjsip_session.c: The transaction state change event is TIMER [Aug 26 13:35:43] DEBUG[12758] res_pjsip_session.c: The current inv state is DISCONNCTD [Aug 26 13:35:43] DEBUG[12758] pjsip: dlg0x7f6c5c04a ...Dialog destroyed [Aug 26 13:35:43] DEBUG[12758] pjsip: tsx0x7f6c4402f Timeout timer event [Aug 26 13:35:43] DEBUG[12758] pjsip: tsx0x7f6c4402f .State changed from Terminated to Destroyed, event=TIMER [Aug 26 13:35:43] DEBUG[12758] pjsip: tdta0x7f6c5800 ..Destroying txdata Request msg ACK/cseq=8608 (tdta0x7f6c58009ef0) [Aug 26 13:35:43] DEBUG[12758] pjsip: tsx0x7f6c4402f Transaction destroyed! [Aug 26 13:35:44] DEBUG[12758] pjsip: tsx0x7f6c4402c Timeout timer event [Aug 26 13:35:44] DEBUG[12758] pjsip: tsx0x7f6c4402c .State changed from Completed to Terminated, event=TIMER [Aug 26 13:35:44] DEBUG[12758] pjsip: dlg0x7f6c4400c ..Transaction tsx0x7f6c4402cee8 state changed to Terminated [Aug 26 13:35:44] DEBUG[12758] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Aug 26 13:35:44] DEBUG[12758] res_pjsip_session.c: inv_session 0x7f6c5c03a028 has no ast session [Aug 26 13:35:44] DEBUG[12758] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Aug 26 13:35:44] DEBUG[12758] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x7f6c4402cee8 [Aug 26 13:35:44] DEBUG[12758] res_pjsip_session.c: The current transaction state is Terminated [Aug 26 13:35:44] DEBUG[12758] res_pjsip_session.c: The transaction state change event is TIMER [Aug 26 13:35:44] DEBUG[12758] res_pjsip_session.c: The current inv state is DISCONNCTD [Aug 26 13:35:44] DEBUG[12758] pjsip: dlg0x7f6c4400c ...Dialog destroyed [Aug 26 13:35:44] DEBUG[12758] pjsip: tsx0x7f6c4402c Timeout timer event [Aug 26 13:35:44] DEBUG[12758] pjsip: tsx0x7f6c4402c .State changed from Terminated to Destroyed, event=TIMER [Aug 26 13:35:44] DEBUG[12758] pjsip: tdta0x7f6c5c05 ..Destroying txdata Request msg ACK/cseq=28049 (tdta0x7f6c5c055570) [Aug 26 13:35:44] DEBUG[12758] pjsip: tsx0x7f6c4402c Transaction destroyed! [Aug 26 13:35:45] DEBUG[12758] pjsip: sip_endpoint.c Processing incoming message: Request msg OPTIONS/cseq=1 (rdata0x7f6c58004618) [Aug 26 13:35:45] VERBOSE[12758] res_pjsip_logger.c: <--- Received SIP request (409 bytes) from UDP:85.93.88.116:5324 ---> OPTIONS sip:100@104.236.91.141 SIP/2.0 Via: SIP/2.0/UDP 85.93.88.116:5324;branch=z9hG4bK-2216888111;rport Content-Length: 0 From: "sipvicious";tag=363865633562386431336334013738313738313638 Accept: application/sdp User-Agent: friendly-scanner To: "sipvicious" Contact: sip:100@85.93.88.116:5324 CSeq: 1 OPTIONS Call-ID: 565893571300934314988533 Max-Forwards: 70 [Aug 26 13:35:45] DEBUG[12758] netsock2.c: Splitting '85.93.88.116:5324' into... [Aug 26 13:35:45] DEBUG[12758] netsock2.c: ...host '85.93.88.116' and port '5324'. [Aug 26 13:35:45] DEBUG[12758] netsock2.c: Splitting '0.0.0.0:5060' into... [Aug 26 13:35:45] DEBUG[12758] netsock2.c: ...host '0.0.0.0' and port '5060'. [Aug 26 13:35:45] DEBUG[14644] pjsip: sip_endpoint.c Distributing rdata to modules: Request msg OPTIONS/cseq=1 (rdata0x7f6c5800ce58) [Aug 26 13:35:45] DEBUG[14644] res_pjsip_endpoint_identifier_ip.c: No identify sections to match against [Aug 26 13:35:45] DEBUG[14644] res_pjsip_endpoint_identifier_user.c: Retrieved endpoint 100 [Aug 26 13:35:45] DEBUG[14644] pjsip: endpoint .Response msg 401/OPTIONS/cseq=1 (tdta0x7f6c58009ef0) created [Aug 26 13:35:45] DEBUG[14644] netsock2.c: Splitting '104.236.91.141' into... [Aug 26 13:35:45] DEBUG[14644] netsock2.c: ...host '104.236.91.141' and port ''. [Aug 26 13:35:45] DEBUG[14644] netsock2.c: Splitting '85.93.88.116' into... [Aug 26 13:35:45] DEBUG[14644] netsock2.c: ...host '85.93.88.116' and port ''. [Aug 26 13:35:45] DEBUG[14644] netsock2.c: Splitting '0.0.0.0:5060' into... [Aug 26 13:35:45] DEBUG[14644] netsock2.c: ...host '0.0.0.0' and port '5060'. [Aug 26 13:35:45] DEBUG[14644] netsock2.c: Splitting '85.93.88.116:5324' into... [Aug 26 13:35:45] DEBUG[14644] netsock2.c: ...host '85.93.88.116' and port '5324'. [Aug 26 13:35:45] VERBOSE[14644] res_pjsip_logger.c: <--- Transmitting SIP response (524 bytes) to UDP:85.93.88.116:5324 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 85.93.88.116:5324;rport=5324;received=85.93.88.116;branch=z9hG4bK-2216888111 Call-ID: 565893571300934314988533 From: "sipvicious" ;tag=363865633562386431336334013738313738313638 To: "sipvicious" ;tag=z9hG4bK-2216888111 CSeq: 1 OPTIONS WWW-Authenticate: Digest realm="asterisk",nonce="1440610545/a6427de0f177282297ffc086ab329678",opaque="1867afdc2a023c5c",algorithm=md5,qop="auth" Server: Asterisk PBX GIT-13-d238cf3M Content-Length: 0 [Aug 26 13:35:45] DEBUG[14644] pjsip: tdta0x7f6c5800 .Destroying txdata Response msg 401/OPTIONS/cseq=1 (tdta0x7f6c58009ef0) [Aug 26 13:35:52] DEBUG[13834] pjsip: endpoint Request msg OPTIONS/cseq=62321 (tdta0x7f6c5c055570) created. [Aug 26 13:35:52] DEBUG[13834] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [Aug 26 13:35:52] DEBUG[13834] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [Aug 26 13:35:52] DEBUG[13834] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [Aug 26 13:35:52] DEBUG[13834] res_pjsip.c: 0x7f6c5c00aca0: Wrapper created [Aug 26 13:35:52] DEBUG[13834] res_pjsip.c: 0x7f6c5c00aca0: Set timer to 3000 msec [Aug 26 13:35:52] DEBUG[13834] pjsip: tsx0x7f6c4402c .Transaction created for Request msg OPTIONS/cseq=62321 (tdta0x7f6c5c055570) [Aug 26 13:35:52] DEBUG[13834] pjsip: tsx0x7f6c4402c Sending Request msg OPTIONS/cseq=62321 (tdta0x7f6c5c055570) in state Null [Aug 26 13:35:52] DEBUG[13834] pjsip: sip_resolve.c .Target '216.207.245.1:5062' type=Unspecified resolved to '216.207.245.1:5062' type=UDP (UDP transport) [Aug 26 13:35:52] DEBUG[13834] res_pjsip_multihomed.c: Re-wrote Contact URI host/port to 104.236.91.141:5060 [Aug 26 13:35:52] DEBUG[13834] netsock2.c: Splitting '0.0.0.0:5060' into... [Aug 26 13:35:52] DEBUG[13834] netsock2.c: ...host '0.0.0.0' and port '5060'. [Aug 26 13:35:52] DEBUG[13834] netsock2.c: Splitting '216.207.245.1:5062' into... [Aug 26 13:35:52] DEBUG[13834] netsock2.c: ...host '216.207.245.1' and port '5062'. [Aug 26 13:35:52] VERBOSE[13834] res_pjsip_logger.c: <--- Transmitting SIP request (499 bytes) to UDP:216.207.245.1:5062 ---> OPTIONS sip:100@216.207.245.1:5062 SIP/2.0 Via: SIP/2.0/UDP 104.236.91.141:5060;rport;branch=z9hG4bKPj38330592-ee36-493a-ba50-6f71633e18cd From: ;tag=4d6b7098-ac27-4386-9333-379c864ff458 To: Contact: Call-ID: 734b26cc-68dc-45f6-8d1a-2ce2801c320b CSeq: 62321 OPTIONS Max-Forwards: 70 User-Agent: Asterisk PBX GIT-13-d238cf3M Content-Length: 0 [Aug 26 13:35:52] DEBUG[13834] pjsip: tsx0x7f6c4402c .State changed from Null to Calling, event=TX_MSG [Aug 26 13:35:52] DEBUG[12758] pjsip: sip_endpoint.c Processing incoming message: Response msg 200/OPTIONS/cseq=62321 (rdata0x7f6c58004618) [Aug 26 13:35:52] VERBOSE[12758] res_pjsip_logger.c: <--- Received SIP response (392 bytes) from UDP:216.207.245.1:5062 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 104.236.91.141:5060;rport;branch=z9hG4bKPj38330592-ee36-493a-ba50-6f71633e18cd From: ;tag=4d6b7098-ac27-4386-9333-379c864ff458 To: ;tag=1307468651 Call-ID: 734b26cc-68dc-45f6-8d1a-2ce2801c320b CSeq: 62321 OPTIONS User-Agent: Yealink SIP-T28P 2.61.0.80 Content-Length: 0 [Aug 26 13:35:52] DEBUG[12758] netsock2.c: Splitting '216.207.245.1:5062' into... [Aug 26 13:35:52] DEBUG[12758] netsock2.c: ...host '216.207.245.1' and port '5062'. [Aug 26 13:35:52] DEBUG[12758] netsock2.c: Splitting '0.0.0.0:5060' into... [Aug 26 13:35:52] DEBUG[12758] netsock2.c: ...host '0.0.0.0' and port '5060'. [Aug 26 13:35:52] DEBUG[14644] pjsip: sip_endpoint.c Distributing rdata to modules: Response msg 200/OPTIONS/cseq=62321 (rdata0x7f6c5800ce58) [Aug 26 13:35:52] DEBUG[14644] pjsip: tsx0x7f6c4402c .Incoming Response msg 200/OPTIONS/cseq=62321 (rdata0x7f6c5800ce58) in state Calling [Aug 26 13:35:52] DEBUG[14644] pjsip: tsx0x7f6c4402c ..State changed from Calling to Completed, event=RX_MSG [Aug 26 13:35:52] DEBUG[14644] res_pjsip.c: 0x7f6c5c00aca0: PJSIP tsx response received [Aug 26 13:35:52] DEBUG[14644] res_pjsip.c: 0x7f6c5c00aca0: Cancelling timer [Aug 26 13:35:52] DEBUG[14644] res_pjsip.c: 0x7f6c5c00aca0: Timer cancelled [Aug 26 13:35:52] DEBUG[14644] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [Aug 26 13:35:52] DEBUG[14644] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [Aug 26 13:35:52] DEBUG[14644] config.c: extract int from [0] in [-2147483648, 2147483647] gives [0](0) [Aug 26 13:35:52] DEBUG[14644] res_pjsip.c: 0x7f6c5c00aca0: Callbacks executed [Aug 26 13:35:52] DEBUG[14644] res_pjsip.c: 0x7f6c5c00aca0: wrapper destroyed [Aug 26 13:35:52] DEBUG[15645] res_pjsip/pjsip_configuration.c: Contact sip:100@216.207.245.1:5062 status didn't change: Reachable, RTT: 71.400 msec [Aug 26 13:35:57] DEBUG[12758] pjsip: tsx0x7f6c4402c Timeout timer event [Aug 26 13:35:57] DEBUG[12758] pjsip: tsx0x7f6c4402c .State changed from Completed to Terminated, event=TIMER [Aug 26 13:35:57] DEBUG[12758] pjsip: tsx0x7f6c4402c Timeout timer event [Aug 26 13:35:57] DEBUG[12758] pjsip: tsx0x7f6c4402c .State changed from Terminated to Destroyed, event=TIMER [Aug 26 13:35:57] DEBUG[12758] pjsip: tdta0x7f6c5c05 ..Destroying txdata Request msg OPTIONS/cseq=62321 (tdta0x7f6c5c055570) [Aug 26 13:35:57] DEBUG[12758] pjsip: tsx0x7f6c4402c Transaction destroyed! [Aug 26 13:36:01] DEBUG[12758] pjsip: sip_endpoint.c Processing incoming message: Request msg INVITE/cseq=1 (rdata0x7f6c58004618) [Aug 26 13:36:01] VERBOSE[12758] res_pjsip_logger.c: <--- Received SIP request (764 bytes) from UDP:62.210.180.213:5070 ---> INVITE sip:9011441200438617@104.236.91.141 SIP/2.0 To: 9011441200438617 From: 101;tag=b93b936c Via: SIP/2.0/UDP 62.210.180.213:5070;branch=z9hG4bK-8380c7d6731fc0de5de1fbf8ec9d3b14;rport Call-ID: 8380c7d6731fc0de5de1fbf8ec9d3b14 CSeq: 1 INVITE Contact: Max-Forwards: 70 Allow: INVITE, ACK, CANCEL, BYE User-Agent: sipcli/v1.8 Content-Type: application/sdp Content-Length: 284 v=0 o=sipcli-Session 605452076 1165456159 IN IP4 62.210.180.213 s=sipcli c=IN IP4 62.210.180.213 t=0 0 m=audio 5072 RTP/AVP 18 0 8 101 a=fmtp:101 0-15 a=rtpmap:18 G729/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=ptime:20 a=sendrecv [Aug 26 13:36:01] DEBUG[12758] netsock2.c: Splitting '62.210.180.213:5070' into... [Aug 26 13:36:01] DEBUG[12758] netsock2.c: ...host '62.210.180.213' and port '5070'. [Aug 26 13:36:01] DEBUG[12758] netsock2.c: Splitting '0.0.0.0:5060' into... [Aug 26 13:36:01] DEBUG[12758] netsock2.c: ...host '0.0.0.0' and port '5060'. [Aug 26 13:36:01] DEBUG[13834] pjsip: sip_endpoint.c Distributing rdata to modules: Request msg INVITE/cseq=1 (rdata0x7f6c5800ce58) [Aug 26 13:36:01] DEBUG[13834] res_pjsip_endpoint_identifier_ip.c: No identify sections to match against [Aug 26 13:36:01] DEBUG[13834] res_pjsip_endpoint_identifier_user.c: Could not identify endpoint by username '101' [Aug 26 13:36:01] DEBUG[13834] res_pjsip_endpoint_identifier_anonymous.c: Retrieved anonymous endpoint 'anonymous' [Aug 26 13:36:01] DEBUG[13834] pjsip: tsx0x7f6c4400c ..Transaction created for Request msg INVITE/cseq=1 (rdata0x7f6c5800ce58) [Aug 26 13:36:01] DEBUG[13834] pjsip: tsx0x7f6c4400c .Incoming Request msg INVITE/cseq=1 (rdata0x7f6c5800ce58) in state Null [Aug 26 13:36:01] DEBUG[13834] pjsip: tsx0x7f6c4400c ..State changed from Null to Trying, event=RX_MSG [Aug 26 13:36:01] DEBUG[13834] pjsip: dlg0x7f6c4402c ...Transaction tsx0x7f6c4400cb68 state changed to Trying [Aug 26 13:36:01] DEBUG[13834] pjsip: dlg0x7f6c4402c .UAS dialog created [Aug 26 13:36:01] DEBUG[13834] pjsip: dlg0x7f6c4402c .Module mod-invite added as dialog usage, data=0x7f6c5c019858 [Aug 26 13:36:01] DEBUG[13834] pjsip: dlg0x7f6c4402c ..Session count inc to 2 by mod-invite [Aug 26 13:36:01] DEBUG[13834] pjsip: inv0x7f6c4402c .UAS invite session created for dialog dlg0x7f6c4402cee8 [Aug 26 13:36:01] DEBUG[13834] pjsip: dlg0x7f6c4402c .Module Session Module added as dialog usage, data=(nil) [Aug 26 13:36:01] DEBUG[13834] pjsip: dlg0x7f6c4402c ..Session count inc to 2 by Session Module [Aug 26 13:36:01] DEBUG[13834] res_pjsip_session.c: Negotiating incoming SDP media stream 'audio' using audio SDP handler [Aug 26 13:36:01] DEBUG[13834] netsock2.c: Splitting '62.210.180.213' into... [Aug 26 13:36:01] DEBUG[13834] netsock2.c: ...host '62.210.180.213' and port ''. [Aug 26 13:36:01] DEBUG[13834] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7f6c5c011c28' [Aug 26 13:36:01] DEBUG[13834] res_rtp_asterisk.c: Allocated port 11204 for RTP instance '0x7f6c5c011c28' [Aug 26 13:36:01] DEBUG[13834] pjsip: icess0x7f6c5c0 ICE session created, comp_cnt=2, role is Unknown agent [Aug 26 13:36:01] DEBUG[13834] netsock2.c: Splitting '104.236.91.141' into... [Aug 26 13:36:01] DEBUG[13834] netsock2.c: ...host '104.236.91.141' and port ''. [Aug 26 13:36:01] DEBUG[13834] pjsip: icess0x7f6c5c0 Candidate 0 added: comp_id=1, type=host, foundation=H68ec5b8d, addr=104.236.91.141:11204, base=104.236.91.141:11204, prio=0x7effffff (2130706431) [Aug 26 13:36:01] DEBUG[13834] rtp_engine.c: RTP instance '0x7f6c5c011c28' is setup and ready to go [Aug 26 13:36:01] DEBUG[13834] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7f6c5c011c28' [Aug 26 13:36:01] DEBUG[13834] netsock2.c: Splitting '104.236.91.141' into... [Aug 26 13:36:01] DEBUG[13834] netsock2.c: ...host '104.236.91.141' and port ''. [Aug 26 13:36:01] DEBUG[13834] pjsip: icess0x7f6c5c0 Candidate 1 added: comp_id=2, type=host, foundation=H68ec5b8d, addr=104.236.91.141:11205, base=104.236.91.141:11205, prio=0x7efffffe (2130706430) [Aug 26 13:36:01] DEBUG[13834] pjsip: icess0x7f6c5c0 Destroying ICE session 0x7f6c5c011f88 [Aug 26 13:36:01] DEBUG[13834] pjsip: stuse0x7f6c5c0 STUN session 0x7f6c5c01cb18 destroy request, ref_cnt=4 [Aug 26 13:36:01] DEBUG[13834] pjsip: stuse0x7f6c5c0 STUN session 0x7f6c5c00fae8 destroy request, ref_cnt=3 [Aug 26 13:36:01] DEBUG[13834] pjsip: ice_session.c ICE session 0x7f6c5c011f88 destroyed [Aug 26 13:36:01] DEBUG[13834] pjsip: stun_session.c STUN session 0x7f6c5c01cb18 destroyed [Aug 26 13:36:01] DEBUG[13834] pjsip: stun_session.c STUN session 0x7f6c5c00fae8 destroyed [Aug 26 13:36:01] DEBUG[13834] rtp_engine.c: Setting tx payload type 18 based on m type on 0x7f6c3eaa03c0 [Aug 26 13:36:01] DEBUG[13834] rtp_engine.c: Setting tx payload type 0 based on m type on 0x7f6c3eaa03c0 [Aug 26 13:36:01] DEBUG[13834] rtp_engine.c: Setting tx payload type 8 based on m type on 0x7f6c3eaa03c0 [Aug 26 13:36:01] DEBUG[13834] rtp_engine.c: Setting tx payload type 101 based on m type on 0x7f6c3eaa03c0 [Aug 26 13:36:01] DEBUG[13834] rtp_engine.c: Copying payload 0 (0x7f6c5c003e50) from 0x7f6c3eaa03c0 to 0x7f6c5c011df0 [Aug 26 13:36:01] DEBUG[13834] rtp_engine.c: Copying payload 8 (0x7f6c5c036d00) from 0x7f6c3eaa03c0 to 0x7f6c5c011df0 [Aug 26 13:36:01] DEBUG[13834] rtp_engine.c: Copying payload 18 (0x7f6c5c001ba0) from 0x7f6c3eaa03c0 to 0x7f6c5c011df0 [Aug 26 13:36:01] DEBUG[13834] rtp_engine.c: Copying payload 101 (0x7f6c5c01cef0) from 0x7f6c3eaa03c0 to 0x7f6c5c011df0 [Aug 26 13:36:01] DEBUG[13834] res_pjsip_session.c: Media stream 'audio' handled by audio [Aug 26 13:36:01] DEBUG[13834] pjsip: endpoint .Response msg 100/INVITE/cseq=1 (tdta0x7f6c5c055570) created [Aug 26 13:36:01] DEBUG[13834] pjsip: dlg0x7f6c4402c .Initial answer Response msg 100/INVITE/cseq=1 (tdta0x7f6c5c055570) [Aug 26 13:36:01] DEBUG[13834] res_pjsip_session.c: Method is INVITE, Response is 100 Trying [Aug 26 13:36:01] DEBUG[13834] pjsip: inv0x7f6c4402c .Sending Response msg 100/INVITE/cseq=1 (tdta0x7f6c5c055570) [Aug 26 13:36:01] DEBUG[13834] pjsip: dlg0x7f6c4402c ..Sending Response msg 100/INVITE/cseq=1 (tdta0x7f6c5c055570) [Aug 26 13:36:01] DEBUG[13834] pjsip: tsx0x7f6c4400c ..Sending Response msg 100/INVITE/cseq=1 (tdta0x7f6c5c055570) in state Trying [Aug 26 13:36:01] DEBUG[13834] netsock2.c: Splitting '0.0.0.0:5060' into... [Aug 26 13:36:01] DEBUG[13834] netsock2.c: ...host '0.0.0.0' and port '5060'. [Aug 26 13:36:01] DEBUG[13834] netsock2.c: Splitting '62.210.180.213:5070' into... [Aug 26 13:36:01] DEBUG[13834] netsock2.c: ...host '62.210.180.213' and port '5070'. [Aug 26 13:36:01] VERBOSE[13834] res_pjsip_logger.c: <--- Transmitting SIP response (373 bytes) to UDP:62.210.180.213:5070 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 62.210.180.213:5070;rport=5070;received=62.210.180.213;branch=z9hG4bK-8380c7d6731fc0de5de1fbf8ec9d3b14 Call-ID: 8380c7d6731fc0de5de1fbf8ec9d3b14 From: "101" ;tag=b93b936c To: "9011441200438617" CSeq: 1 INVITE Server: Asterisk PBX GIT-13-d238cf3M Content-Length: 0 [Aug 26 13:36:01] DEBUG[13834] pjsip: tsx0x7f6c4400c ...State changed from Trying to Proceeding, event=TX_MSG [Aug 26 13:36:01] DEBUG[13834] pjsip: dlg0x7f6c4402c ....Transaction tsx0x7f6c4400cb68 state changed to Proceeding [Aug 26 13:36:01] DEBUG[13834] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Aug 26 13:36:01] DEBUG[13834] res_pjsip_session.c: The state change pertains to the endpoint 'anonymous()' [Aug 26 13:36:01] DEBUG[13834] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f6c4400cb68) [Aug 26 13:36:01] DEBUG[13834] res_pjsip_session.c: There is no transaction involved in this state change [Aug 26 13:36:01] DEBUG[13834] res_pjsip_session.c: The current inv state is INCOMING [Aug 26 13:36:01] DEBUG[13834] res_pjsip_session.c: Source of transaction state change is TX_MSG [Aug 26 13:36:01] DEBUG[13834] res_pjsip_session.c: Sending response [Aug 26 13:36:01] DEBUG[13834] res_pjsip_session.c: Method is INVITE, Response is 100 Trying [Aug 26 13:36:01] DEBUG[13834] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Aug 26 13:36:01] DEBUG[13834] res_pjsip_session.c: The state change pertains to the endpoint 'anonymous()' [Aug 26 13:36:01] DEBUG[13834] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f6c4400cb68) [Aug 26 13:36:01] DEBUG[13834] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7f6c4400cb68 [Aug 26 13:36:01] DEBUG[13834] res_pjsip_session.c: The current transaction state is Proceeding [Aug 26 13:36:01] DEBUG[13834] res_pjsip_session.c: The transaction state change event is TX_MSG [Aug 26 13:36:01] DEBUG[13834] res_pjsip_session.c: The current inv state is INCOMING [Aug 26 13:36:01] DEBUG[13834] res_pjsip_session.c: Sending response [Aug 26 13:36:01] DEBUG[13834] res_pjsip_session.c: Method is INVITE, Response is 100 Trying [Aug 26 13:36:01] DEBUG[13834] res_pjsip_session.c: Method is INVITE [Aug 26 13:36:01] DEBUG[13834] pjsip: dlg0x7f6c4402c Module NAT added as dialog usage, data=(nil) [Aug 26 13:36:01] DEBUG[13834] chan_pjsip.c: Started PBX on new PJSIP channel PJSIP/anonymous-0000001b [Aug 26 13:36:01] DEBUG[12731] threadpool.c: Increasing threadpool stasis-core's size by 1 [Aug 26 13:36:01] DEBUG[15734] logger.c: CALL_ID [C-00000009] created by thread. [Aug 26 13:36:01] DEBUG[15734][C-00000009] logger.c: CALL_ID [C-00000009] bound to thread. [Aug 26 13:36:01] DEBUG[15734][C-00000009] pbx.c: Launching 'Dial' [Aug 26 13:36:01] VERBOSE[15734][C-00000009] pbx.c: Executing [9011441200438617@from-anonymous:1] Dial("PJSIP/anonymous-0000001b", "PJSIP/100,6") in new stack [Aug 26 13:36:01] DEBUG[13834] config.c: extract double from [3.0] in [-inf, inf] gives [3.000000](0) [Aug 26 13:36:01] DEBUG[13834] config.c: extract int from [15] in [0, 86400] gives [15](0) [Aug 26 13:36:01] DEBUG[13834] config.c: extract double from [3.000000] in [-inf, inf] gives [3.000000](0) [Aug 26 13:36:01] DEBUG[13834] pjsip: dlg0x7f6c4402f UAC dialog created [Aug 26 13:36:01] DEBUG[13834] pjsip: dlg0x7f6c4402f Module Outbound INVITE Auth added as dialog usage, data=(nil) [Aug 26 13:36:01] DEBUG[13834] pjsip: dlg0x7f6c4402f Module mod-invite added as dialog usage, data=0x7f6c5c00fec8 [Aug 26 13:36:01] DEBUG[13834] pjsip: dlg0x7f6c4402f .Session count inc to 2 by mod-invite [Aug 26 13:36:01] DEBUG[13834] pjsip: dlg0x7f6c4402f Module mod-100rel added as dialog usage, data=0x7f6c5c010088 [Aug 26 13:36:01] DEBUG[13834] pjsip: dlg0x7f6c4402f 100rel module attached [Aug 26 13:36:01] DEBUG[13834] pjsip: inv0x7f6c4402f UAC invite session created for dialog dlg0x7f6c4402f2f8 [Aug 26 13:36:01] DEBUG[13834] pjsip: dlg0x7f6c4402f .Session count inc to 2 by Session Module [Aug 26 13:36:01] DEBUG[13834] pjsip: dlg0x7f6c4402f Module Session Module added as dialog usage, data=(nil)