[Dec 28 16:48:15] DEBUG[837]: manager.c:6313 process_message: Running action 'Login' [Dec 28 16:48:15] == Manager 'sendcron' logged on from 127.0.0.1 [Dec 28 16:48:15] DEBUG[837]: manager.c:6313 process_message: Running action 'Originate' [Dec 28 16:48:15] DEBUG[31554]: manager.c:5858 match_filter: Examining AMI event: Event: Newchannel Privilege: call,all Channel: Local/917275777470@default-00000030;1 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: default Exten: 917275777470 Priority: 1 Uniqueid: 1482961695.189 Linkedid: 1482961695.189 [Dec 28 16:48:15] DEBUG[31554]: manager.c:5858 match_filter: Examining AMI event: Event: Newchannel Privilege: call,all Channel: Local/917275777470@default-00000030;2 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: default Exten: 917275777470 Priority: 1 Uniqueid: 1482961695.190 Linkedid: 1482961695.189 [Dec 28 16:48:15] DEBUG[31554]: manager.c:5858 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: Local/917275777470@default-00000030;1 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: default Exten: 917275777470 Priority: 1 Uniqueid: 1482961695.189 Linkedid: 1482961695.189 Extension: 917275777470 Application: AppDial2 AppData: (Outgoing Line) [Dec 28 16:48:15] DEBUG[31554]: manager.c:5858 match_filter: Examining AMI event: Event: NewCallerid Privilege: call,all Channel: Local/917275777470@default-00000030;1 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: 0000000000 CallerIDName: V2281648150000060018 ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: default Exten: 917275777470 Priority: 1 Uniqueid: 1482961695.189 Linkedid: 1482961695.189 CID-CallingPres: 0 (Presentation Allowed, Not Screened) [Dec 28 16:48:15] DEBUG[31554]: manager.c:5858 match_filter: Examining AMI event: Event: NewConnectedLine Privilege: call,all Channel: Local/917275777470@default-00000030;1 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: 0000000000 CallerIDName: V2281648150000060018 ConnectedLineNum: 0000000000 ConnectedLineName: V2281648150000060018 Language: en AccountCode: Context: default Exten: 917275777470 Priority: 1 Uniqueid: 1482961695.189 Linkedid: 1482961695.189 [Dec 28 16:48:15] -- Called 917275777470@default [Dec 28 16:48:15] DEBUG[31554]: manager.c:5858 match_filter: Examining AMI event: Event: NewCallerid Privilege: call,all Channel: Local/917275777470@default-00000030;2 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 0000000000 CallerIDName: V2281648150000060018 ConnectedLineNum: 0000000000 ConnectedLineName: V2281648150000060018 Language: en AccountCode: Context: default Exten: 917275777470 Priority: 1 Uniqueid: 1482961695.190 Linkedid: 1482961695.189 CID-CallingPres: 0 (Presentation Allowed, Not Screened) [Dec 28 16:48:15] DEBUG[31554]: manager.c:5858 match_filter: Examining AMI event: Event: NewConnectedLine Privilege: call,all Channel: Local/917275777470@default-00000030;2 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 0000000000 CallerIDName: V2281648150000060018 ConnectedLineNum: 0000000000 ConnectedLineName: V2281648150000060018 Language: en AccountCode: Context: default Exten: 917275777470 Priority: 1 Uniqueid: 1482961695.190 Linkedid: 1482961695.189 [Dec 28 16:48:15] DEBUG[31554]: manager.c:5858 match_filter: Examining AMI event: Event: LocalBridge Privilege: call,all LocalOneChannel: Local/917275777470@default-00000030;1 LocalOneChannelState: 0 LocalOneChannelStateDesc: Down LocalOneCallerIDNum: 0000000000 LocalOneCallerIDName: V2281648150000060018 LocalOneConnectedLineNum: 0000000000 LocalOneConnectedLineName: V2281648150000060018 LocalOneLanguage: en LocalOneAccountCode: LocalOneContext: default LocalOneExten: 917275777470 LocalOnePriority: 1 LocalOneUniqueid: 1482961695.189 LocalOneLinkedid: 1482961695.189 LocalTwoChannel: Local/917275777470@default-00000030;2 LocalTwoChannelState: 4 LocalTwoChannelStateDesc: Ring LocalTwoCallerIDNum: 0000000000 LocalTwoCallerIDName: V2281648150000060018 LocalTwoConnectedLineNum: 0000000000 LocalTwoConnectedLineName: V2281648150000060018 LocalTwoLanguage: en LocalTwoAccountCode: LocalTwoContext: default LocalTwoExten: 917275777470 LocalTwoPriority: 1 LocalTwoUniqueid: 1482961695.190 LocalTwoLinkedid: 1482961695.189 Context: default Exten: 917275777470 LocalOptimization: Yes [Dec 28 16:48:15] DEBUG[31554]: manager.c:5858 match_filter: Examining AMI event: Event: DialBegin Privilege: call,all DestChannel: Local/917275777470@default-00000030;1 DestChannelState: 0 DestChannelStateDesc: Down DestCallerIDNum: 0000000000 DestCallerIDName: V2281648150000060018 DestConnectedLineNum: 0000000000 DestConnectedLineName: V2281648150000060018 DestLanguage: en DestAccountCode: DestContext: default DestExten: 917275777470 DestPriority: 1 DestUniqueid: 1482961695.189 DestLinkedid: 1482961695.189 DialString: 917275777470@default [Dec 28 16:48:15] DEBUG[839][C-0000007b]: pbx.c:2875 pbx_extension_helper: Launching 'AGI' [Dec 28 16:48:15] -- Executing [917275777470@default:1] AGI("Local/917275777470@default-00000030;2", "agi://127.0.0.1:4577/call_log") in new stack [Dec 28 16:48:15] DEBUG[839][C-0000007b]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '127.0.0.1:4577' into... [Dec 28 16:48:15] DEBUG[839][C-0000007b]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '127.0.0.1' and port '4577'. [Dec 28 16:48:15] DEBUG[31554]: manager.c:5858 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: Local/917275777470@default-00000030;2 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 0000000000 CallerIDName: V2281648150000060018 ConnectedLineNum: 0000000000 ConnectedLineName: V2281648150000060018 Language: en AccountCode: Context: default Exten: 917275777470 Priority: 1 Uniqueid: 1482961695.190 Linkedid: 1482961695.189 Extension: 917275777470 Application: AGI AppData: agi://127.0.0.1:4577/call_log [Dec 28 16:48:15] DEBUG[839][C-0000007b]: res_agi.c:2105 launch_netscript: Wow, connected! [Dec 28 16:48:15] -- AGI Script Executing Application: (EXEC) Options: (Set(_CAMPCUST=TESTCAMP)) [Dec 28 16:48:15] -- AGI Script agi://127.0.0.1:4577/call_log completed, returning 0 [Dec 28 16:48:15] DEBUG[839][C-0000007b]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'EXTEN' is '917275777470' [Dec 28 16:48:15] DEBUG[839][C-0000007b]: pbx.c:2875 pbx_extension_helper: Launching 'Dial' [Dec 28 16:48:15] -- Executing [917275777470@default:2] Dial("Local/917275777470@default-00000030;2", "SIP/office-server/17275777470,,To") in new stack [Dec 28 16:48:15] DEBUG[31554]: manager.c:5858 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: Local/917275777470@default-00000030;2 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 0000000000 CallerIDName: V2281648150000060018 ConnectedLineNum: 0000000000 ConnectedLineName: V2281648150000060018 Language: en AccountCode: Context: default Exten: 917275777470 Priority: 2 Uniqueid: 1482961695.190 Linkedid: 1482961695.189 Extension: 917275777470 Application: Dial AppData: SIP/office-server/17275777470,,To [Dec 28 16:48:15] DEBUG[839][C-0000007b]: chan_sip.c:30260 sip_request_call: Asked to create a SIP channel with formats: (slin) [Dec 28 16:48:15] DEBUG[839][C-0000007b]: chan_sip.c:8981 __sip_alloc: Allocating new SIP dialog for 4740b5b94766957236337a5c02ab65fb@192.168.198.30:5060 - INVITE (No RTP) [Dec 28 16:48:15] DEBUG[839][C-0000007b]: rtp_engine.c:454 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0x7f7b04005c50' [Dec 28 16:48:15] DEBUG[839][C-0000007b]: res_rtp_asterisk.c:2679 ast_rtp_new: Allocated port 17306 for RTP instance '0x7f7b04005c50' [Dec 28 16:48:15] DEBUG[839][C-0000007b]: rtp_engine.c:463 ast_rtp_instance_new: RTP instance '0x7f7b04005c50' is setup and ready to go [Dec 28 16:48:15] DEBUG[839][C-0000007b]: acl.c:958 ast_find_ourip: Not an IPv4 nor IPv6 address, cannot get port. [Dec 28 16:48:15] DEBUG[839][C-0000007b]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting 'mike-dev1' into... [Dec 28 16:48:15] DEBUG[839][C-0000007b]: netsock2.c:226 ast_sockaddr_split_hostport: ...host 'mike-dev1' and port ''. [Dec 28 16:48:15] DEBUG[839][C-0000007b]: res_rtp_asterisk.c:4920 ast_rtp_prop_set: Setup RTCP on RTP instance '0x7f7b04005c50' [Dec 28 16:48:15] == Using SIP RTP CoS mark 5 [Dec 28 16:48:15] DEBUG[839][C-0000007b]: chan_sip.c:5788 do_setnat: Setting NAT on RTP to On [Dec 28 16:48:15] DEBUG[839][C-0000007b]: acl.c:946 ast_ouraddrfor: For destination '192.168.198.1', our source address is '192.168.198.30'. [Dec 28 16:48:15] DEBUG[839][C-0000007b]: chan_sip.c:3903 ast_sip_ouraddrfor: Setting AST_TRANSPORT_UDP with address 192.168.198.30:5060 [Dec 28 16:48:15] DEBUG[839][C-0000007b]: chan_sip.c:5788 do_setnat: Setting NAT on RTP to On [Dec 28 16:48:15] DEBUG[839][C-0000007b]: chan_sip.c:8766 change_callid_pvt: SIP call-id changed from '4740b5b94766957236337a5c02ab65fb@192.168.198.30:5060' to '46ca6204476c4b8e56716c3d109b504d@192.168.198.30:5060' [Dec 28 16:48:15] DEBUG[31406]: threadpool.c:517 grow: Increasing threadpool stasis-core's size by 1 [Dec 28 16:48:15] DEBUG[839][C-0000007b]: chan_sip.c:8138 sip_new: *** Our native formats are (gsm) [Dec 28 16:48:15] DEBUG[839][C-0000007b]: chan_sip.c:8139 sip_new: *** Joint capabilities are (nothing) [Dec 28 16:48:15] DEBUG[839][C-0000007b]: chan_sip.c:8140 sip_new: *** Our capabilities are (gsm|ulaw) [Dec 28 16:48:15] DEBUG[839][C-0000007b]: chan_sip.c:8141 sip_new: *** AST_CODEC_CHOOSE formats are gsm [Dec 28 16:48:15] DEBUG[839][C-0000007b]: chan_sip.c:8143 sip_new: *** Our preferred formats from the incoming channel are (slin) [Dec 28 16:48:15] DEBUG[839][C-0000007b]: chan_sip.c:8174 sip_new: This channel will not be able to handle video. [Dec 28 16:48:15] DEBUG[31554]: manager.c:5858 match_filter: Examining AMI event: Event: Newchannel Privilege: call,all Channel: SIP/office-server-00000003 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: CallerIDName: ConnectedLineNum: ConnectedLineName: Language: en AccountCode: Context: international Exten: s Priority: 1 Uniqueid: 1482961695.191 Linkedid: 1482961695.189 [Dec 28 16:48:15] DEBUG[839][C-0000007b]: channel_internal_api.c:935 ast_channel_callid_set: Channel Call ID changing from [C-0000007b] to [C-0000007b] [Dec 28 16:48:15] DEBUG[839][C-0000007b]: rtp_engine.c:1191 ast_rtp_instance_early_bridge_make_compatible: Can't find native functions for channel 'Local/917275777470@default-00000030;2' [Dec 28 16:48:15] DEBUG[839][C-0000007b]: channel.c:6628 ast_channel_inherit_variables: Inheriting variable CAMPCUST from Local/917275777470@default-00000030;2 to SIP/office-server-00000003. [Dec 28 16:48:15] DEBUG[839][C-0000007b]: chan_sip.c:6463 sip_call: Outgoing Call for 17275777470 [Dec 28 16:48:15] DEBUG[31554]: manager.c:5858 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/office-server-00000003 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: 0000000000 CallerIDName: V2281648150000060018 ConnectedLineNum: 0000000000 ConnectedLineName: V2281648150000060018 Language: en AccountCode: Context: international Exten: 917275777470 Priority: 1 Uniqueid: 1482961695.191 Linkedid: 1482961695.189 Extension: 917275777470 Application: AppDial AppData: (Outgoing Line) [Dec 28 16:48:15] DEBUG[31554]: manager.c:5858 match_filter: Examining AMI event: Event: NewCallerid Privilege: call,all Channel: SIP/office-server-00000003 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: 0000000000 CallerIDName: V2281648150000060018 ConnectedLineNum: 0000000000 ConnectedLineName: V2281648150000060018 Language: en AccountCode: Context: international Exten: 917275777470 Priority: 1 Uniqueid: 1482961695.191 Linkedid: 1482961695.189 CID-CallingPres: 0 (Presentation Allowed, Not Screened) [Dec 28 16:48:15] DEBUG[839][C-0000007b]: chan_sip.c:6757 update_call_counter: Updating call counter for outgoing call [Dec 28 16:48:15] DEBUG[31554]: manager.c:5858 match_filter: Examining AMI event: Event: NewConnectedLine Privilege: call,all Channel: SIP/office-server-00000003 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: 0000000000 CallerIDName: V2281648150000060018 ConnectedLineNum: 0000000000 ConnectedLineName: V2281648150000060018 Language: en AccountCode: Context: international Exten: 917275777470 Priority: 1 Uniqueid: 1482961695.191 Linkedid: 1482961695.189 [Dec 28 16:48:15] DEBUG[839][C-0000007b]: chan_sip.c:13393 add_sdp: ** Our capability: (gsm|ulaw) Video flag: False Text flag: False [Dec 28 16:48:15] DEBUG[839][C-0000007b]: chan_sip.c:13394 add_sdp: ** Our prefcodec: (slin) [Dec 28 16:48:15] DEBUG[839][C-0000007b]: chan_sip.c:13564 add_sdp: -- Done with adding codecs to SDP [Dec 28 16:48:15] DEBUG[839][C-0000007b]: chan_sip.c:13777 add_sdp: Done building SDP. Settling with this capability: (gsm|ulaw) [Dec 28 16:48:15] DEBUG[839][C-0000007b]: chan_sip.c:3389 initialize_initreq: Initializing initreq for method INVITE - callid 46ca6204476c4b8e56716c3d109b504d@192.168.198.30:5060 [Dec 28 16:48:15] DEBUG[839][C-0000007b]: chan_sip.c:3746 __sip_xmit: Trying to put 'INVITE sip:' onto UDP socket destined for 192.168.198.1:5060 [Dec 28 16:48:15] -- Called SIP/office-server/17275777470 [Dec 28 16:48:15] DEBUG[31554]: manager.c:5858 match_filter: Examining AMI event: Event: DialBegin Privilege: call,all Channel: Local/917275777470@default-00000030;2 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 0000000000 CallerIDName: V2281648150000060018 ConnectedLineNum: 0000000000 ConnectedLineName: V2281648150000060018 Language: en AccountCode: Context: default Exten: 917275777470 Priority: 2 Uniqueid: 1482961695.190 Linkedid: 1482961695.189 DestChannel: SIP/office-server-00000003 DestChannelState: 0 DestChannelStateDesc: Down DestCallerIDNum: 0000000000 DestCallerIDName: V2281648150000060018 DestConnectedLineNum: 0000000000 DestConnectedLineName: V2281648150000060018 DestLanguage: en DestAccountCode: DestContext: international DestExten: 917275777470 DestPriority: 1 DestUniqueid: 1482961695.191 DestLinkedid: 1482961695.189 DialString: office-server/17275777470 [Dec 28 16:48:15] DEBUG[839][C-0000007b]: channel.c:5657 set_format: Channel SIP/office-server-00000003 setting read format path: gsm -> slin [Dec 28 16:48:15] DEBUG[839][C-0000007b]: channel.c:5657 set_format: Channel SIP/office-server-00000003 setting write format path: slin -> gsm [Dec 28 16:48:15] DEBUG[31434]: chan_sip.c:9394 __find_call: = Looking for Call ID: 46ca6204476c4b8e56716c3d109b504d@192.168.198.30:5060 (Checking To) --From tag as3bc76506 --To-tag [Dec 28 16:48:15] DEBUG[31434][C-0000007b]: chan_sip.c:4568 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '46ca6204476c4b8e56716c3d109b504d@192.168.198.30:5060' Request 102: Found [Dec 28 16:48:15] DEBUG[31434][C-0000007b]: chan_sip.c:23471 handle_response_invite: SIP response 100 to standard invite [Dec 28 16:48:15] DEBUG[31543]: manager.c:6313 process_message: Running action 'Command' [Dec 28 16:48:15] DEBUG[31543]: manager.c:6313 process_message: Running action 'Command' [Dec 28 16:48:16] DEBUG[31543]: manager.c:6313 process_message: Running action 'Command' [Dec 28 16:48:16] DEBUG[31554]: manager.c:6313 process_message: Running action 'Command' [Dec 28 16:48:16] DEBUG[31543]: manager.c:6313 process_message: Running action 'Command' [Dec 28 16:48:17] DEBUG[31543]: manager.c:6313 process_message: Running action 'Command' [Dec 28 16:48:17] DEBUG[31543]: manager.c:6313 process_message: Running action 'Command' [Dec 28 16:48:17] DEBUG[31543]: manager.c:6313 process_message: Running action 'Command' [Dec 28 16:48:18] DEBUG[31434]: chan_sip.c:9394 __find_call: = Looking for Call ID: 46ca6204476c4b8e56716c3d109b504d@192.168.198.30:5060 (Checking To) --From tag as3bc76506 --To-tag as014408bc [Dec 28 16:48:18] DEBUG[31434][C-0000007b]: chan_sip.c:4568 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '46ca6204476c4b8e56716c3d109b504d@192.168.198.30:5060' Request 102: Found [Dec 28 16:48:18] DEBUG[31434][C-0000007b]: chan_sip.c:23471 handle_response_invite: SIP response 183 to standard invite [Dec 28 16:48:18] DEBUG[31434][C-0000007b]: chan_sip.c:10246 process_sdp: Processing session-level SDP v=0... UNSUPPORTED OR FAILED. [Dec 28 16:48:18] DEBUG[31434][C-0000007b]: chan_sip.c:10246 process_sdp: Processing session-level SDP o=root 889090418 889090418 IN IP4 192.168.198.1... OK. [Dec 28 16:48:18] DEBUG[31434][C-0000007b]: chan_sip.c:10246 process_sdp: Processing session-level SDP s=Asterisk PBX 11.23.1-vici... UNSUPPORTED OR FAILED. [Dec 28 16:48:18] DEBUG[31434][C-0000007b]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.198.1' into... [Dec 28 16:48:18] DEBUG[31434][C-0000007b]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.198.1' and port ''. [Dec 28 16:48:18] DEBUG[31434][C-0000007b]: chan_sip.c:10246 process_sdp: Processing session-level SDP c=IN IP4 192.168.198.1... OK. [Dec 28 16:48:18] DEBUG[31434][C-0000007b]: chan_sip.c:10246 process_sdp: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED. [Dec 28 16:48:18] DEBUG[31434][C-0000007b]: rtp_engine.c:689 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 3 based on m type on 0x7f7b0cc3b4c0 [Dec 28 16:48:18] DEBUG[31434][C-0000007b]: rtp_engine.c:689 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 0 based on m type on 0x7f7b0cc3b4c0 [Dec 28 16:48:18] DEBUG[31434][C-0000007b]: rtp_engine.c:689 ast_rtp_codecs_payloads_set_m_type: Setting tx payload type 101 based on m type on 0x7f7b0cc3b4c0 [Dec 28 16:48:18] DEBUG[31434][C-0000007b]: chan_sip.c:10701 process_sdp: Processing media-level (audio) SDP a=rtpmap:3 GSM/8000... OK. [Dec 28 16:48:18] DEBUG[31434][C-0000007b]: chan_sip.c:10701 process_sdp: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. [Dec 28 16:48:18] DEBUG[31434][C-0000007b]: chan_sip.c:10701 process_sdp: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [Dec 28 16:48:18] DEBUG[31434][C-0000007b]: chan_sip.c:10701 process_sdp: Processing media-level (audio) SDP a=fmtp:101 0-16... UNSUPPORTED OR FAILED. [Dec 28 16:48:18] DEBUG[31434][C-0000007b]: chan_sip.c:10701 process_sdp: Processing media-level (audio) SDP a=ptime:20... OK. [Dec 28 16:48:18] DEBUG[31434][C-0000007b]: chan_sip.c:10701 process_sdp: Processing media-level (audio) SDP a=sendrecv... OK. [Dec 28 16:48:18] DEBUG[31434][C-0000007b]: acl.c:920 ast_ouraddrfor: Not an IPv4 nor IPv6 address, cannot get port. [Dec 28 16:48:18] DEBUG[31434][C-0000007b]: acl.c:946 ast_ouraddrfor: For destination '192.168.198.1', our source address is '192.168.198.30'. [Dec 28 16:48:18] DEBUG[31434][C-0000007b]: res_rtp_asterisk.c:4986 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7f7b04005c50' [Dec 28 16:48:18] DEBUG[31434][C-0000007b]: rtp_engine.c:658 ast_rtp_codecs_payloads_copy: Copying payload 0 (0x7f7af8004fc8) from 0x7f7b0cc3b4c0 to 0x7f7b04005e18 [Dec 28 16:48:18] DEBUG[31434][C-0000007b]: rtp_engine.c:658 ast_rtp_codecs_payloads_copy: Copying payload 3 (0x7f7af8003ef8) from 0x7f7b0cc3b4c0 to 0x7f7b04005e18 [Dec 28 16:48:18] DEBUG[31434][C-0000007b]: rtp_engine.c:658 ast_rtp_codecs_payloads_copy: Copying payload 101 (0x7f7af8005008) from 0x7f7b0cc3b4c0 to 0x7f7b04005e18 [Dec 28 16:48:18] DEBUG[31434][C-0000007b]: res_rtp_asterisk.c:4871 ast_rtp_prop_set: Ignoring duplicate RTCP property on RTP instance '0x7f7b04005c50' [Dec 28 16:48:18] DEBUG[31434][C-0000007b]: chan_sip.c:10999 process_sdp: We're settling with these formats: (gsm|ulaw) [Dec 28 16:48:18] DEBUG[31434][C-0000007b]: chan_sip.c:11006 process_sdp: We have an owner, now see if we need to change this call [Dec 28 16:48:18] -- SIP/office-server-00000003 is making progress passing it to Local/917275777470@default-00000030;2 [Dec 28 16:48:18] -- Local/917275777470@default-00000030;1 is making progress [Dec 28 16:48:18] DEBUG[31434]: chan_sip.c:4351 __sip_autodestruct: Auto destroying SIP dialog '0e04fe4418b9f6064fd7a90b05b26bdb@192.168.198.1:5060' [Dec 28 16:48:18] DEBUG[31434]: chan_sip.c:6579 sip_pvt_dtor: Destroying SIP dialog 0e04fe4418b9f6064fd7a90b05b26bdb@192.168.198.1:5060 [Dec 28 16:48:18] DEBUG[31543]: manager.c:6313 process_message: Running action 'Command' [Dec 28 16:48:18] DEBUG[31543]: manager.c:6313 process_message: Running action 'Command' [Dec 28 16:48:19] DEBUG[31543]: manager.c:6313 process_message: Running action 'Command' [Dec 28 16:48:19] DEBUG[31543]: manager.c:6313 process_message: Running action 'Command' [Dec 28 16:48:19] DEBUG[31543]: manager.c:6313 process_message: Running action 'Command' [Dec 28 16:48:20] DEBUG[31543]: manager.c:6313 process_message: Running action 'Command' [Dec 28 16:48:20] DEBUG[31543]: manager.c:6313 process_message: Running action 'Command' [Dec 28 16:48:20] DEBUG[31434]: chan_sip.c:9394 __find_call: = Looking for Call ID: 46ca6204476c4b8e56716c3d109b504d@192.168.198.30:5060 (Checking To) --From tag as3bc76506 --To-tag as014408bc [Dec 28 16:48:20] DEBUG[31434][C-0000007b]: chan_sip.c:4511 __sip_ack: Acked pending invite 102 [Dec 28 16:48:20] DEBUG[31434][C-0000007b]: chan_sip.c:4527 __sip_ack: Stopping retransmission on '46ca6204476c4b8e56716c3d109b504d@192.168.198.30:5060' of Request 102: Match Found [Dec 28 16:48:20] DEBUG[31434][C-0000007b]: chan_sip.c:23471 handle_response_invite: SIP response 200 to standard invite [Dec 28 16:48:20] DEBUG[31434][C-0000007b]: chan_sip.c:10246 process_sdp: Processing session-level SDP v=0... UNSUPPORTED OR FAILED. [Dec 28 16:48:20] DEBUG[31434][C-0000007b]: chan_sip.c:11141 process_sdp_o: Call 46ca6204476c4b8e56716c3d109b504d@192.168.198.30:5060 responded to our reinvite without changing SDP version; ignoring SDP. [Dec 28 16:48:20] DEBUG[31434][C-0000007b]: chan_sip.c:6757 update_call_counter: Updating call counter for outgoing call [Dec 28 16:48:20] DEBUG[31434][C-0000007b]: chan_sip.c:29764 parse_session_expires: Session-Expires: 1800 [Dec 28 16:48:20] DEBUG[31434][C-0000007b]: chan_sip.c:29780 parse_session_expires: Refresher: UAS [Dec 28 16:48:20] DEBUG[31434][C-0000007b]: chan_sip.c:3746 __sip_xmit: Trying to put 'ACK sip:172' onto UDP socket destined for 192.168.198.1:5060 [Dec 28 16:48:20] DEBUG[31434]: chan_sip.c:29691 __start_session_timer: Session timer started: 1 - 46ca6204476c4b8e56716c3d109b504d@192.168.198.30:5060 1768000ms [Dec 28 16:48:20] -- SIP/office-server-00000003 answered Local/917275777470@default-00000030;2 [Dec 28 16:48:20] DEBUG[839][C-0000007b]: core_unreal.c:437 unreal_queue_indicate: Blocked indication -1 [Dec 28 16:48:20] DEBUG[839][C-0000007b]: bridge_native_rtp.c:332 native_rtp_bridge_compatible: Bridge 'dd59f896-199d-452a-8f6c-4d1dfeaa6c2c' can not use native RTP bridge as two channels are required [Dec 28 16:48:20] DEBUG[839][C-0000007b]: bridge.c:506 find_best_technology: Bridge technology native_rtp is not compatible with properties of existing bridge. [Dec 28 16:48:20] DEBUG[839][C-0000007b]: bridge.c:496 find_best_technology: Bridge technology holding_bridge does not have any capabilities we want. [Dec 28 16:48:20] DEBUG[839][C-0000007b]: bridge.c:515 find_best_technology: Chose bridge technology simple_bridge [Dec 28 16:48:20] DEBUG[839][C-0000007b]: bridge.c:794 bridge_base_init: Bridge dd59f896-199d-452a-8f6c-4d1dfeaa6c2c: calling simple_bridge technology constructor [Dec 28 16:48:20] DEBUG[839][C-0000007b]: bridge.c:802 bridge_base_init: Bridge dd59f896-199d-452a-8f6c-4d1dfeaa6c2c: calling simple_bridge technology start [Dec 28 16:48:20] -- Local/917275777470@default-00000030;1 answered [Dec 28 16:48:20] DEBUG[853][C-0000007b]: bridge_channel.c:2654 bridge_channel_internal_join: Bridge dd59f896-199d-452a-8f6c-4d1dfeaa6c2c: 0x7f7b04027030(SIP/office-server-00000003) is joining [Dec 28 16:48:20] DEBUG[838][C-0000007c]: pbx.c:2875 pbx_extension_helper: Launching 'Playback' [Dec 28 16:48:20] -- Executing [8368@default:1] Playback("Local/917275777470@default-00000030;1", "sip-silence") in new stack [Dec 28 16:48:20] DEBUG[853][C-0000007b]: bridge_channel.c:2118 bridge_channel_internal_push_full: Bridge dd59f896-199d-452a-8f6c-4d1dfeaa6c2c: pushing 0x7f7b04027030(SIP/office-server-00000003) [Dec 28 16:48:20] -- Channel SIP/office-server-00000003 joined 'simple_bridge' basic-bridge [Dec 28 16:48:20] DEBUG[853][C-0000007b]: bridge.c:496 find_best_technology: Bridge technology softmix does not have any capabilities we want. [Dec 28 16:48:20] DEBUG[853][C-0000007b]: bridge_native_rtp.c:332 native_rtp_bridge_compatible: Bridge 'dd59f896-199d-452a-8f6c-4d1dfeaa6c2c' can not use native RTP bridge as two channels are required [Dec 28 16:48:20] DEBUG[853][C-0000007b]: bridge.c:506 find_best_technology: Bridge technology native_rtp is not compatible with properties of existing bridge. [Dec 28 16:48:20] DEBUG[853][C-0000007b]: bridge.c:496 find_best_technology: Bridge technology holding_bridge does not have any capabilities we want. [Dec 28 16:48:20] DEBUG[853][C-0000007b]: bridge.c:515 find_best_technology: Chose bridge technology simple_bridge [Dec 28 16:48:20] DEBUG[853][C-0000007b]: bridge.c:1046 smart_bridge_operation: Bridge dd59f896-199d-452a-8f6c-4d1dfeaa6c2c is already using the new technology. [Dec 28 16:48:20] DEBUG[853][C-0000007b]: bridge.c:432 bridge_channel_complete_join: Bridge dd59f896-199d-452a-8f6c-4d1dfeaa6c2c: 0x7f7b04027030(SIP/office-server-00000003) is joining simple_bridge technology [Dec 28 16:48:20] DEBUG[853][C-0000007b]: res_rtp_asterisk.c:3062 ast_rtp_change_source: Not changing SSRC since we haven't sent any RTP yet [Dec 28 16:48:20] DEBUG[853][C-0000007b]: bridge.c:496 find_best_technology: Bridge technology softmix does not have any capabilities we want. [Dec 28 16:48:20] DEBUG[853][C-0000007b]: bridge_native_rtp.c:332 native_rtp_bridge_compatible: Bridge 'dd59f896-199d-452a-8f6c-4d1dfeaa6c2c' can not use native RTP bridge as two channels are required [Dec 28 16:48:20] DEBUG[853][C-0000007b]: bridge.c:506 find_best_technology: Bridge technology native_rtp is not compatible with properties of existing bridge. [Dec 28 16:48:20] DEBUG[853][C-0000007b]: bridge.c:496 find_best_technology: Bridge technology holding_bridge does not have any capabilities we want. [Dec 28 16:48:20] DEBUG[853][C-0000007b]: bridge.c:515 find_best_technology: Chose bridge technology simple_bridge [Dec 28 16:48:20] DEBUG[853][C-0000007b]: bridge.c:1046 smart_bridge_operation: Bridge dd59f896-199d-452a-8f6c-4d1dfeaa6c2c is already using the new technology. [Dec 28 16:48:20] DEBUG[838][C-0000007c]: channel.c:5657 set_format: Channel Local/917275777470@default-00000030;1 setting write format path: gsm -> slin [Dec 28 16:48:20] DEBUG[838][C-0000007c]: channel.c:3461 ast_settimeout_full: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Dec 28 16:48:20] -- Playing 'sip-silence.gsm' (language 'en') [Dec 28 16:48:20] DEBUG[31554]: manager.c:5858 match_filter: Examining AMI event: Event: Newstate Privilege: call,all Channel: SIP/office-server-00000003 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 0000000000 CallerIDName: V2281648150000060018 ConnectedLineNum: 0000000000 ConnectedLineName: V2281648150000060018 Language: en AccountCode: Context: international Exten: 917275777470 Priority: 1 Uniqueid: 1482961695.191 Linkedid: 1482961695.189 [Dec 28 16:48:20] DEBUG[31417]: devicestate.c:369 _ast_device_state: No provider found, checking channel drivers for SIP - office-server [Dec 28 16:48:20] DEBUG[31417]: chan_sip.c:30154 sip_devicestate: Checking device state for peer office-server [Dec 28 16:48:20] DEBUG[31417]: devicestate.c:474 do_state_change: Changing state for SIP/office-server - state 1 (Not in use) [Dec 28 16:48:20] DEBUG[31417]: devicestate.c:369 _ast_device_state: No provider found, checking channel drivers for Local - 917275777470@default [Dec 28 16:48:20] DEBUG[31417]: devicestate.c:474 do_state_change: Changing state for Local/917275777470@default - state 2 (In use) [Dec 28 16:48:20] DEBUG[31417]: devicestate.c:369 _ast_device_state: No provider found, checking channel drivers for Local - 917275777470@default [Dec 28 16:48:20] DEBUG[31417]: devicestate.c:474 do_state_change: Changing state for Local/917275777470@default - state 2 (In use) [Dec 28 16:48:20] DEBUG[31554]: manager.c:5858 match_filter: Examining AMI event: Event: DialEnd Privilege: call,all Channel: Local/917275777470@default-00000030;2 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 0000000000 CallerIDName: V2281648150000060018 ConnectedLineNum: 0000000000 ConnectedLineName: V2281648150000060018 Language: en AccountCode: Context: default Exten: 917275777470 Priority: 2 Uniqueid: 1482961695.190 Linkedid: 1482961695.189 DestChannel: SIP/office-server-00000003 DestChannelState: 6 DestChannelStateDesc: Up DestCallerIDNum: 0000000000 DestCallerIDName: V2281648150000060018 DestConnectedLineNum: 0000000000 DestConnectedLineName: V2281648150000060018 DestLanguage: en DestAccountCode: DestContext: international DestExten: DestPriority: 1 DestUniqueid: 1482961695.191 DestLinkedid: 1482961695.189 DialStatus: ANSWER [Dec 28 16:48:20] DEBUG[839][C-0000007b]: bridge_channel.c:2654 bridge_channel_internal_join: Bridge dd59f896-199d-452a-8f6c-4d1dfeaa6c2c: 0x7f7b0400f320(Local/917275777470@default-00000030;2) is joining [Dec 28 16:48:20] DEBUG[839][C-0000007b]: bridge_channel.c:2118 bridge_channel_internal_push_full: Bridge dd59f896-199d-452a-8f6c-4d1dfeaa6c2c: pushing 0x7f7b0400f320(Local/917275777470@default-00000030;2) [Dec 28 16:48:20] DEBUG[31554]: manager.c:5858 match_filter: Examining AMI event: Event: Newstate Privilege: call,all Channel: Local/917275777470@default-00000030;2 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 0000000000 CallerIDName: V2281648150000060018 ConnectedLineNum: 0000000000 ConnectedLineName: V2281648150000060018 Language: en AccountCode: Context: default Exten: 917275777470 Priority: 2 Uniqueid: 1482961695.190 Linkedid: 1482961695.189 [Dec 28 16:48:20] -- Channel Local/917275777470@default-00000030;2 joined 'simple_bridge' basic-bridge [Dec 28 16:48:20] DEBUG[31554]: manager.c:5858 match_filter: Examining AMI event: Event: BridgeCreate Privilege: call,all BridgeUniqueid: dd59f896-199d-452a-8f6c-4d1dfeaa6c2c BridgeType: basic BridgeTechnology: simple_bridge BridgeCreator: BridgeName: BridgeNumChannels: 0 BridgeVideoSourceMode: none [Dec 28 16:48:20] DEBUG[839][C-0000007b]: bridge.c:496 find_best_technology: Bridge technology softmix does not have any capabilities we want. [Dec 28 16:48:20] DEBUG[839][C-0000007b]: bridge_native_rtp.c:338 native_rtp_bridge_compatible: Bridge 'dd59f896-199d-452a-8f6c-4d1dfeaa6c2c' can not use native RTP bridge as channel 'SIP/office-server-00000003' has features which prevent it [Dec 28 16:48:20] DEBUG[839][C-0000007b]: bridge.c:506 find_best_technology: Bridge technology native_rtp is not compatible with properties of existing bridge. [Dec 28 16:48:20] DEBUG[839][C-0000007b]: bridge.c:496 find_best_technology: Bridge technology holding_bridge does not have any capabilities we want. [Dec 28 16:48:20] DEBUG[839][C-0000007b]: bridge.c:515 find_best_technology: Chose bridge technology simple_bridge [Dec 28 16:48:20] DEBUG[839][C-0000007b]: bridge.c:1046 smart_bridge_operation: Bridge dd59f896-199d-452a-8f6c-4d1dfeaa6c2c is already using the new technology. [Dec 28 16:48:20] DEBUG[839][C-0000007b]: bridge.c:432 bridge_channel_complete_join: Bridge dd59f896-199d-452a-8f6c-4d1dfeaa6c2c: 0x7f7b0400f320(Local/917275777470@default-00000030;2) is joining simple_bridge technology [Dec 28 16:48:20] DEBUG[31419]: cdr.c:1293 cdr_object_finalize: Finalized CDR for SIP/office-server-00000003 - start 1482961695.441954 answer 1482961700.815172 end 1482961700.816357 dispo ANSWERED [Dec 28 16:48:20] DEBUG[31554]: manager.c:5858 match_filter: Examining AMI event: Event: Newstate Privilege: call,all Channel: Local/917275777470@default-00000030;1 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 0000000000 CallerIDName: V2281648150000060018 ConnectedLineNum: 0000000000 ConnectedLineName: V2281648150000060018 Language: en AccountCode: Context: default Exten: 917275777470 Priority: 1 Uniqueid: 1482961695.189 Linkedid: 1482961695.189 [Dec 28 16:48:20] DEBUG[31554]: manager.c:5858 match_filter: Examining AMI event: Event: DialEnd Privilege: call,all DestChannel: Local/917275777470@default-00000030;1 DestChannelState: 6 DestChannelStateDesc: Up DestCallerIDNum: 0000000000 DestCallerIDName: V2281648150000060018 DestConnectedLineNum: 0000000000 DestConnectedLineName: V2281648150000060018 DestLanguage: en DestAccountCode: DestContext: default DestExten: 917275777470 DestPriority: 1 DestUniqueid: 1482961695.189 DestLinkedid: 1482961695.189 DialStatus: ANSWER [Dec 28 16:48:20] DEBUG[853][C-0000007b]: res_rtp_asterisk.c:3601 ast_rtp_write: Ooh, format changed from none to gsm [Dec 28 16:48:20] DEBUG[31554]: manager.c:5858 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/office-server-00000003 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 0000000000 CallerIDName: V2281648150000060018 ConnectedLineNum: 0000000000 ConnectedLineName: V2281648150000060018 Language: en AccountCode: Context: international Exten: Priority: 1 Uniqueid: 1482961695.191 Linkedid: 1482961695.189 Extension: Application: AppDial AppData: (Outgoing Line) [Dec 28 16:48:20] DEBUG[31554]: manager.c:5858 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: Local/917275777470@default-00000030;1 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 0000000000 CallerIDName: V2281648150000060018 ConnectedLineNum: 0000000000 ConnectedLineName: V2281648150000060018 Language: en AccountCode: Context: default Exten: 8368 Priority: 1 Uniqueid: 1482961695.189 Linkedid: 1482961695.189 Extension: 8368 Application: Playback AppData: sip-silence [Dec 28 16:48:20] DEBUG[853][C-0000007b]: res_rtp_asterisk.c:3446 ast_rtp_raw_write: Starting RTCP transmission on RTP instance '0x7f7b04005c50' [Dec 28 16:48:20] DEBUG[31554]: manager.c:5858 match_filter: Examining AMI event: Event: BridgeEnter Privilege: call,all BridgeUniqueid: dd59f896-199d-452a-8f6c-4d1dfeaa6c2c BridgeType: basic BridgeTechnology: simple_bridge BridgeCreator: BridgeName: BridgeNumChannels: 1 BridgeVideoSourceMode: none Channel: SIP/office-server-00000003 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 0000000000 CallerIDName: V2281648150000060018 ConnectedLineNum: 0000000000 ConnectedLineName: V2281648150000060018 Language: en AccountCode: Context: international Exten: Priority: 1 Uniqueid: 1482961695.191 Linkedid: 1482961695.189 [Dec 28 16:48:20] DEBUG[31554]: manager.c:5858 match_filter: Examining AMI event: Event: DeviceStateChange Privilege: call,all Device: Local/917275777470@default State: INUSE [Dec 28 16:48:20] DEBUG[31554]: manager.c:5858 match_filter: Examining AMI event: Event: DeviceStateChange Privilege: call,all Device: Local/917275777470@default State: INUSE [Dec 28 16:48:20] DEBUG[31554]: manager.c:5858 match_filter: Examining AMI event: Event: BridgeEnter Privilege: call,all BridgeUniqueid: dd59f896-199d-452a-8f6c-4d1dfeaa6c2c BridgeType: basic BridgeTechnology: simple_bridge BridgeCreator: BridgeName: BridgeNumChannels: 2 BridgeVideoSourceMode: none Channel: Local/917275777470@default-00000030;2 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 0000000000 CallerIDName: V2281648150000060018 ConnectedLineNum: 0000000000 ConnectedLineName: V2281648150000060018 Language: en AccountCode: Context: default Exten: 917275777470 Priority: 2 Uniqueid: 1482961695.190 Linkedid: 1482961695.189 [Dec 28 16:48:20] DEBUG[838][C-0000007c]: channel.c:3461 ast_settimeout_full: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Dec 28 16:48:20] DEBUG[838][C-0000007c]: channel.c:3461 ast_settimeout_full: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Dec 28 16:48:20] DEBUG[838][C-0000007c]: channel.c:3461 ast_settimeout_full: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Dec 28 16:48:20] DEBUG[838][C-0000007c]: channel.c:5657 set_format: Channel Local/917275777470@default-00000030;1 setting write format path: slin -> slin [Dec 28 16:48:20] DEBUG[838][C-0000007c]: pbx.c:2875 pbx_extension_helper: Launching 'Wait' [Dec 28 16:48:20] -- Executing [8368@default:2] Wait("Local/917275777470@default-00000030;1", "30") in new stack [Dec 28 16:48:20] DEBUG[31554]: manager.c:5858 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: Local/917275777470@default-00000030;1 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 0000000000 CallerIDName: V2281648150000060018 ConnectedLineNum: 0000000000 ConnectedLineName: V2281648150000060018 Language: en AccountCode: Context: default Exten: 8368 Priority: 2 Uniqueid: 1482961695.189 Linkedid: 1482961695.189 Extension: 8368 Application: Wait AppData: 30 [Dec 28 16:48:21] DEBUG[31543]: manager.c:6313 process_message: Running action 'Command' [Dec 28 16:48:21] DEBUG[853][C-0000007b]: res_rtp_asterisk.c:4519 ast_rtp_read: 0x7f7b0400a110 -- Probation learning mode pass with source address 192.168.198.1:11498 [Dec 28 16:48:21] > 0x7f7b0400a110 -- Probation passed - setting RTP source address to 192.168.198.1:11498 [Dec 28 16:48:21] DEBUG[31543]: manager.c:6313 process_message: Running action 'Command' [Dec 28 16:48:21] DEBUG[837]: manager.c:6313 process_message: Running action 'Logoff' [Dec 28 16:48:21] == Manager 'sendcron' logged off from 127.0.0.1 [Dec 28 16:48:21] DEBUG[31543]: manager.c:6313 process_message: Running action 'Command' [Dec 28 16:48:21] DEBUG[31437]: chan_iax2.c:2715 peercnt_remove: ip callno count decremented to 8 for 127.0.0.1 [Dec 28 16:48:21] DEBUG[31450]: chan_iax2.c:2683 peercnt_add: ip callno count incremented to 9 for 127.0.0.1 [Dec 28 16:48:21] DEBUG[31441]: chan_iax2.c:3083 sched_delay_remove: schedule decrement of callno used for 127.0.0.1 in 60 seconds [Dec 28 16:48:21] DEBUG[31441]: chan_iax2.c:11177 socket_process_helper: Peer ASTloop: got pong, lastms 3, historicms 3, maxms 2000 [Dec 28 16:48:22] DEBUG[31543]: manager.c:6313 process_message: Running action 'Command' [Dec 28 16:48:22] DEBUG[31543]: manager.c:6313 process_message: Running action 'Command' [Dec 28 16:48:23] DEBUG[31543]: manager.c:6313 process_message: Running action 'Command' [Dec 28 16:48:23] DEBUG[31543]: manager.c:6313 process_message: Running action 'Command' [Dec 28 16:48:23] DEBUG[31543]: manager.c:6313 process_message: Running action 'Command' [Dec 28 16:48:24] DEBUG[31543]: manager.c:6313 process_message: Running action 'Command' [Dec 28 16:48:24] DEBUG[31543]: manager.c:6313 process_message: Running action 'Command' [Dec 28 16:48:25] DEBUG[31543]: manager.c:6313 process_message: Running action 'Command' [Dec 28 16:48:25] DEBUG[31543]: manager.c:6313 process_message: Running action 'Command' [Dec 28 16:48:25] DEBUG[31495]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.198.30:17307' into... [Dec 28 16:48:25] DEBUG[31495]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.198.30' and port '17307'. [Dec 28 16:48:25] DEBUG[31495]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.198.1:11499' into... [Dec 28 16:48:25] DEBUG[31495]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.198.1' and port '11499'. [Dec 28 16:48:25] DEBUG[853][C-0000007b]: res_rtp_asterisk.c:4167 ast_rtcp_read: Got RTCP report of 64 bytes [Dec 28 16:48:25] DEBUG[31495]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.198.1:11499' into... [Dec 28 16:48:25] DEBUG[31495]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.198.1' and port '11499'. [Dec 28 16:48:25] DEBUG[31495]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.198.30:17307' into... [Dec 28 16:48:25] DEBUG[31495]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.198.30' and port '17307'. [Dec 28 16:48:26] DEBUG[31543]: manager.c:6313 process_message: Running action 'Command' [Dec 28 16:48:26] DEBUG[31543]: manager.c:6313 process_message: Running action 'Command' [Dec 28 16:48:26] DEBUG[31452]: chan_iax2.c:12178 iax2_do_register: Allocate call number [Dec 28 16:48:26] DEBUG[31452]: chan_iax2.c:2683 peercnt_add: ip callno count incremented to 10 for 127.0.0.1 [Dec 28 16:48:26] DEBUG[31452]: chan_iax2.c:12185 iax2_do_register: Registration created on call 14868 [Dec 28 16:48:26] DEBUG[31449]: chan_iax2.c:2683 peercnt_add: ip callno count incremented to 11 for 127.0.0.1 [Dec 28 16:48:26] DEBUG[31417]: devicestate.c:369 _ast_device_state: No provider found, checking channel drivers for IAX2 - ASTblind [Dec 28 16:48:26] DEBUG[31417]: chan_iax2.c:14492 iax2_devicestate: Checking device state for device ASTblind [Dec 28 16:48:26] DEBUG[31417]: chan_iax2.c:14501 iax2_devicestate: Found peer. What's device state of ASTblind? addr=127.0.0.1:50835, defaddr=(null) maxms=2000, lastms=1 [Dec 28 16:48:26] DEBUG[31417]: devicestate.c:474 do_state_change: Changing state for IAX2/ASTblind - state 0 (Unknown) [Dec 28 16:48:26] DEBUG[31417]: devicestate.c:369 _ast_device_state: No provider found, checking channel drivers for IAX2 - ASTblind [Dec 28 16:48:26] DEBUG[31417]: chan_iax2.c:14492 iax2_devicestate: Checking device state for device ASTblind [Dec 28 16:48:26] DEBUG[31417]: chan_iax2.c:14501 iax2_devicestate: Found peer. What's device state of ASTblind? addr=127.0.0.1:50835, defaddr=(null) maxms=2000, lastms=1 [Dec 28 16:48:26] DEBUG[31417]: devicestate.c:474 do_state_change: Changing state for IAX2/ASTblind - state 0 (Unknown) [Dec 28 16:48:26] DEBUG[31474]: chan_iax2.c:3083 sched_delay_remove: schedule decrement of callno used for 127.0.0.1 in 60 seconds [Dec 28 16:48:26] DEBUG[31475]: chan_iax2.c:3083 sched_delay_remove: schedule decrement of callno used for 127.0.0.1 in 60 seconds [Dec 28 16:48:26] DEBUG[31543]: manager.c:6313 process_message: Running action 'Command' [Dec 28 16:48:27] DEBUG[31543]: manager.c:6313 process_message: Running action 'Command' [Dec 28 16:48:27] DEBUG[31543]: manager.c:6313 process_message: Running action 'Command' [Dec 28 16:48:28] DEBUG[31543]: manager.c:6313 process_message: Running action 'Command' [Dec 28 16:48:28] DEBUG[31543]: manager.c:6313 process_message: Running action 'Command' [Dec 28 16:48:28] DEBUG[31456]: chan_iax2.c:12178 iax2_do_register: Allocate call number [Dec 28 16:48:28] DEBUG[31456]: chan_iax2.c:2683 peercnt_add: ip callno count incremented to 12 for 127.0.0.1 [Dec 28 16:48:28] DEBUG[31456]: chan_iax2.c:12185 iax2_do_register: Registration created on call 10112 [Dec 28 16:48:28] DEBUG[31463]: chan_iax2.c:2683 peercnt_add: ip callno count incremented to 13 for 127.0.0.1 [Dec 28 16:48:28] DEBUG[31417]: devicestate.c:369 _ast_device_state: No provider found, checking channel drivers for IAX2 - ASTplay [Dec 28 16:48:28] DEBUG[31417]: chan_iax2.c:14492 iax2_devicestate: Checking device state for device ASTplay [Dec 28 16:48:28] DEBUG[31417]: chan_iax2.c:14501 iax2_devicestate: Found peer. What's device state of ASTplay? addr=127.0.0.1:30053, defaddr=(null) maxms=2000, lastms=3 [Dec 28 16:48:28] DEBUG[31417]: devicestate.c:474 do_state_change: Changing state for IAX2/ASTplay - state 0 (Unknown) [Dec 28 16:48:28] DEBUG[31417]: devicestate.c:369 _ast_device_state: No provider found, checking channel drivers for IAX2 - ASTplay [Dec 28 16:48:28] DEBUG[31417]: chan_iax2.c:14492 iax2_devicestate: Checking device state for device ASTplay [Dec 28 16:48:28] DEBUG[31417]: chan_iax2.c:14501 iax2_devicestate: Found peer. What's device state of ASTplay? addr=127.0.0.1:30053, defaddr=(null) maxms=2000, lastms=3 [Dec 28 16:48:28] DEBUG[31417]: devicestate.c:474 do_state_change: Changing state for IAX2/ASTplay - state 0 (Unknown) [Dec 28 16:48:28] DEBUG[31472]: chan_iax2.c:3083 sched_delay_remove: schedule decrement of callno used for 127.0.0.1 in 60 seconds [Dec 28 16:48:28] DEBUG[31483]: chan_iax2.c:3083 sched_delay_remove: schedule decrement of callno used for 127.0.0.1 in 60 seconds [Dec 28 16:48:28] DEBUG[31482]: chan_iax2.c:12178 iax2_do_register: Allocate call number [Dec 28 16:48:28] DEBUG[31482]: chan_iax2.c:2683 peercnt_add: ip callno count incremented to 14 for 127.0.0.1 [Dec 28 16:48:28] DEBUG[31482]: chan_iax2.c:12185 iax2_do_register: Registration created on call 12559 [Dec 28 16:48:28] DEBUG[31469]: chan_iax2.c:2683 peercnt_add: ip callno count incremented to 15 for 127.0.0.1 [Dec 28 16:48:28] DEBUG[31417]: devicestate.c:369 _ast_device_state: No provider found, checking channel drivers for IAX2 - ASTloop [Dec 28 16:48:28] DEBUG[31417]: chan_iax2.c:14492 iax2_devicestate: Checking device state for device ASTloop [Dec 28 16:48:28] DEBUG[31417]: chan_iax2.c:14501 iax2_devicestate: Found peer. What's device state of ASTloop? addr=127.0.0.1:13787, defaddr=(null) maxms=2000, lastms=3 [Dec 28 16:48:28] DEBUG[31417]: devicestate.c:474 do_state_change: Changing state for IAX2/ASTloop - state 0 (Unknown) [Dec 28 16:48:28] DEBUG[31417]: devicestate.c:369 _ast_device_state: No provider found, checking channel drivers for IAX2 - ASTloop [Dec 28 16:48:28] DEBUG[31417]: chan_iax2.c:14492 iax2_devicestate: Checking device state for device ASTloop [Dec 28 16:48:28] DEBUG[31417]: chan_iax2.c:14501 iax2_devicestate: Found peer. What's device state of ASTloop? addr=127.0.0.1:13787, defaddr=(null) maxms=2000, lastms=3 [Dec 28 16:48:28] DEBUG[31417]: devicestate.c:474 do_state_change: Changing state for IAX2/ASTloop - state 0 (Unknown) [Dec 28 16:48:28] DEBUG[31473]: chan_iax2.c:3083 sched_delay_remove: schedule decrement of callno used for 127.0.0.1 in 60 seconds [Dec 28 16:48:28] DEBUG[31486]: chan_iax2.c:3083 sched_delay_remove: schedule decrement of callno used for 127.0.0.1 in 60 seconds [Dec 28 16:48:28] DEBUG[31543]: manager.c:6313 process_message: Running action 'Command' [Dec 28 16:48:29] DEBUG[31543]: manager.c:6313 process_message: Running action 'Command' [Dec 28 16:48:29] DEBUG[31543]: manager.c:6313 process_message: Running action 'Command' [Dec 28 16:48:30] DEBUG[31543]: manager.c:6313 process_message: Running action 'Command' [Dec 28 16:48:30] DEBUG[31543]: manager.c:6313 process_message: Running action 'Command' [Dec 28 16:48:30] DEBUG[31495]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.198.30:17307' into... [Dec 28 16:48:30] DEBUG[31495]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.198.30' and port '17307'. [Dec 28 16:48:30] DEBUG[31495]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.198.1:11499' into... [Dec 28 16:48:30] DEBUG[31495]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.198.1' and port '11499'. [Dec 28 16:48:30] DEBUG[853][C-0000007b]: res_rtp_asterisk.c:4167 ast_rtcp_read: Got RTCP report of 64 bytes [Dec 28 16:48:30] DEBUG[31495]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.198.1:11499' into... [Dec 28 16:48:30] DEBUG[31495]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.198.1' and port '11499'. [Dec 28 16:48:30] DEBUG[31495]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.198.30:17307' into... [Dec 28 16:48:30] DEBUG[31495]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.198.30' and port '17307'. [Dec 28 16:48:30] DEBUG[31543]: manager.c:6313 process_message: Running action 'Command' [Dec 28 16:48:31] DEBUG[31543]: manager.c:6313 process_message: Running action 'Command' [Dec 28 16:48:31] DEBUG[31543]: manager.c:6313 process_message: Running action 'Command' [Dec 28 16:48:32] DEBUG[31543]: manager.c:6313 process_message: Running action 'Command' [Dec 28 16:48:32] DEBUG[31543]: manager.c:6313 process_message: Running action 'Command' [Dec 28 16:48:32] DEBUG[31543]: manager.c:6313 process_message: Running action 'Command' [Dec 28 16:48:33] DEBUG[31543]: manager.c:6313 process_message: Running action 'Command' [Dec 28 16:48:33] DEBUG[31543]: manager.c:6313 process_message: Running action 'Command' [Dec 28 16:48:34] DEBUG[31543]: manager.c:6313 process_message: Running action 'Command' [Dec 28 16:48:34] DEBUG[31543]: manager.c:6313 process_message: Running action 'Command' [Dec 28 16:48:34] DEBUG[31543]: manager.c:6313 process_message: Running action 'Command' [Dec 28 16:48:35] DEBUG[31543]: manager.c:6313 process_message: Running action 'Command' [Dec 28 16:48:35] DEBUG[31543]: manager.c:6313 process_message: Running action 'Command' [Dec 28 16:48:35] DEBUG[31495]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.198.30:17307' into... [Dec 28 16:48:35] DEBUG[31495]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.198.30' and port '17307'. [Dec 28 16:48:35] DEBUG[31495]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.198.1:11499' into... [Dec 28 16:48:35] DEBUG[31495]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.198.1' and port '11499'. [Dec 28 16:48:35] DEBUG[853][C-0000007b]: res_rtp_asterisk.c:4167 ast_rtcp_read: Got RTCP report of 64 bytes [Dec 28 16:48:35] DEBUG[31495]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.198.1:11499' into... [Dec 28 16:48:35] DEBUG[31495]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.198.1' and port '11499'. [Dec 28 16:48:35] DEBUG[31495]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.198.30:17307' into... [Dec 28 16:48:35] DEBUG[31495]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.198.30' and port '17307'. [Dec 28 16:48:36] DEBUG[31543]: manager.c:6313 process_message: Running action 'Command' [Dec 28 16:48:36] DEBUG[31543]: manager.c:6313 process_message: Running action 'Command' [Dec 28 16:48:36] DEBUG[31437]: chan_iax2.c:2715 peercnt_remove: ip callno count decremented to 14 for 127.0.0.1 [Dec 28 16:48:36] DEBUG[31437]: chan_iax2.c:2715 peercnt_remove: ip callno count decremented to 13 for 127.0.0.1 [Dec 28 16:48:36] DEBUG[31543]: manager.c:6313 process_message: Running action 'Command' [Dec 28 16:48:37] DEBUG[31543]: manager.c:6313 process_message: Running action 'Command' [Dec 28 16:48:37] DEBUG[31543]: manager.c:6313 process_message: Running action 'Command' [Dec 28 16:48:38] DEBUG[31543]: manager.c:6313 process_message: Running action 'Command' [Dec 28 16:48:38] DEBUG[31543]: manager.c:6313 process_message: Running action 'Command' [Dec 28 16:48:38] DEBUG[31437]: chan_iax2.c:2715 peercnt_remove: ip callno count decremented to 12 for 127.0.0.1 [Dec 28 16:48:38] DEBUG[31437]: chan_iax2.c:2715 peercnt_remove: ip callno count decremented to 11 for 127.0.0.1 [Dec 28 16:48:38] DEBUG[31437]: chan_iax2.c:2715 peercnt_remove: ip callno count decremented to 10 for 127.0.0.1 [Dec 28 16:48:38] DEBUG[31437]: chan_iax2.c:2715 peercnt_remove: ip callno count decremented to 9 for 127.0.0.1 [Dec 28 16:48:38] DEBUG[31543]: manager.c:6313 process_message: Running action 'Command' [Dec 28 16:48:39] DEBUG[31543]: manager.c:6313 process_message: Running action 'Command' [Dec 28 16:48:39] DEBUG[31543]: manager.c:6313 process_message: Running action 'Command' [Dec 28 16:48:40] DEBUG[31543]: manager.c:6313 process_message: Running action 'Command' [Dec 28 16:48:40] DEBUG[31543]: manager.c:6313 process_message: Running action 'Command' [Dec 28 16:48:40] DEBUG[31495]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.198.30:17307' into... [Dec 28 16:48:40] DEBUG[31495]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.198.30' and port '17307'. [Dec 28 16:48:40] DEBUG[31495]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.198.1:11499' into... [Dec 28 16:48:40] DEBUG[31495]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.198.1' and port '11499'. [Dec 28 16:48:40] DEBUG[841]: threadpool.c:1137 worker_idle: Worker thread idle timeout reached. Dying. [Dec 28 16:48:40] DEBUG[31406]: threadpool.c:996 worker_thread_destroy: Destroying worker thread 11 [Dec 28 16:48:40] DEBUG[853][C-0000007b]: res_rtp_asterisk.c:4167 ast_rtcp_read: Got RTCP report of 64 bytes [Dec 28 16:48:40] DEBUG[31495]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.198.1:11499' into... [Dec 28 16:48:40] DEBUG[31495]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.198.1' and port '11499'. [Dec 28 16:48:40] DEBUG[31495]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.198.30:17307' into... [Dec 28 16:48:40] DEBUG[31495]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.198.30' and port '17307'. [Dec 28 16:48:40] DEBUG[31543]: manager.c:6313 process_message: Running action 'Command' [Dec 28 16:48:41] DEBUG[31543]: manager.c:6313 process_message: Running action 'Command' [Dec 28 16:48:41] DEBUG[31543]: manager.c:6313 process_message: Running action 'Command' [Dec 28 16:48:42] DEBUG[31543]: manager.c:6313 process_message: Running action 'Command' [Dec 28 16:48:42] DEBUG[31543]: manager.c:6313 process_message: Running action 'Command' [Dec 28 16:48:42] DEBUG[31543]: manager.c:6313 process_message: Running action 'Command' [Dec 28 16:48:43] DEBUG[31543]: manager.c:6313 process_message: Running action 'Command' [Dec 28 16:48:43] DEBUG[31543]: manager.c:6313 process_message: Running action 'Command' [Dec 28 16:48:44] DEBUG[31543]: manager.c:6313 process_message: Running action 'Command' [Dec 28 16:48:44] DEBUG[31543]: manager.c:6313 process_message: Running action 'Command' [Dec 28 16:48:44] DEBUG[31543]: manager.c:6313 process_message: Running action 'Command' [Dec 28 16:48:45] DEBUG[31543]: manager.c:6313 process_message: Running action 'Command' [Dec 28 16:48:45] DEBUG[31543]: manager.c:6313 process_message: Running action 'Command' [Dec 28 16:48:45] DEBUG[31495]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.198.30:17307' into... [Dec 28 16:48:45] DEBUG[31495]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.198.30' and port '17307'. [Dec 28 16:48:45] DEBUG[31495]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.198.1:11499' into... [Dec 28 16:48:45] DEBUG[31495]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.198.1' and port '11499'. [Dec 28 16:48:45] DEBUG[853][C-0000007b]: res_rtp_asterisk.c:4167 ast_rtcp_read: Got RTCP report of 64 bytes [Dec 28 16:48:45] DEBUG[31495]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.198.1:11499' into... [Dec 28 16:48:45] DEBUG[31495]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.198.1' and port '11499'. [Dec 28 16:48:45] DEBUG[31495]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.198.30:17307' into... [Dec 28 16:48:45] DEBUG[31495]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.198.30' and port '17307'. [Dec 28 16:48:46] DEBUG[31554]: manager.c:6313 process_message: Running action 'Command' [Dec 28 16:48:46] DEBUG[31543]: manager.c:6313 process_message: Running action 'Command' [Dec 28 16:48:46] DEBUG[31434]: chan_sip.c:9394 __find_call: = Looking for Call ID: 76a33c6047891df574eaf689226f84b3@192.168.198.1:5060 (Checking From) --From tag as25213d5e --To-tag [Dec 28 16:48:46] DEBUG[31434]: acl.c:946 ast_ouraddrfor: For destination '192.168.198.1', our source address is '192.168.198.30'. [Dec 28 16:48:46] DEBUG[31434]: chan_sip.c:3903 ast_sip_ouraddrfor: Setting AST_TRANSPORT_UDP with address 192.168.198.30:5060 [Dec 28 16:48:46] DEBUG[31434]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.198.1:5060' into... [Dec 28 16:48:46] DEBUG[31434]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.198.1' and port '5060'. [Dec 28 16:48:46] DEBUG[31434]: chan_sip.c:8981 __sip_alloc: Allocating new SIP dialog for 76a33c6047891df574eaf689226f84b3@192.168.198.1:5060 - OPTIONS (No RTP) [Dec 28 16:48:46] DEBUG[31434]: chan_sip.c:28628 handle_incoming: **** Received OPTIONS (3) - Command in SIP OPTIONS [Dec 28 16:48:46] DEBUG[31434]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.198.30' into... [Dec 28 16:48:46] DEBUG[31434]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.198.30' and port ''. [Dec 28 16:48:46] DEBUG[31434]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.198.1' into... [Dec 28 16:48:46] DEBUG[31434]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.198.1' and port ''. [Dec 28 16:48:46] DEBUG[31434]: chan_sip.c:3746 __sip_xmit: Trying to put 'SIP/2.0 404' onto UDP socket destined for 192.168.198.1:5060 [Dec 28 16:48:46] DEBUG[31543]: manager.c:6313 process_message: Running action 'Command' [Dec 28 16:48:46] DEBUG[31543]: manager.c:6313 process_message: Running action 'Command' [Dec 28 16:48:47] DEBUG[31543]: manager.c:6313 process_message: Running action 'Command' [Dec 28 16:48:47] DEBUG[31543]: manager.c:6313 process_message: Running action 'Command' [Dec 28 16:48:48] DEBUG[31543]: manager.c:6313 process_message: Running action 'Command' [Dec 28 16:48:48] DEBUG[31543]: manager.c:6313 process_message: Running action 'Command' [Dec 28 16:48:48] DEBUG[31543]: manager.c:6313 process_message: Running action 'Command' [Dec 28 16:48:49] DEBUG[31543]: manager.c:6313 process_message: Running action 'Command' [Dec 28 16:48:49] DEBUG[31543]: manager.c:6313 process_message: Running action 'Command' [Dec 28 16:48:50] DEBUG[31543]: manager.c:6313 process_message: Running action 'Command' [Dec 28 16:48:50] DEBUG[31543]: manager.c:6313 process_message: Running action 'Command' [Dec 28 16:48:50] DEBUG[31495]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.198.30:17307' into... [Dec 28 16:48:50] DEBUG[31495]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.198.30' and port '17307'. [Dec 28 16:48:50] DEBUG[31495]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.198.1:11499' into... [Dec 28 16:48:50] DEBUG[31495]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.198.1' and port '11499'. [Dec 28 16:48:50] DEBUG[853][C-0000007b]: res_rtp_asterisk.c:4167 ast_rtcp_read: Got RTCP report of 64 bytes [Dec 28 16:48:50] DEBUG[31495]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.198.1:11499' into... [Dec 28 16:48:50] DEBUG[31495]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.198.1' and port '11499'. [Dec 28 16:48:50] DEBUG[31495]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '192.168.198.30:17307' into... [Dec 28 16:48:50] DEBUG[31495]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '192.168.198.30' and port '17307'. [Dec 28 16:48:50] DEBUG[838][C-0000007c]: pbx.c:2875 pbx_extension_helper: Launching 'DumpChan' [Dec 28 16:48:50] -- Executing [8368@default:3] DumpChan("Local/917275777470@default-00000030;1", "") in new stack [Dec 28 16:48:50] [Dec 28 16:48:50] Dumping Info For Channel: Local/917275777470@default-00000030;1: [Dec 28 16:48:50] ================================================================================ [Dec 28 16:48:50] Info: [Dec 28 16:48:50] Name= Local/917275777470@default-00000030;1 [Dec 28 16:48:50] Type= Local [Dec 28 16:48:50] UniqueID= 1482961695.189 [Dec 28 16:48:50] LinkedID= 1482961695.189 [Dec 28 16:48:50] CallerIDNum= 0000000000 [Dec 28 16:48:50] CallerIDName= V2281648150000060018 [Dec 28 16:48:50] ConnectedLineIDNum= 0000000000 [Dec 28 16:48:50] ConnectedLineIDName=V2281648150000060018 [Dec 28 16:48:50] DNIDDigits= (N/A) [Dec 28 16:48:50] RDNIS= (N/A) [Dec 28 16:48:50] Parkinglot= [Dec 28 16:48:50] Language= en [Dec 28 16:48:50] State= Up (6) [Dec 28 16:48:50] Rings= 0 [Dec 28 16:48:50] NativeFormat= (slin) [Dec 28 16:48:50] WriteFormat= slin [Dec 28 16:48:50] ReadFormat= slin [Dec 28 16:48:50] RawWriteFormat= slin [Dec 28 16:48:50] RawReadFormat= slin [Dec 28 16:48:50] WriteTranscode= No [Dec 28 16:48:50] ReadTranscode= No [Dec 28 16:48:50] 1stFileDescriptor= -1 [Dec 28 16:48:50] Framesin= 1484 [Dec 28 16:48:50] Framesout= 1 [Dec 28 16:48:50] TimetoHangup= 0 [Dec 28 16:48:50] ElapsedTime= 0h0m35s [Dec 28 16:48:50] BridgeID= (Not bridged) [Dec 28 16:48:50] Context= default [Dec 28 16:48:50] Extension= 8368 [Dec 28 16:48:50] Priority= 3 [Dec 28 16:48:50] CallGroup= [Dec 28 16:48:50] PickupGroup= [Dec 28 16:48:50] Application= DumpChan [Dec 28 16:48:50] Data= (Empty) [Dec 28 16:48:50] Blocking_in= (Not Blocking) [Dec 28 16:48:50] [Dec 28 16:48:50] Variables: [Dec 28 16:48:50] PLAYBACKSTATUS=SUCCESS [Dec 28 16:48:50] ================================================================================ [Dec 28 16:48:50] DEBUG[838][C-0000007c]: pbx.c:2875 pbx_extension_helper: Launching 'AGI' [Dec 28 16:48:50] -- Executing [8368@default:4] AGI("Local/917275777470@default-00000030;1", "agi://127.0.0.1:4577/call_log") in new stack [Dec 28 16:48:50] DEBUG[838][C-0000007c]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '127.0.0.1:4577' into... [Dec 28 16:48:50] DEBUG[31554]: manager.c:5858 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: Local/917275777470@default-00000030;1 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 0000000000 CallerIDName: V2281648150000060018 ConnectedLineNum: 0000000000 ConnectedLineName: V2281648150000060018 Language: en AccountCode: Context: default Exten: 8368 Priority: 3 Uniqueid: 1482961695.189 Linkedid: 1482961695.189 Extension: 8368 Application: DumpChan AppData: [Dec 28 16:48:50] DEBUG[838][C-0000007c]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '127.0.0.1' and port '4577'. [Dec 28 16:48:50] DEBUG[838][C-0000007c]: res_agi.c:2105 launch_netscript: Wow, connected! [Dec 28 16:48:50] DEBUG[31554]: manager.c:5858 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: Local/917275777470@default-00000030;1 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 0000000000 CallerIDName: V2281648150000060018 ConnectedLineNum: 0000000000 ConnectedLineName: V2281648150000060018 Language: en AccountCode: Context: default Exten: 8368 Priority: 4 Uniqueid: 1482961695.189 Linkedid: 1482961695.189 Extension: 8368 Application: AGI AppData: agi://127.0.0.1:4577/call_log [Dec 28 16:48:50] -- AGI Script Executing Application: (EXEC) Options: (Set(_CAMPCUST=TESTCAMP)) [Dec 28 16:48:50] -- AGI Script agi://127.0.0.1:4577/call_log completed, returning 0 [Dec 28 16:48:50] DEBUG[838][C-0000007c]: pbx.c:2875 pbx_extension_helper: Launching 'AGI' [Dec 28 16:48:50] -- Executing [8368@default:5] AGI("Local/917275777470@default-00000030;1", "agi-VDAD_ALL_outbound.agi,NORMAL-----LB") in new stack [Dec 28 16:48:50] DEBUG[31554]: manager.c:5858 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: Local/917275777470@default-00000030;1 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 0000000000 CallerIDName: V2281648150000060018 ConnectedLineNum: 0000000000 ConnectedLineName: V2281648150000060018 Language: en AccountCode: Context: default Exten: 8368 Priority: 5 Uniqueid: 1482961695.189 Linkedid: 1482961695.189 Extension: 8368 Application: AGI AppData: agi-VDAD_ALL_outbound.agi,NORMAL-----LB [Dec 28 16:48:50] -- Launched AGI Script /var/lib/asterisk/agi-bin/agi-VDAD_ALL_outbound.agi [Dec 28 16:48:50] DEBUG[31554]: manager.c:5858 match_filter: Examining AMI event: Event: NewCallerid Privilege: call,all Channel: Local/917275777470@default-00000030;1 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: CallerIDName: V2281648150000060018 ConnectedLineNum: 0000000000 ConnectedLineName: V2281648150000060018 Language: en AccountCode: Context: default Exten: 8368 Priority: 5 Uniqueid: 1482961695.189 Linkedid: 1482961695.189 CID-CallingPres: 0 (Presentation Allowed, Not Screened) [Dec 28 16:48:50] DEBUG[31543]: manager.c:6313 process_message: Running action 'Command' [Dec 28 16:48:51] DEBUG[31543]: manager.c:6313 process_message: Running action 'Command' [Dec 28 16:48:51] DEBUG[31543]: manager.c:6313 process_message: Running action 'Command' [Dec 28 16:48:51] -- AGI Script agi-VDAD_ALL_outbound.agi completed, returning 0 [Dec 28 16:48:51] DEBUG[838][C-0000007c]: pbx.c:2875 pbx_extension_helper: Launching 'AGI' [Dec 28 16:48:51] -- Executing [8368@default:6] AGI("Local/917275777470@default-00000030;1", "agi-VDAD_ALL_outbound.agi,NORMAL-----LB") in new stack [Dec 28 16:48:51] -- Launched AGI Script /var/lib/asterisk/agi-bin/agi-VDAD_ALL_outbound.agi [Dec 28 16:48:51] DEBUG[31554]: manager.c:5858 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: Local/917275777470@default-00000030;1 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: CallerIDName: V2281648150000060018 ConnectedLineNum: 0000000000 ConnectedLineName: V2281648150000060018 Language: en AccountCode: Context: default Exten: 8368 Priority: 6 Uniqueid: 1482961695.189 Linkedid: 1482961695.189 Extension: 8368 Application: AGI AppData: agi-VDAD_ALL_outbound.agi,NORMAL-----LB [Dec 28 16:48:52] DEBUG[31543]: manager.c:6313 process_message: Running action 'Command' [Dec 28 16:48:52] DEBUG[31543]: manager.c:6313 process_message: Running action 'Command' [Dec 28 16:48:52] DEBUG[31543]: manager.c:6313 process_message: Running action 'Command' DBD::mysql::db do failed: Duplicate entry '1482961695.189' for key 'PRIMARY' at /var/lib/asterisk/agi-bin/agi-VDAD_ALL_outbound.agi line 452, line 23. DBD::mysql::db do failed: Duplicate entry '1482961695.189' for key 'PRIMARY' at /var/lib/asterisk/agi-bin/agi-VDAD_ALL_outbound.agi line 458, line 23. [Dec 28 16:48:53] -- AGI Script agi-VDAD_ALL_outbound.agi completed, returning 0 [Dec 28 16:48:53] DEBUG[838][C-0000007c]: pbx.c:2875 pbx_extension_helper: Launching 'Hangup' [Dec 28 16:48:53] -- Executing [8368@default:7] Hangup("Local/917275777470@default-00000030;1", "") in new stack [Dec 28 16:48:53] DEBUG[838][C-0000007c]: channel.c:2571 ast_softhangup_nolock: Soft-Hanging (0x20) up channel 'Local/917275777470@default-00000030;1' [Dec 28 16:48:53] DEBUG[838][C-0000007c]: pbx.c:4346 __ast_pbx_run: Spawn extension (default,8368,7) exited non-zero on 'Local/917275777470@default-00000030;1' [Dec 28 16:48:53] == Spawn extension (default, 8368, 7) exited non-zero on 'Local/917275777470@default-00000030;1' [Dec 28 16:48:53] DEBUG[838][C-0000007c]: channel.c:2571 ast_softhangup_nolock: Soft-Hanging (0x10) up channel 'Local/917275777470@default-00000030;1' [Dec 28 16:48:53] DEBUG[838][C-0000007c]: channel.c:2571 ast_softhangup_nolock: Soft-Hanging (0x80) up channel 'Local/917275777470@default-00000030;1' [Dec 28 16:48:53] DEBUG[838][C-0000007c]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'HANGUPCAUSE' is '16' [Dec 28 16:48:53] DEBUG[838][C-0000007c]: pbx_variables.c:378 ast_str_retrieve_variable: Result of 'DIALSTATUS' is NULL [Dec 28 16:48:53] DEBUG[838][C-0000007c]: pbx_variables.c:378 ast_str_retrieve_variable: Result of 'DIALEDTIME' is NULL [Dec 28 16:48:53] DEBUG[838][C-0000007c]: pbx_variables.c:378 ast_str_retrieve_variable: Result of 'ANSWEREDTIME' is NULL [Dec 28 16:48:53] DEBUG[838][C-0000007c]: pbx.c:2875 pbx_extension_helper: Launching 'AGI' [Dec 28 16:48:53] -- Executing [h@default:1] AGI("Local/917275777470@default-00000030;1", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16---------------") in new stack [Dec 28 16:48:53] DEBUG[838][C-0000007c]: res_agi.c:4491 agi_exec_full: Hungup channel detected, running agi in dead mode. [Dec 28 16:48:53] DEBUG[838][C-0000007c]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '127.0.0.1:4577' into... [Dec 28 16:48:53] DEBUG[838][C-0000007c]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '127.0.0.1' and port '4577'. [Dec 28 16:48:53] DEBUG[838][C-0000007c]: res_agi.c:2105 launch_netscript: Wow, connected! [Dec 28 16:48:53] DEBUG[31419]: cdr.c:1293 cdr_object_finalize: Finalized CDR for Local/917275777470@default-00000030;1 - start 1482961700.816170 answer 1482961700.816161 end 1482961733.017895 dispo ANSWERED [Dec 28 16:48:53] DEBUG[31554]: manager.c:5858 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: Local/917275777470@default-00000030;1 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: CallerIDName: V2281648150000060018 ConnectedLineNum: 0000000000 ConnectedLineName: V2281648150000060018 Language: en AccountCode: Context: default Exten: 8368 Priority: 7 Uniqueid: 1482961695.189 Linkedid: 1482961695.189 Extension: 8368 Application: Hangup AppData: [Dec 28 16:48:53] DEBUG[31554]: manager.c:5858 match_filter: Examining AMI event: Event: SoftHangupRequest Privilege: call,all Channel: Local/917275777470@default-00000030;1 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: CallerIDName: V2281648150000060018 ConnectedLineNum: 0000000000 ConnectedLineName: V2281648150000060018 Language: en AccountCode: Context: default Exten: 8368 Priority: 7 Uniqueid: 1482961695.189 Linkedid: 1482961695.189 Cause: 16 [Dec 28 16:48:53] DEBUG[31554]: manager.c:5858 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: Local/917275777470@default-00000030;1 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: CallerIDName: V2281648150000060018 ConnectedLineNum: 0000000000 ConnectedLineName: V2281648150000060018 Language: en AccountCode: Context: default Exten: h Priority: 1 Uniqueid: 1482961695.189 Linkedid: 1482961695.189 Extension: h Application: AGI AppData: agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16--------------- [Dec 28 16:48:53] DEBUG[31543]: manager.c:6313 process_message: Running action 'Command' [Dec 28 16:48:53] DEBUG[31543]: manager.c:6313 process_message: Running action 'Command' [Dec 28 16:48:54] -- AGI Script agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16--------------- completed, returning 0 [Dec 28 16:48:54] DEBUG[838][C-0000007c]: channel.c:2720 ast_hangup: Hanging up channel 'Local/917275777470@default-00000030;1' [Dec 28 16:48:54] DEBUG[839][C-0000007b]: bridge_channel.c:288 ast_bridge_channel_leave_bridge_nolock: Setting 0x7f7b0400f320(Local/917275777470@default-00000030;2) state from:0 to:1 [Dec 28 16:48:54] DEBUG[31417]: devicestate.c:369 _ast_device_state: No provider found, checking channel drivers for Local - 917275777470@default [Dec 28 16:48:54] DEBUG[839][C-0000007b]: bridge_channel.c:2055 bridge_channel_internal_pull: Bridge dd59f896-199d-452a-8f6c-4d1dfeaa6c2c: pulling 0x7f7b0400f320(Local/917275777470@default-00000030;2) [Dec 28 16:48:54] DEBUG[31417]: devicestate.c:474 do_state_change: Changing state for Local/917275777470@default - state 1 (Not in use) [Dec 28 16:48:54] -- Channel Local/917275777470@default-00000030;2 left 'simple_bridge' basic-bridge [Dec 28 16:48:54] DEBUG[839][C-0000007b]: bridge_channel.c:2067 bridge_channel_internal_pull: Bridge dd59f896-199d-452a-8f6c-4d1dfeaa6c2c: 0x7f7b0400f320(Local/917275777470@default-00000030;2) is leaving simple_bridge technology [Dec 28 16:48:54] DEBUG[839][C-0000007b]: bridge.c:322 bridge_dissolve: Bridge dd59f896-199d-452a-8f6c-4d1dfeaa6c2c: dissolving bridge with cause 16(Normal Clearing) [Dec 28 16:48:54] DEBUG[839][C-0000007b]: bridge_channel.c:288 ast_bridge_channel_leave_bridge_nolock: Setting 0x7f7b04027030(SIP/office-server-00000003) state from:0 to:2 [Dec 28 16:48:54] DEBUG[31406]: threadpool.c:517 grow: Increasing threadpool stasis-core's size by 1 [Dec 28 16:48:54] DEBUG[839][C-0000007b]: bridge.c:283 bridge_queue_action_nodup: Bridge dd59f896-199d-452a-8f6c-4d1dfeaa6c2c: queueing action type:13 sub:1001 [Dec 28 16:48:54] DEBUG[839][C-0000007b]: bridge.c:1003 smart_bridge_operation: Bridge dd59f896-199d-452a-8f6c-4d1dfeaa6c2c is dissolved, not performing smart bridge operation. [Dec 28 16:48:54] DEBUG[853][C-0000007b]: bridge_channel.c:2055 bridge_channel_internal_pull: Bridge dd59f896-199d-452a-8f6c-4d1dfeaa6c2c: pulling 0x7f7b04027030(SIP/office-server-00000003) [Dec 28 16:48:54] DEBUG[31419]: cdr.c:1293 cdr_object_finalize: Finalized CDR for Local/917275777470@default-00000030;2 - start 1482961695.437718 answer 1482961700.816156 end 1482961734.021774 dispo ANSWERED [Dec 28 16:48:54] -- Channel SIP/office-server-00000003 left 'simple_bridge' basic-bridge [Dec 28 16:48:54] DEBUG[853][C-0000007b]: bridge_channel.c:2067 bridge_channel_internal_pull: Bridge dd59f896-199d-452a-8f6c-4d1dfeaa6c2c: 0x7f7b04027030(SIP/office-server-00000003) is leaving simple_bridge technology [Dec 28 16:48:54] DEBUG[853][C-0000007b]: bridge.c:1003 smart_bridge_operation: Bridge dd59f896-199d-452a-8f6c-4d1dfeaa6c2c is dissolved, not performing smart bridge operation. [Dec 28 16:48:54] DEBUG[853][C-0000007b]: res_rtp_asterisk.c:3069 ast_rtp_change_source: Changing ssrc from 1390110721 to 479108088 due to a source change [Dec 28 16:48:54] DEBUG[839][C-0000007b]: app_dial.c:3229 dial_exec_full: Exiting with DIALSTATUS=ANSWER. [Dec 28 16:48:54] DEBUG[839][C-0000007b]: pbx.c:4346 __ast_pbx_run: Spawn extension (default,917275777470,2) exited non-zero on 'Local/917275777470@default-00000030;2' [Dec 28 16:48:54] == Spawn extension (default, 917275777470, 2) exited non-zero on 'Local/917275777470@default-00000030;2' [Dec 28 16:48:54] DEBUG[839][C-0000007b]: channel.c:2571 ast_softhangup_nolock: Soft-Hanging (0x10) up channel 'Local/917275777470@default-00000030;2' [Dec 28 16:48:54] DEBUG[853][C-0000007b]: abstract_jb.c:871 hook_destroy_cb: JITTERBUFFER hook destroyed [Dec 28 16:48:54] DEBUG[839][C-0000007b]: channel.c:2571 ast_softhangup_nolock: Soft-Hanging (0x80) up channel 'Local/917275777470@default-00000030;2' [Dec 28 16:48:54] DEBUG[853][C-0000007b]: channel.c:2720 ast_hangup: Hanging up channel 'SIP/office-server-00000003' [Dec 28 16:48:54] DEBUG[853][C-0000007b]: chan_sip.c:7145 sip_hangup: Hangup call SIP/office-server-00000003, SIP callid 46ca6204476c4b8e56716c3d109b504d@192.168.198.30:5060 [Dec 28 16:48:54] DEBUG[853][C-0000007b]: res_rtp_asterisk.c:4986 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7f7b04005c50' [Dec 28 16:48:54] DEBUG[31416][C-0000007b]: bridge.c:648 destroy_bridge: Bridge dd59f896-199d-452a-8f6c-4d1dfeaa6c2c: actually destroying basic bridge, nobody wants it anymore [Dec 28 16:48:54] DEBUG[31416][C-0000007b]: bridge.c:673 destroy_bridge: Bridge dd59f896-199d-452a-8f6c-4d1dfeaa6c2c: calling basic bridge destructor [Dec 28 16:48:54] DEBUG[31416][C-0000007b]: bridge.c:679 destroy_bridge: Bridge dd59f896-199d-452a-8f6c-4d1dfeaa6c2c: calling simple_bridge technology stop [Dec 28 16:48:54] DEBUG[31416][C-0000007b]: bridge.c:686 destroy_bridge: Bridge dd59f896-199d-452a-8f6c-4d1dfeaa6c2c: calling simple_bridge technology destructor [Dec 28 16:48:54] DEBUG[839][C-0000007b]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'HANGUPCAUSE' is '16' [Dec 28 16:48:54] DEBUG[839][C-0000007b]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'DIALSTATUS' is 'ANSWER' [Dec 28 16:48:54] DEBUG[839][C-0000007b]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'DIALEDTIME' is '38' [Dec 28 16:48:54] DEBUG[839][C-0000007b]: pbx_variables.c:381 ast_str_retrieve_variable: Result of 'ANSWEREDTIME' is '33' [Dec 28 16:48:54] DEBUG[839][C-0000007b]: pbx.c:2875 pbx_extension_helper: Launching 'AGI' [Dec 28 16:48:54] -- Executing [h@default:1] AGI("Local/917275777470@default-00000030;2", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16-----ANSWER-----38-----33") in new stack [Dec 28 16:48:54] DEBUG[839][C-0000007b]: res_agi.c:4491 agi_exec_full: Hungup channel detected, running agi in dead mode. [Dec 28 16:48:54] DEBUG[839][C-0000007b]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '127.0.0.1:4577' into... [Dec 28 16:48:54] DEBUG[839][C-0000007b]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '127.0.0.1' and port '4577'. [Dec 28 16:48:54] DEBUG[853][C-0000007b]: chan_sip.c:3746 __sip_xmit: Trying to put 'BYE sip:172' onto UDP socket destined for 192.168.198.1:5060 [Dec 28 16:48:54] DEBUG[839][C-0000007b]: res_agi.c:2105 launch_netscript: Wow, connected! [Dec 28 16:48:54] DEBUG[853][C-0000007b]: abstract_jb.c:861 datastore_destroy_cb: JITTERBUFFER datastore destroyed [Dec 28 16:48:54] DEBUG[31554]: manager.c:5858 match_filter: Examining AMI event: Event: HangupRequest Privilege: call,all Channel: Local/917275777470@default-00000030;2 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 0000000000 CallerIDName: V2281648150000060018 ConnectedLineNum: 0000000000 ConnectedLineName: V2281648150000060018 Language: en AccountCode: Context: default Exten: 917275777470 Priority: 2 Uniqueid: 1482961695.190 Linkedid: 1482961695.189 Cause: 16 [Dec 28 16:48:54] DEBUG[31554]: manager.c:5858 match_filter: Examining AMI event: Event: Hangup Privilege: call,all Channel: Local/917275777470@default-00000030;1 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: CallerIDName: V2281648150000060018 ConnectedLineNum: 0000000000 ConnectedLineName: V2281648150000060018 Language: en AccountCode: Context: default Exten: h Priority: 2 Uniqueid: 1482961695.189 Linkedid: 1482961695.189 Cause: 16 Cause-txt: Normal Clearing [Dec 28 16:48:54] DEBUG[31417]: devicestate.c:369 _ast_device_state: No provider found, checking channel drivers for SIP - office-server [Dec 28 16:48:54] DEBUG[31417]: chan_sip.c:30154 sip_devicestate: Checking device state for peer office-server [Dec 28 16:48:54] DEBUG[31554]: manager.c:5858 match_filter: Examining AMI event: Event: DeviceStateChange Privilege: call,all Device: Local/917275777470@default State: NOT_INUSE [Dec 28 16:48:54] DEBUG[31417]: devicestate.c:474 do_state_change: Changing state for SIP/office-server - state 1 (Not in use) [Dec 28 16:48:54] DEBUG[31554]: manager.c:5858 match_filter: Examining AMI event: Event: BridgeLeave Privilege: call,all BridgeUniqueid: dd59f896-199d-452a-8f6c-4d1dfeaa6c2c BridgeType: basic BridgeTechnology: simple_bridge BridgeCreator: BridgeName: BridgeNumChannels: 1 BridgeVideoSourceMode: none Channel: Local/917275777470@default-00000030;2 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 0000000000 CallerIDName: V2281648150000060018 ConnectedLineNum: 0000000000 ConnectedLineName: V2281648150000060018 Language: en AccountCode: Context: default Exten: 917275777470 Priority: 2 Uniqueid: 1482961695.190 Linkedid: 1482961695.189 [Dec 28 16:48:54] DEBUG[31554]: manager.c:5858 match_filter: Examining AMI event: Event: BridgeLeave Privilege: call,all BridgeUniqueid: dd59f896-199d-452a-8f6c-4d1dfeaa6c2c BridgeType: basic BridgeTechnology: simple_bridge BridgeCreator: BridgeName: BridgeNumChannels: 0 BridgeVideoSourceMode: none Channel: SIP/office-server-00000003 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 0000000000 CallerIDName: V2281648150000060018 ConnectedLineNum: 0000000000 ConnectedLineName: V2281648150000060018 Language: en AccountCode: Context: international Exten: Priority: 1 Uniqueid: 1482961695.191 Linkedid: 1482961695.189 [Dec 28 16:48:54] DEBUG[31419]: cdr.c:1121 cdr_object_create_public_records: CDR for SIP/office-server-00000003 is dialed and has no Party B; discarding [Dec 28 16:48:54] DEBUG[31554]: manager.c:5858 match_filter: Examining AMI event: Event: SoftHangupRequest Privilege: call,all Channel: Local/917275777470@default-00000030;2 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 0000000000 CallerIDName: V2281648150000060018 ConnectedLineNum: 0000000000 ConnectedLineName: V2281648150000060018 Language: en AccountCode: Context: default Exten: 917275777470 Priority: 2 Uniqueid: 1482961695.190 Linkedid: 1482961695.189 Cause: 16 [Dec 28 16:48:54] DEBUG[31554]: manager.c:5858 match_filter: Examining AMI event: Event: BridgeDestroy Privilege: call,all BridgeUniqueid: dd59f896-199d-452a-8f6c-4d1dfeaa6c2c BridgeType: basic BridgeTechnology: simple_bridge BridgeCreator: BridgeName: BridgeNumChannels: 0 BridgeVideoSourceMode: none [Dec 28 16:48:54] DEBUG[31554]: manager.c:5858 match_filter: Examining AMI event: Event: Newexten Privilege: call,all Channel: Local/917275777470@default-00000030;2 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 0000000000 CallerIDName: V2281648150000060018 ConnectedLineNum: 0000000000 ConnectedLineName: V2281648150000060018 Language: en AccountCode: Context: default Exten: h Priority: 1 Uniqueid: 1482961695.190 Linkedid: 1482961695.189 Extension: h Application: AGI AppData: agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16-----ANSWER-----38-----33 [Dec 28 16:48:54] DEBUG[31554]: manager.c:5858 match_filter: Examining AMI event: Event: Hangup Privilege: call,all Channel: SIP/office-server-00000003 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 0000000000 CallerIDName: V2281648150000060018 ConnectedLineNum: 0000000000 ConnectedLineName: V2281648150000060018 Language: en AccountCode: Context: international Exten: Priority: 1 Uniqueid: 1482961695.191 Linkedid: 1482961695.189 Cause: 16 Cause-txt: Normal Clearing [Dec 28 16:48:54] DEBUG[31434]: chan_sip.c:29630 do_stop_session_timer: Session timer stopped: 1 - 46ca6204476c4b8e56716c3d109b504d@192.168.198.30:5060 [Dec 28 16:48:54] DEBUG[31434]: chan_sip.c:9394 __find_call: = Looking for Call ID: 46ca6204476c4b8e56716c3d109b504d@192.168.198.30:5060 (Checking To) --From tag as3bc76506 --To-tag as014408bc [Dec 28 16:48:54] DEBUG[31434][C-0000007b]: chan_sip.c:4527 __sip_ack: Stopping retransmission on '46ca6204476c4b8e56716c3d109b504d@192.168.198.30:5060' of Request 103: Match Found [Dec 28 16:48:54] DEBUG[31434]: chan_sip.c:6579 sip_pvt_dtor: Destroying SIP dialog 46ca6204476c4b8e56716c3d109b504d@192.168.198.30:5060 [Dec 28 16:48:54] DEBUG[31434]: rtp_engine.c:397 instance_destructor: Destroyed RTP instance '0x7f7b04005c50' [Dec 28 16:48:54] DEBUG[31543]: manager.c:6313 process_message: Running action 'Command' [Dec 28 16:48:54] DEBUG[31543]: manager.c:6313 process_message: Running action 'Command' [Dec 28 16:48:54] DEBUG[31543]: manager.c:6313 process_message: Running action 'Command' [Dec 28 16:48:55] -- AGI Script agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16-----ANSWER-----38-----33 completed, returning 0 [Dec 28 16:48:55] DEBUG[839][C-0000007b]: channel.c:2720 ast_hangup: Hanging up channel 'Local/917275777470@default-00000030;2' [Dec 28 16:48:55] DEBUG[31417]: devicestate.c:369 _ast_device_state: No provider found, checking channel drivers for Local - 917275777470@default [Dec 28 16:48:55] DEBUG[31417]: core_local.c:354 local_devicestate: Checking if extension 917275777470@default exists (devicestate) [Dec 28 16:48:55] DEBUG[31417]: devicestate.c:474 do_state_change: Changing state for Local/917275777470@default - state 1 (Not in use) [Dec 28 16:48:55] DEBUG[31554]: manager.c:5858 match_filter: Examining AMI event: Event: Hangup Privilege: call,all Channel: Local/917275777470@default-00000030;2 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 0000000000 CallerIDName: V2281648150000060018 ConnectedLineNum: 0000000000 ConnectedLineName: V2281648150000060018 Language: en AccountCode: Context: default Exten: h Priority: 2 Uniqueid: 1482961695.190 Linkedid: 1482961695.189 Cause: 16 Cause-txt: Normal Clearing [Dec 28 16:48:55] DEBUG[31554]: manager.c:5858 match_filter: Examining AMI event: Event: DeviceStateChange Privilege: call,all Device: Local/917275777470@default State: NOT_INUSE