[Sep 8 00:08:45] DEBUG[27740] manager.c: Running action 'Originate' [Sep 8 00:08:45] DEBUG[34165] pjsip: dlg0x7ffddc43a UAC dialog created [Sep 8 00:08:45] DEBUG[34165] pjsip: dlg0x7ffddc43a Module Outbound INVITE Auth added as dialog usage, data=(nil) [Sep 8 00:08:45] DEBUG[34165] pjsip: dlg0x7ffddc43a Module mod-invite added as dialog usage, data=0x7ffddd003f08 [Sep 8 00:08:45] DEBUG[34165] pjsip: dlg0x7ffddc43a .Session count inc to 2 by mod-invite [Sep 8 00:08:45] DEBUG[34165] pjsip: dlg0x7ffddc43a Module mod-100rel added as dialog usage, data=0x7ffddcda1950 [Sep 8 00:08:45] DEBUG[34165] pjsip: dlg0x7ffddc43a 100rel module attached [Sep 8 00:08:45] DEBUG[34165] pjsip: inv0x7ffddc43a UAC invite session created for dialog dlg0x7ffddc43a718 [Sep 8 00:08:45] DEBUG[34165] pjsip: dlg0x7ffddc43a .Session count inc to 2 by Session Module [Sep 8 00:08:45] DEBUG[34165] pjsip: dlg0x7ffddc43a Module Session Module added as dialog usage, data=(nil) [Sep 8 00:08:45] DEBUG[27740] manager.c: Examining AMI event: Event: Newchannel^M Privilege: call,all^M Channel: PJSIP/novanetpharma1-0000f60c^M ChannelState: 0^M ChannelStateDesc: Down^M CallerIDNum: ^M CallerIDName: ^M ConnectedLineNum: ^M ConnectedLineName: ^M Language: en^M AccountCode: ^M Context: default^M Exten: s^M Priority: 1^M Uniqueid: 1441651125.105895^M Linkedid: 1441651125.105895^M [Sep 8 00:08:45] DEBUG[27740] manager.c: Examining AMI event: Event: Newexten^M Privilege: call,all^M Channel: PJSIP/novanetpharma1-0000f60c^M ChannelState: 0^M ChannelStateDesc: Down^M CallerIDNum: ^M CallerIDName: ^M ConnectedLineNum: ^M ConnectedLineName: ^M Language: en^M AccountCode: ^M Context: default^M Exten: s^M Priority: 1^M Uniqueid: 1441651125.105895^M Linkedid: 1441651125.105895^M Extension: s^M Application: AppDial2^M AppData: (Outgoing Line)^M ^M [Sep 8 00:08:45] DEBUG[29413] audiohook.c: Read factory 0x7ffdf001cec8 was pretty quick last time, waiting for them. [Sep 8 00:08:45] DEBUG[29332] audiohook.c: Read factory 0x7ffdf00742b8 was pretty quick last time, waiting for them. [Sep 8 00:08:45] DEBUG[29556] audiohook.c: Write factory 0x7ffdf00064e8 was pretty quick last time, waiting for them. [Sep 8 00:08:45] DEBUG[27740] manager.c: Examining AMI event: Event: NewAccountCode^M Privilege: call,all^M Channel: PJSIP/novanetpharma1-0000f60c^M ChannelState: 0^M ChannelStateDesc: Down^M CallerIDNum: ^M CallerIDName: ^M ConnectedLineNum: ^M ConnectedLineName: ^M Language: en^M AccountCode: A090820150008450000880230^M Context: default^M Exten: s^M Priority: 1^M Uniqueid: 1441651125.105895^M Linkedid: 1441651125.105895^M OldAccountCode: ^M ^M [Sep 8 00:08:45] DEBUG[27740] manager.c: Examining AMI event: Event: NewCallerid^M Privilege: call,all^M Channel: PJSIP/novanetpharma1-0000f60c^M ChannelState: 0^M ChannelStateDesc: Down^M CallerIDNum: 5127176649^M CallerIDName: 5127176649^M ConnectedLineNum: ^M ConnectedLineName: ^M Language: en^M AccountCode: A090820150008450000880230^M Context: default^M Exten: s^M [Sep 8 00:08:45] DEBUG[27740] manager.c: Examining AMI event: Event: NewConnectedLine^M Privilege: call,all^M Channel: PJSIP/novanetpharma1-0000f60c^M ChannelState: 0^M ChannelStateDesc: Down^M CallerIDNum: 5127176649^M CallerIDName: 5127176649^M ConnectedLineNum: 5127176649^M ConnectedLineName: 5127176649^M Language: en^M AccountCode: A090820150008450000880230^M Context: default^M Exten: s^M Priority: 1^M Uniqueid: 1441651125.105895^M Linkedid: 1441651125.105895^M ^M Event: DialBegin^M Privilege: call,all^M DestChannel: PJSIP/novanetpharma1-0000f60c^M DestChannelState: 0^M DestChannelStateDesc: Down^M DestCallerIDNum: 5127176649^M DestCallerIDName: 5127176649^M DestConnectedLineNum: 5127176649^M DestConnectedLineName: 5127176649^M DestLanguage: en^M DestAccountCode: A090820150008450000880230^M DestContext: default^M DestExten: s^M DestPriority: 1^M DestUniqueid: 1441651125.105895^M DestLinkedid: 1441651125.105895^M DialString: 18033511225@novanetpharma1^M ^M [Sep 8 00:08:45] DEBUG[34165] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Sep 8 00:08:45] DEBUG[34165] res_pjsip_session.c: The state change pertains to the endpoint 'novanetpharma1(PJSIP/novanetpharma1-0000f60c)' [Sep 8 00:08:45] DEBUG[34165] res_pjsip_session.c: The inv session still has an invite_tsx (0x7ffddc827de8) [Sep 8 00:08:45] DEBUG[34165] res_pjsip_session.c: The UAC INVITE transaction involved in this state change is 0x7ffddc827de8 [Sep 8 00:08:45] DEBUG[34165] res_pjsip_session.c: The current transaction state is Proceeding [Sep 8 00:08:45] DEBUG[34165] res_pjsip_session.c: The transaction state change event is RX_MSG [Sep 8 00:08:45] DEBUG[34165] res_pjsip_session.c: The current inv state is CALLING [Sep 8 00:08:45] DEBUG[34165] res_pjsip_session.c: Received response [Sep 8 00:08:45] DEBUG[34165] res_pjsip_session.c: Response is 100 Analyzing [Sep 8 00:08:47] DEBUG[31225] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Sep 8 00:08:47] DEBUG[31225] res_pjsip_session.c: The state change pertains to the endpoint 'novanetpharma1(PJSIP/novanetpharma1-0000f60c)' [Sep 8 00:08:47] DEBUG[31225] res_pjsip_session.c: The inv session still has an invite_tsx (0x7ffddc827de8) [Sep 8 00:08:47] DEBUG[31225] res_pjsip_session.c: There is no transaction involved in this state change [Sep 8 00:08:47] DEBUG[31225] res_pjsip_session.c: The current inv state is EARLY [Sep 8 00:08:47] DEBUG[31225] res_pjsip_session.c: Source of transaction state change is RX_MSG [Sep 8 00:08:47] DEBUG[31225] res_pjsip_session.c: Received response [Sep 8 00:08:47] DEBUG[31225] res_pjsip_session.c: Response is 183 Session Progress [Sep 8 00:08:47] DEBUG[34165] res_pjsip_session.c: The state change pertains to the endpoint 'novanetpharma1(PJSIP/novanetpharma1-0000f60c)' [Sep 8 00:08:47] DEBUG[34165] res_pjsip_session.c: The inv session still has an invite_tsx (0x7ffddc827de8) [Sep 8 00:08:47] DEBUG[34165] res_pjsip_session.c: The UAC PRACK transaction involved in this state change is 0x7ffddc74b6f8 [Sep 8 00:08:47] DEBUG[34165] res_pjsip_session.c: The current transaction state is Completed [Sep 8 00:08:47] DEBUG[34165] res_pjsip_session.c: The transaction state change event is RX_MSG [Sep 8 00:08:47] DEBUG[34165] res_pjsip_session.c: The current inv state is EARLY [Sep 8 00:08:47] DEBUG[34165] res_pjsip_session.c: Received response [Sep 8 00:08:47] DEBUG[34165] res_pjsip_session.c: Response is 200 OK [Sep 8 00:08:52] DEBUG[27734] res_pjsip_session.c: The state change pertains to the endpoint 'novanetpharma1(PJSIP/novanetpharma1-0000f60c)' [Sep 8 00:08:52] DEBUG[27734] res_pjsip_session.c: The inv session still has an invite_tsx (0x7ffddc827de8) [Sep 8 00:08:52] DEBUG[27734] res_pjsip_session.c: The UAC PRACK transaction involved in this state change is 0x7ffddc74b6f8 [Sep 8 00:08:52] DEBUG[27734] res_pjsip_session.c: The current transaction state is Terminated [Sep 8 00:08:52] DEBUG[27734] res_pjsip_session.c: The transaction state change event is TIMER [Sep 8 00:08:52] DEBUG[27734] res_pjsip_session.c: The current inv state is EARLY [Sep 8 00:08:52] DEBUG[27734] pjsip: tsx0x7ffddc74b Timeout timer event [Sep 8 00:08:52] DEBUG[27734] pjsip: tsx0x7ffddc74b .State changed from Terminated to Destroyed, event=TIMER [Sep 8 00:08:52] DEBUG[27734] pjsip: tdta0x7ffe4406 ..Destroying txdata Request msg PRACK/cseq=8487 (tdta0x7ffe4406aeb0) [Sep 8 00:08:52] DEBUG[27734] pjsip: tsx0x7ffddc74b Transaction destroyed! Event: Unhold^M Privilege: call,all^M Channel: PJSIP/novanetpharma1-0000f60c^M ChannelState: 0^M ChannelStateDesc: Down^M CallerIDNum: 5127176649^M CallerIDName: 5127176649^M ConnectedLineNum: 5127176649^M ConnectedLineName: 5127176649^M Language: en^M AccountCode: A090820150008450000880230^M Context: default^M Exten: s^M Priority: 1^M Uniqueid: 1441651125.105895^M Linkedid: 1441651125.105895^M ^M [Sep 8 00:09:05] DEBUG[31225] pjsip: tsx0x7ffddc49c ...Transaction created for Request msg INVITE/cseq=80489508 (rdata0x7ffe44026ea8) [Sep 8 00:09:05] DEBUG[31225] pjsip: tsx0x7ffddc49c ..Incoming Request msg INVITE/cseq=80489508 (rdata0x7ffe44026ea8) in state Null [Sep 8 00:09:05] DEBUG[31225] pjsip: tsx0x7ffddc49c ...State changed from Null to Trying, event=RX_MSG [Sep 8 00:09:05] DEBUG[31225] pjsip: dlg0x7ffddc43a ....Transaction tsx0x7ffddc49c828 state changed to Trying [Sep 8 00:09:05] DEBUG[31225] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Sep 8 00:09:05] DEBUG[31225] res_pjsip_session.c: The state change pertains to the endpoint 'novanetpharma1(PJSIP/novanetpharma1-0000f60c)' [Sep 8 00:09:05] DEBUG[31225] res_pjsip_session.c: The inv session still has an invite_tsx (0x7ffddc827de8) [Sep 8 00:09:05] DEBUG[31225] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7ffddc49c828 [Sep 8 00:09:05] DEBUG[31225] res_pjsip_session.c: The current transaction state is Trying [Sep 8 00:09:05] DEBUG[31225] res_pjsip_session.c: The transaction state change event is RX_MSG [Sep 8 00:09:05] DEBUG[31225] res_pjsip_session.c: The current inv state is EARLY [Sep 8 00:09:05] DEBUG[31225] res_pjsip_session.c: Received request [Sep 8 00:09:05] DEBUG[31225] res_pjsip_session.c: Method is INVITE [Sep 8 00:09:05] DEBUG[31225] chan_pjsip.c: Started PBX on new PJSIP channel PJSIP/novanetpharma1-0000f60c [Sep 8 00:09:05] VERBOSE[29873][C-0000a7f0] pbx.c: Channel 'PJSIP/novanetpharma1-0000f60c' sent to invalid extension: context,exten,priority=default,s,1 [Sep 8 00:09:05] DEBUG[29873][C-0000a7f0] pbx.c: Launching 'Hangup' [Sep 8 00:09:05] VERBOSE[29873][C-0000a7f0] pbx.c: Executing [i@default:1] Hangup("PJSIP/novanetpharma1-0000f60c", "") in new stack [Sep 8 00:09:05] DEBUG[29873][C-0000a7f0] channel.c: Soft-Hanging (0x20) up channel 'PJSIP/novanetpharma1-0000f60c' [Sep 8 00:09:05] DEBUG[27740] manager.c: Examining AMI event: Event: Newexten^M Privilege: call,all^M Channel: PJSIP/novanetpharma1-0000f60c^M ChannelState: 0^M ChannelStateDesc: Down^M CallerIDNum: 5127176649^M CallerIDName: 5127176649^M ConnectedLineNum: 5127176649^M ConnectedLineName: 5127176649^M Language: en^M AccountCode: A090820150008450000880230^M Context: default^M Exten: i^M Priority: 1^M Uniqueid: 1441651125.105895^M Linkedid: 1441651125.105895^M Extension: i^M Application: Hangup [Sep 8 00:09:05] DEBUG[29559] channel.c: Hanging up channel 'PJSIP/novanetpharma1-0000f60c' [Sep 8 00:09:05] DEBUG[29559] chan_pjsip.c: AST hangup cause 16 (no match found in PJSIP) [Sep 8 00:09:05] DEBUG[27740] manager.c: Examining AMI event: Event: DialEnd^M Privilege: call,all^M DestChannel: PJSIP/novanetpharma1-0000f60c^M DestChannelState: 0^M DestChannelStateDesc: Down^M DestCallerIDNum: 5127176649^M DestCallerIDName: 5127176649^M DestConnectedLineNum: 5127176649^M DestConnectedLineName: 5127176649^M DestLanguage: en^M DestAccountCode: A090820150008450000880230^M DestContext: default^M DestExten: i^M DestPriority: 1^M DestUniqueid: 1441651125.105895^M DestLinkedid: 1441651125.105895^M DialStatus: NOANSWER^M [Sep 8 00:09:05] DEBUG[29873][C-0000a7f0] pbx.c: Spawn extension (default,i,1) exited non-zero on 'PJSIP/novanetpharma1-0000f60c' [Sep 8 00:09:05] VERBOSE[29873][C-0000a7f0] pbx.c: Spawn extension (default, i, 1) exited non-zero on 'PJSIP/novanetpharma1-0000f60c' [Sep 8 00:09:05] DEBUG[29873][C-0000a7f0] channel.c: Soft-Hanging (0x10) up channel 'PJSIP/novanetpharma1-0000f60c' [Sep 8 00:09:05] DEBUG[29873][C-0000a7f0] channel.c: Hanging up channel 'PJSIP/novanetpharma1-0000f60c' [Sep 8 00:09:05] DEBUG[29873][C-0000a7f0] chan_pjsip.c: AST hangup cause 16 (no match found in PJSIP) [Sep 8 00:09:05] DEBUG[27740] manager.c: Examining AMI event: Event: OriginateResponse^M Privilege: call,all^M ActionID: A090820150008450000880230^M Response: Failure^M Channel: PJSIP/18033511225@novanetpharma1^M Context: default^M Exten: dialer^M Reason: 0^M Uniqueid: ^M CallerIDNum: 5127176649^M CallerIDName: 5127176649^M [Sep 8 00:09:05] DEBUG[27718] cdr.c: Finalized CDR for PJSIP/novanetpharma1-0000f60c - start 1441651125.749139 answer 0.000000 end 1441651145.561316 dispo NO ANSWER [Sep 8 00:09:05] DEBUG[27740] manager.c: Examining AMI event: Event: SoftHangupRequest^M Privilege: call,all^M Channel: PJSIP/novanetpharma1-0000f60c^M ChannelState: 0^M ChannelStateDesc: Down^M CallerIDNum: 5127176649^M CallerIDName: 5127176649^M ConnectedLineNum: 5127176649^M ConnectedLineName: 5127176649^M Language: en^M AccountCode: A090820150008450000880230^M Context: default^M Exten: i^M Priority: 1^M Uniqueid: 1441651125.105895^M Linkedid: 1441651125.105895^M Cause: 16^M ^M [Sep 8 00:09:05] DEBUG[34165] pjsip: endpoint .Request msg CANCEL/cseq=8486 (tdta0x7ffe44021e30) created. [Sep 8 00:09:05] DEBUG[29561][C-0000a7e9] res_rtp_asterisk.c: Ooh, format changed from none to ulaw [Sep 8 00:09:05] DEBUG[34165] res_pjsip_session.c: Method is CANCEL [Sep 8 00:09:05] DEBUG[27734] pjsip: sip_endpoint.c Processing incoming message: Response msg 180/INVITE/cseq=21617 (rdata0x7ffe4407ae38) [Sep 8 00:09:05] DEBUG[27734] netsock2.c: Splitting '192.168.1.137:32648' into... [Sep 8 00:09:05] DEBUG[27734] netsock2.c: ...host '192.168.1.137' and port '32648'. [Sep 8 00:09:05] DEBUG[34165] pjsip: inv0x7ffddc43a .Sending Request msg CANCEL/cseq=8486 (tdta0x7ffe44021e30) [Sep 8 00:09:05] DEBUG[27734] netsock2.c: Splitting '0.0.0.0:5060' into... [Sep 8 00:09:05] DEBUG[27734] netsock2.c: ...host '0.0.0.0' and port '5060'. [Sep 8 00:09:05] DEBUG[34165] pjsip: dlg0x7ffddc43a ..Sending Request msg CANCEL/cseq=8486 (tdta0x7ffe44021e30) [Sep 8 00:09:05] DEBUG[34165] pjsip: tsx0x7ffddc453 ...Transaction created for Request msg CANCEL/cseq=8486 (tdta0x7ffe44021e30) [Sep 8 00:09:05] DEBUG[34165] pjsip: tsx0x7ffddc453 ..Sending Request msg CANCEL/cseq=8486 (tdta0x7ffe44021e30) in state Null [Sep 8 00:09:05] DEBUG[34165] pjsip: endpoint ...Request msg CANCEL/cseq=8486 (tdta0x7ffe44021e30): skipping target resolution because address is already set [Sep 8 00:09:05] DEBUG[31225] pjsip: sip_endpoint.c Distributing rdata to modules: Response msg 180/INVITE/cseq=21617 (rdata0x7ffe44055f28) [Sep 8 00:09:05] DEBUG[31225] pjsip: tsx0x7ffddc935 .Incoming Response msg 180/INVITE/cseq=21617 (rdata0x7ffe44055f28) in state Calling [Sep 8 00:09:05] DEBUG[31225] pjsip: tsx0x7ffddc935 ..State changed from Calling to Proceeding, event=RX_MSG [Sep 8 00:09:05] DEBUG[34165] netsock2.c: Splitting '0.0.0.0:5060' into... [Sep 8 00:09:05] DEBUG[31225] pjsip: dlg0x7ffddc21c ...Received Response msg 180/INVITE/cseq=21617 (rdata0x7ffe44055f28) [Sep 8 00:09:05] DEBUG[34165] netsock2.c: ...host '0.0.0.0' and port '5060'. [Sep 8 00:09:05] DEBUG[34165] netsock2.c: Splitting '203.153.53.141:5060' into... [Sep 8 00:09:05] DEBUG[34165] netsock2.c: ...host '203.153.53.141' and port '5060'. [Sep 8 00:09:05] DEBUG[31225] pjsip: dlg0x7ffddc21c ....Route-set updated [Sep 8 00:09:05] DEBUG[31225] pjsip: dlg0x7ffddc21c ...Transaction tsx0x7ffddc935868 state changed to Proceeding [Sep 8 00:09:05] DEBUG[31225] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Sep 8 00:09:05] DEBUG[31225] res_pjsip_session.c: The state change pertains to the endpoint '2026(PJSIP/2026-0000f674)' [Sep 8 00:09:05] DEBUG[31225] res_pjsip_session.c: The inv session still has an invite_tsx (0x7ffddc935868) [Sep 8 00:09:05] DEBUG[31225] res_pjsip_session.c: There is no transaction involved in this state change [Sep 8 00:09:05] DEBUG[34165] pjsip: tsx0x7ffddc453 ...State changed from Null to Calling, event=TX_MSG [Sep 8 00:09:05] DEBUG[31225] res_pjsip_session.c: The current inv state is EARLY [Sep 8 00:09:05] DEBUG[31225] res_pjsip_session.c: Source of transaction state change is RX_MSG [Sep 8 00:09:05] DEBUG[31225] res_pjsip_session.c: Received response [Sep 8 00:09:05] DEBUG[34165] pjsip: dlg0x7ffddc43a ....Transaction tsx0x7ffddc453408 state changed to Calling [Sep 8 00:09:05] DEBUG[31225] res_pjsip_session.c: Response is 180 Ringing [Sep 8 00:09:22] Asterisk 13.5.0 built by root @ ubuntu on a x86_64 running Linux on 2015-09-03 04:36:50 UTC [Sep 8 00:09:22] VERBOSE[29881] manager.c: Manager registered action DBGet [Sep 8 00:09:22] VERBOSE[29881] manager.c: Manager registered action DBPut [Sep 8 00:09:22] VERBOSE[29881] manager.c: Manager registered action DBDel [Sep 8 00:09:22] VERBOSE[29881] manager.c: Manager registered action DBDelTree [Sep 8 00:09:22] VERBOSE[29881] message.c: Message handler 'dialplan' registered.