[2018-03-13 12:35:00.233] DEBUG[2830] chan_sip.c: = Looking for Call ID: 1520958900229-7f0c0893e430-0820b490-000006c5@10.1.144.14 (Checking From) --From tag 1c78725c-422bf87e-3361a7-8052ab8-0-13c4-7217 --To-tag [2018-03-13 12:35:00.233] DEBUG[2830] acl.c: For destination '10.1.174.33', our source address is '10.1.144.6'. [2018-03-13 12:35:00.233] DEBUG[2830] chan_sip.c: Setting AST_TRANSPORT_UDP with address 10.1.144.6:5060 [2018-03-13 12:35:00.233] DEBUG[2830] netsock2.c: Splitting '10.1.174.33' into... [2018-03-13 12:35:00.233] DEBUG[2830] netsock2.c: ...host '10.1.174.33' and port ''. [2018-03-13 12:35:00.233] DEBUG[2830] chan_sip.c: Allocating new SIP dialog for 1520958900229-7f0c0893e430-0820b490-000006c5@10.1.144.14 - INVITE (No RTP) [2018-03-13 12:35:00.233] DEBUG[2830][C-00000000] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [2018-03-13 12:35:00.234] DEBUG[2830][C-00000000] netsock2.c: Splitting '10.1.174.33' into... [2018-03-13 12:35:00.234] DEBUG[2830][C-00000000] netsock2.c: ...host '10.1.174.33' and port ''. [2018-03-13 12:35:00.234] DEBUG[2830][C-00000000] netsock2.c: Splitting '10.1.174.33:5060' into... [2018-03-13 12:35:00.234] DEBUG[2830][C-00000000] netsock2.c: ...host '10.1.174.33' and port ''. [2018-03-13 12:35:00.234] DEBUG[2830][C-00000000] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7f92100110d8' [2018-03-13 12:35:00.235] DEBUG[2830][C-00000000] res_rtp_asterisk.c: Allocated port 19376 for RTP instance '0x7f92100110d8' [2018-03-13 12:35:00.235] DEBUG[2830][C-00000000] rtp_engine.c: RTP instance '0x7f92100110d8' is setup and ready to go [2018-03-13 12:35:00.235] DEBUG[2830][C-00000000] netsock2.c: Splitting 'ast-dev01.dialogtech.com' into... [2018-03-13 12:35:00.235] DEBUG[2830][C-00000000] netsock2.c: ...host 'ast-dev01.dialogtech.com' and port ''. [2018-03-13 12:35:00.235] DEBUG[2830][C-00000000] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7f92100110d8' [2018-03-13 12:35:00.235] VERBOSE[2830][C-00000000] netsock2.c: Using SIP RTP CoS mark 5 [2018-03-13 12:35:00.235] DEBUG[2830][C-00000000] chan_sip.c: Setting NAT on RTP to Off [2018-03-13 12:35:00.235] DEBUG[2830][C-00000000] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED OR FAILED. [2018-03-13 12:35:00.235] DEBUG[2830][C-00000000] chan_sip.c: Processing session-level SDP o=- 3606533 3606533 IN IP4 10.1.144.14... OK. [2018-03-13 12:35:00.235] DEBUG[2830][C-00000000] chan_sip.c: Processing session-level SDP s=voxeo.16.0.4.47.89389... UNSUPPORTED OR FAILED. [2018-03-13 12:35:00.235] DEBUG[2830][C-00000000] netsock2.c: Splitting '10.1.144.14' into... [2018-03-13 12:35:00.235] DEBUG[2830][C-00000000] netsock2.c: ...host '10.1.144.14' and port ''. [2018-03-13 12:35:00.235] DEBUG[2830][C-00000000] chan_sip.c: Processing session-level SDP c=IN IP4 10.1.144.14... OK. [2018-03-13 12:35:00.235] DEBUG[2830][C-00000000] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED. [2018-03-13 12:35:00.236] DEBUG[2830][C-00000000] rtp_engine.c: Setting tx payload type 0 based on m type on 0x7f91e1408290 [2018-03-13 12:35:00.236] DEBUG[2830][C-00000000] rtp_engine.c: Setting tx payload type 101 based on m type on 0x7f91e1408290 [2018-03-13 12:35:00.236] DEBUG[2830][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. [2018-03-13 12:35:00.236] DEBUG[2830][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [2018-03-13 12:35:00.236] DEBUG[2830][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-15... UNSUPPORTED OR FAILED. [2018-03-13 12:35:00.236] DEBUG[2830][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK. [2018-03-13 12:35:00.236] DEBUG[2830][C-00000000] acl.c: For destination '10.1.144.14', our source address is '10.1.144.6'. [2018-03-13 12:35:00.236] DEBUG[2830][C-00000000] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7f92100110d8' [2018-03-13 12:35:00.236] VERBOSE[2830][C-00000000] res_rtp_asterisk.c: 0x7f9210012770 -- Strict RTP learning after remote address set to: 10.1.144.14:10138 [2018-03-13 12:35:00.236] DEBUG[2830][C-00000000] rtp_engine.c: Copying payload 0 (0x7f921001b710) from 0x7f91e1408290 to 0x7f92100112a0 [2018-03-13 12:35:00.236] DEBUG[2830][C-00000000] rtp_engine.c: Copying payload 101 (0x7f921001bb90) from 0x7f91e1408290 to 0x7f92100112a0 [2018-03-13 12:35:00.236] DEBUG[2830][C-00000000] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x7f92100110d8' [2018-03-13 12:35:00.236] DEBUG[2830][C-00000000] chan_sip.c: We're settling with these formats: (ulaw) [2018-03-13 12:35:00.236] DEBUG[2830][C-00000000] chan_sip.c: Checking SIP call limits for device [2018-03-13 12:35:00.237] DEBUG[2830][C-00000000] chan_sip.c: Updating call counter for incoming call [2018-03-13 12:35:00.237] DEBUG[2830][C-00000000] netsock2.c: Splitting '10.1.144.6:5060' into... [2018-03-13 12:35:00.237] DEBUG[2830][C-00000000] netsock2.c: ...host '10.1.144.6' and port ''. [2018-03-13 12:35:00.237] DEBUG[2830][C-00000000] netsock2.c: Splitting '10.1.174.33:5060' into... [2018-03-13 12:35:00.237] DEBUG[2830][C-00000000] netsock2.c: ...host '10.1.174.33' and port ''. [2018-03-13 12:35:00.238] DEBUG[2830][C-00000000] channel.c: Channel 0x7f9210020088 'SIP/voxprox-dev01-00000000' allocated [2018-03-13 12:35:00.238] DEBUG[2830][C-00000000] chan_sip.c: *** Our native formats are (ulaw) [2018-03-13 12:35:00.238] DEBUG[2830][C-00000000] chan_sip.c: *** Joint capabilities are (ulaw) [2018-03-13 12:35:00.238] DEBUG[2830][C-00000000] chan_sip.c: *** Our capabilities are (ulaw) [2018-03-13 12:35:00.238] DEBUG[2830][C-00000000] chan_sip.c: *** AST_CODEC_CHOOSE formats are ulaw [2018-03-13 12:35:00.238] DEBUG[2830][C-00000000] chan_sip.c: This channel will not be able to handle video. [2018-03-13 12:35:00.239] DEBUG[2830][C-00000000] sip/route.c: sip_route_process_header: [2018-03-13 12:35:00.239] DEBUG[2830][C-00000000] chan_sip.c: SIP/voxprox-dev01-00000000: New call is still down.... Trying... [2018-03-13 12:35:00.239] DEBUG[2830][C-00000000] chan_sip.c: Trying to put 'SIP/2.0 100' onto UDP socket destined for 10.1.174.33:5060 [2018-03-13 12:35:00.241] DEBUG[2797] threadpool.c: Increasing threadpool stasis-core's size by 1 [2018-03-13 12:35:00.242] DEBUG[2808] devicestate.c: No provider found, checking channel drivers for SIP - voxprox-dev01 [2018-03-13 12:35:00.242] DEBUG[2808] chan_sip.c: Checking device state for peer voxprox-dev01 [2018-03-13 12:35:00.242] DEBUG[2808] devicestate.c: Changing state for SIP/voxprox-dev01 - state 1 (Not in use) [2018-03-13 12:35:00.243] DEBUG[2869][C-00000000] pbx_variables.c: Result of 'newdnis' is NULL [2018-03-13 12:35:00.243] DEBUG[2869][C-00000000] pbx_variables.c: Expression result is '1' [2018-03-13 12:35:00.243] DEBUG[2869][C-00000000] pbx.c: Launching 'GotoIf' [2018-03-13 12:35:00.243] VERBOSE[2869][C-00000000] pbx.c: Executing [17732507208@default:1] GotoIf("SIP/voxprox-dev01-00000000", "1?remove_ext:prepare_dial") in new stack [2018-03-13 12:35:00.243] VERBOSE[2869][C-00000000] pbx_builtins.c: Goto (default,17732507208,2) [2018-03-13 12:35:00.243] DEBUG[2869][C-00000000] pbx_variables.c: Result of 'ext' is NULL [2018-03-13 12:35:00.243] DEBUG[2869][C-00000000] pbx_variables.c: Expression result is '1' [2018-03-13 12:35:00.244] DEBUG[2869][C-00000000] pbx_variables.c: Evaluating 'EXTEN' (from 'EXTEN}' len 5) [2018-03-13 12:35:00.244] DEBUG[2869][C-00000000] pbx_variables.c: Result of 'EXTEN' is '17732507208' [2018-03-13 12:35:00.244] DEBUG[2869][C-00000000] pbx_variables.c: Function CUT(EXTEN,x,2) result is '' [2018-03-13 12:35:00.244] DEBUG[2869][C-00000000] pbx.c: Launching 'ExecIf' [2018-03-13 12:35:00.244] VERBOSE[2869][C-00000000] pbx.c: Executing [17732507208@default:2] ExecIf("SIP/voxprox-dev01-00000000", "1?Set(ext=") in new stack [2018-03-13 12:35:00.245] DEBUG[2869][C-00000000] pbx_variables.c: Evaluating 'EXTEN' (from 'EXTEN}' len 5) [2018-03-13 12:35:00.245] DEBUG[2869][C-00000000] pbx_variables.c: Result of 'EXTEN' is '17732507208' [2018-03-13 12:35:00.245] DEBUG[2869][C-00000000] pbx_variables.c: Function CUT(EXTEN,x,1) result is '17732507208' [2018-03-13 12:35:00.245] DEBUG[2869][C-00000000] pbx.c: Launching 'Set' [2018-03-13 12:35:00.245] VERBOSE[2869][C-00000000] pbx.c: Executing [17732507208@default:3] Set("SIP/voxprox-dev01-00000000", "newdnis=17732507208") in new stack [2018-03-13 12:35:00.245] DEBUG[2869][C-00000000] pbx_variables.c: Result of 'newdnis' is '17732507208' [2018-03-13 12:35:00.245] DEBUG[2869][C-00000000] pbx.c: Launching 'Goto' [2018-03-13 12:35:00.245] VERBOSE[2869][C-00000000] pbx.c: Executing [17732507208@default:4] Goto("SIP/voxprox-dev01-00000000", "17732507208,validate_dnis") in new stack [2018-03-13 12:35:00.246] VERBOSE[2869][C-00000000] pbx_builtins.c: Goto (default,17732507208,1) [2018-03-13 12:35:00.246] DEBUG[2869][C-00000000] pbx_variables.c: Result of 'newdnis' is '17732507208' [2018-03-13 12:35:00.246] DEBUG[2869][C-00000000] pbx_variables.c: Expression result is '0' [2018-03-13 12:35:00.246] DEBUG[2869][C-00000000] pbx.c: Launching 'GotoIf' [2018-03-13 12:35:00.246] VERBOSE[2869][C-00000000] pbx.c: Executing [17732507208@default:1] GotoIf("SIP/voxprox-dev01-00000000", "0?remove_ext:prepare_dial") in new stack [2018-03-13 12:35:00.246] VERBOSE[2869][C-00000000] pbx_builtins.c: Goto (default,17732507208,5) [2018-03-13 12:35:00.246] DEBUG[2869][C-00000000] pbx.c: Launching 'Set' [2018-03-13 12:35:00.246] VERBOSE[2869][C-00000000] pbx.c: Executing [17732507208@default:5] Set("SIP/voxprox-dev01-00000000", "inboundmergehack=1") in new stack [2018-03-13 12:35:00.247] DEBUG[2869][C-00000000] pbx_variables.c: Result of 'SIPREFER' is NULL [2018-03-13 12:35:00.247] DEBUG[2869][C-00000000] pbx_variables.c: Expression result is '0' [2018-03-13 12:35:00.247] DEBUG[2869][C-00000000] pbx.c: Launching 'ExecIf' [2018-03-13 12:35:00.247] VERBOSE[2869][C-00000000] pbx.c: Executing [17732507208@default:6] ExecIf("SIP/voxprox-dev01-00000000", "0?Macro(assert_refer_triaged)") in new stack [2018-03-13 12:35:00.247] DEBUG[2869][C-00000000] pbx_variables.c: Function CALLERID(num) result is '13129990302' [2018-03-13 12:35:00.247] DEBUG[2869][C-00000000] pbx.c: Launching 'Set' [2018-03-13 12:35:00.247] VERBOSE[2869][C-00000000] pbx.c: Executing [17732507208@default:7] Set("SIP/voxprox-dev01-00000000", "CALLERID(name)=13129990302") in new stack [2018-03-13 12:35:00.248] DEBUG[2869][C-00000000] pbx.c: Launching 'Set' [2018-03-13 12:35:00.248] VERBOSE[2869][C-00000000] pbx.c: Executing [17732507208@default:8] Set("SIP/voxprox-dev01-00000000", "refercall=") in new stack [2018-03-13 12:35:00.248] DEBUG[2869][C-00000000] pbx_variables.c: Result of 'x-play_warning' is NULL [2018-03-13 12:35:00.249] DEBUG[2869][C-00000000] pbx_variables.c: Function ISNULL() result is '1' [2018-03-13 12:35:00.249] DEBUG[2869][C-00000000] pbx_variables.c: Expression result is '0' [2018-03-13 12:35:00.249] DEBUG[2869][C-00000000] pbx.c: Launching 'ExecIf' [2018-03-13 12:35:00.249] VERBOSE[2869][C-00000000] pbx.c: Executing [17732507208@default:9] ExecIf("SIP/voxprox-dev01-00000000", "0?Macro(playwarning_variable)") in new stack [2018-03-13 12:35:00.249] DEBUG[2869][C-00000000] pbx_variables.c: Result of 'x-play_warning' is NULL [2018-03-13 12:35:00.249] DEBUG[2869][C-00000000] pbx_variables.c: Function ISNULL() result is '1' [2018-03-13 12:35:00.249] DEBUG[2869][C-00000000] pbx_variables.c: Expression result is '1' [2018-03-13 12:35:00.249] DEBUG[2869][C-00000000] pbx.c: Launching 'ExecIf' [2018-03-13 12:35:00.249] VERBOSE[2869][C-00000000] pbx.c: Executing [17732507208@default:10] ExecIf("SIP/voxprox-dev01-00000000", "1?Macro(playwarning_header)") in new stack [2018-03-13 12:35:00.251] DEBUG[2869][C-00000000] pbx_variables.c: Function SIP_HEADER(x-callee_custom_monitored_audio) result is '(null)' [2018-03-13 12:35:00.251] DEBUG[2869][C-00000000] pbx.c: Launching 'Set' [2018-03-13 12:35:00.251] VERBOSE[2869][C-00000000] pbx.c: Executing [s@macro-playwarning_header:1] Set("SIP/voxprox-dev01-00000000", "warning-audio=") in new stack [2018-03-13 12:35:00.251] DEBUG[2869][C-00000000] app_macro.c: Executed application: Set [2018-03-13 12:35:00.252] DEBUG[2869][C-00000000] pbx_variables.c: Function SIP_HEADER(x-callee_custom_monitored_audio) result is '(null)' [2018-03-13 12:35:00.252] DEBUG[2869][C-00000000] pbx_variables.c: Expression result is '1' [2018-03-13 12:35:00.252] DEBUG[2869][C-00000000] pbx.c: Launching 'ExecIf' [2018-03-13 12:35:00.252] VERBOSE[2869][C-00000000] pbx.c: Executing [s@macro-playwarning_header:2] ExecIf("SIP/voxprox-dev01-00000000", "1?Set(warning-audio=this-call-may-be-monitored-or-recorded)") in new stack [2018-03-13 12:35:00.253] DEBUG[2869][C-00000000] app_macro.c: Executed application: ExecIf [2018-03-13 12:35:00.253] DEBUG[2869][C-00000000] pbx_variables.c: Evaluating 'SIP_HEADER(x-callee_custom_monitored_audio)' (from 'SIP_HEADER(x-callee_custom_monitored_audio)}" = ""' len 43) [2018-03-13 12:35:00.253] DEBUG[2869][C-00000000] pbx_variables.c: Function SIP_HEADER(x-callee_custom_monitored_audio) result is '(null)' [2018-03-13 12:35:00.253] DEBUG[2869][C-00000000] pbx_variables.c: Expression result is '1' [2018-03-13 12:35:00.253] DEBUG[2869][C-00000000] pbx_variables.c: Function SIP_HEADER(x-play_warning) result is '3' [2018-03-13 12:35:00.253] DEBUG[2869][C-00000000] pbx_variables.c: Function SIP_HEADER(x-play_warning) result is '3' [2018-03-13 12:35:00.253] DEBUG[2869][C-00000000] pbx_variables.c: Expression result is '0' [2018-03-13 12:35:00.254] DEBUG[2869][C-00000000] pbx.c: Launching 'ExecIf' [2018-03-13 12:35:00.254] VERBOSE[2869][C-00000000] pbx.c: Executing [s@macro-playwarning_header:3] ExecIf("SIP/voxprox-dev01-00000000", "0?Set(x-limit_playaudio_callee=yes)") in new stack [2018-03-13 12:35:00.259] DEBUG[2869][C-00000000] app_macro.c: Executed application: ExecIf [2018-03-13 12:35:00.259] DEBUG[2869][C-00000000] pbx_variables.c: Evaluating 'SIP_HEADER(x-play_warning)' (from 'SIP_HEADER(x-play_warning)}" = "0" || "${SIP_HEADER(x-play_warning)}" = "2"' len 26) [2018-03-13 12:35:00.259] DEBUG[2869][C-00000000] pbx_variables.c: Function SIP_HEADER(x-play_warning) result is '3' [2018-03-13 12:35:00.259] DEBUG[2869][C-00000000] pbx_variables.c: Evaluating 'SIP_HEADER(x-play_warning)' (from 'SIP_HEADER(x-play_warning)}" = "2"' len 26) [2018-03-13 12:35:00.260] DEBUG[2869][C-00000000] pbx_variables.c: Function SIP_HEADER(x-play_warning) result is '3' [2018-03-13 12:35:00.260] DEBUG[2869][C-00000000] pbx_variables.c: Expression result is '0' [2018-03-13 12:35:00.260] DEBUG[2869][C-00000000] pbx_variables.c: Function SIP_HEADER(x-play_warning) result is '3' [2018-03-13 12:35:00.260] DEBUG[2869][C-00000000] pbx_variables.c: Function SIP_HEADER(x-play_warning) result is '3' [2018-03-13 12:35:00.260] DEBUG[2869][C-00000000] pbx_variables.c: Function SIP_HEADER(x-play_warning) result is '3' [2018-03-13 12:35:00.260] DEBUG[2869][C-00000000] pbx_variables.c: Expression result is '1' [2018-03-13 12:35:00.260] DEBUG[2869][C-00000000] pbx.c: Launching 'ExecIf' [2018-03-13 12:35:00.260] VERBOSE[2869][C-00000000] pbx.c: Executing [s@macro-playwarning_header:4] ExecIf("SIP/voxprox-dev01-00000000", "1?Set(x-limit_playaudio_caller=no)") in new stack [2018-03-13 12:35:00.261] DEBUG[2869][C-00000000] app_macro.c: Executed application: ExecIf [2018-03-13 12:35:00.261] DEBUG[2869][C-00000000] pbx_variables.c: Evaluating 'SIP_HEADER(x-play_warning)' (from 'SIP_HEADER(x-play_warning)}" = "3" || "${SIP_HEADER(x-play_warning)}" = "2" || "${SIP_HEADER(x-play_warning)}" = "0" ' len 26) [2018-03-13 12:35:00.261] DEBUG[2869][C-00000000] pbx_variables.c: Function SIP_HEADER(x-play_warning) result is '3' [2018-03-13 12:35:00.261] DEBUG[2869][C-00000000] pbx_variables.c: Evaluating 'SIP_HEADER(x-play_warning)' (from 'SIP_HEADER(x-play_warning)}" = "2" || "${SIP_HEADER(x-play_warning)}" = "0" ' len 26) [2018-03-13 12:35:00.261] DEBUG[2869][C-00000000] pbx_variables.c: Function SIP_HEADER(x-play_warning) result is '3' [2018-03-13 12:35:00.261] DEBUG[2869][C-00000000] pbx_variables.c: Evaluating 'SIP_HEADER(x-play_warning)' (from 'SIP_HEADER(x-play_warning)}" = "0" ' len 26) [2018-03-13 12:35:00.262] DEBUG[2869][C-00000000] pbx_variables.c: Function SIP_HEADER(x-play_warning) result is '3' [2018-03-13 12:35:00.262] DEBUG[2869][C-00000000] pbx_variables.c: Expression result is '1' [2018-03-13 12:35:00.262] DEBUG[2869][C-00000000] pbx_variables.c: Function SIP_HEADER(x-play_warning) result is '3' [2018-03-13 12:35:00.262] DEBUG[2869][C-00000000] pbx_variables.c: Function SIP_HEADER(x-play_warning) result is '3' [2018-03-13 12:35:00.262] DEBUG[2869][C-00000000] pbx_variables.c: Expression result is '0' [2018-03-13 12:35:00.262] DEBUG[2869][C-00000000] pbx_variables.c: Result of 'warning-audio' is 'this-call-may-be-monitored-or-recorded' [2018-03-13 12:35:00.262] DEBUG[2869][C-00000000] pbx.c: Launching 'ExecIf' [2018-03-13 12:35:00.262] VERBOSE[2869][C-00000000] pbx.c: Executing [s@macro-playwarning_header:5] ExecIf("SIP/voxprox-dev01-00000000", "0?Set(x-limit_connect_file=this-call-may-be-monitored-or-recorded)") in new stack [2018-03-13 12:35:00.263] DEBUG[2869][C-00000000] app_macro.c: Executed application: ExecIf [2018-03-13 12:35:00.263] DEBUG[2869][C-00000000] pbx_variables.c: Evaluating 'SIP_HEADER(x-play_warning)' (from 'SIP_HEADER(x-play_warning)}" = "0" || "${SIP_HEADER(x-play_warning)}" = "2"' len 26) [2018-03-13 12:35:00.263] DEBUG[2869][C-00000000] pbx_variables.c: Function SIP_HEADER(x-play_warning) result is '3' [2018-03-13 12:35:00.263] DEBUG[2869][C-00000000] pbx_variables.c: Evaluating 'SIP_HEADER(x-play_warning)' (from 'SIP_HEADER(x-play_warning)}" = "2"' len 26) [2018-03-13 12:35:00.263] DEBUG[2869][C-00000000] pbx_variables.c: Function SIP_HEADER(x-play_warning) result is '3' [2018-03-13 12:35:00.263] DEBUG[2869][C-00000000] pbx_variables.c: Expression result is '0' [2018-03-13 12:35:00.263] DEBUG[2869][C-00000000] pbx_variables.c: Evaluating 'warning-audio' (from 'warning-audio})' len 13) [2018-03-13 12:35:00.263] DEBUG[2869][C-00000000] pbx_variables.c: Result of 'warning-audio' is 'this-call-may-be-monitored-or-recorded' [2018-03-13 12:35:00.264] DEBUG[2869][C-00000000] pbx.c: Launching 'Macro' [2018-03-13 12:35:00.264] VERBOSE[2869][C-00000000] pbx.c: Executing [17732507208@default:11] Macro("SIP/voxprox-dev01-00000000", "get_headers_outbound") in new stack [2018-03-13 12:35:00.265] DEBUG[2869][C-00000000] pbx.c: Launching 'NoOp' [2018-03-13 12:35:00.265] VERBOSE[2869][C-00000000] pbx.c: Executing [s@macro-get_headers_outbound:1] NoOp("SIP/voxprox-dev01-00000000", "Storing SIP headers for outbound call") in new stack [2018-03-13 12:35:00.265] DEBUG[2869][C-00000000] app_macro.c: Executed application: NoOp [2018-03-13 12:35:00.265] DEBUG[2869][C-00000000] pbx_variables.c: Result of 'SIPURI' is 'sip:13129990302@10.1.144.14:5060' [2018-03-13 12:35:00.265] DEBUG[2869][C-00000000] pbx_variables.c: Expression result is '0' [2018-03-13 12:35:00.265] DEBUG[2869][C-00000000] pbx.c: Launching 'ExecIf' [2018-03-13 12:35:00.266] VERBOSE[2869][C-00000000] pbx.c: Executing [s@macro-get_headers_outbound:2] ExecIf("SIP/voxprox-dev01-00000000", "0?MacroExit") in new stack [2018-03-13 12:35:00.266] DEBUG[2869][C-00000000] app_macro.c: Executed application: ExecIf [2018-03-13 12:35:00.266] DEBUG[2869][C-00000000] pbx_variables.c: Evaluating 'SIPURI' (from 'SIPURI}" == ""' len 6) [2018-03-13 12:35:00.266] DEBUG[2869][C-00000000] pbx_variables.c: Result of 'SIPURI' is 'sip:13129990302@10.1.144.14:5060' [2018-03-13 12:35:00.266] DEBUG[2869][C-00000000] pbx_variables.c: Expression result is '0' [2018-03-13 12:35:00.266] DEBUG[2869][C-00000000] pbx_variables.c: Function SIP_HEADER(X-IBP-NoRecord) result is '(null)' [2018-03-13 12:35:00.266] DEBUG[2869][C-00000000] pbx_variables.c: Expression result is '0' [2018-03-13 12:35:00.266] DEBUG[2869][C-00000000] pbx_variables.c: Function SIP_HEADER(X-IBP-NoRecord) result is '(null)' [2018-03-13 12:35:00.266] DEBUG[2869][C-00000000] pbx.c: Launching 'ExecIf' [2018-03-13 12:35:00.267] VERBOSE[2869][C-00000000] pbx.c: Executing [s@macro-get_headers_outbound:3] ExecIf("SIP/voxprox-dev01-00000000", "0?Set(__x-ibp-norecord=)") in new stack [2018-03-13 12:35:00.267] DEBUG[2869][C-00000000] app_macro.c: Executed application: ExecIf [2018-03-13 12:35:00.267] DEBUG[2869][C-00000000] pbx_variables.c: Evaluating 'SIP_HEADER(X-IBP-NoRecord)' (from 'SIP_HEADER(X-IBP-NoRecord)}" != ""' len 26) [2018-03-13 12:35:00.267] DEBUG[2869][C-00000000] pbx_variables.c: Function SIP_HEADER(X-IBP-NoRecord) result is '(null)' [2018-03-13 12:35:00.267] DEBUG[2869][C-00000000] pbx_variables.c: Expression result is '0' [2018-03-13 12:35:00.267] DEBUG[2869][C-00000000] pbx_variables.c: Evaluating 'SIP_HEADER(X-IBP-NoRecord)' (from 'SIP_HEADER(X-IBP-NoRecord)})' len 26) [2018-03-13 12:35:00.267] DEBUG[2869][C-00000000] pbx_variables.c: Function SIP_HEADER(X-IBP-NoRecord) result is '(null)' [2018-03-13 12:35:00.267] DEBUG[2869][C-00000000] pbx_variables.c: Function SIP_HEADER(x-out) result is '(null)' [2018-03-13 12:35:00.268] DEBUG[2869][C-00000000] pbx_variables.c: Expression result is '0' [2018-03-13 12:35:00.268] DEBUG[2869][C-00000000] pbx.c: Launching 'ExecIf' [2018-03-13 12:35:00.268] VERBOSE[2869][C-00000000] pbx.c: Executing [s@macro-get_headers_outbound:4] ExecIf("SIP/voxprox-dev01-00000000", "0?Set(outboundmergehack=1)") in new stack [2018-03-13 12:35:00.268] DEBUG[2869][C-00000000] app_macro.c: Executed application: ExecIf [2018-03-13 12:35:00.268] DEBUG[2869][C-00000000] pbx_variables.c: Evaluating 'SIP_HEADER(x-out)' (from 'SIP_HEADER(x-out)}" != ""' len 17) [2018-03-13 12:35:00.268] DEBUG[2869][C-00000000] pbx_variables.c: Function SIP_HEADER(x-out) result is '(null)' [2018-03-13 12:35:00.268] DEBUG[2869][C-00000000] pbx_variables.c: Expression result is '0' [2018-03-13 12:35:00.268] DEBUG[2869][C-00000000] pbx_variables.c: Function SIP_HEADER(x-privacy) result is '(null)' [2018-03-13 12:35:00.268] DEBUG[2869][C-00000000] pbx_variables.c: Expression result is '0' [2018-03-13 12:35:00.268] DEBUG[2869][C-00000000] pbx.c: Launching 'ExecIf' [2018-03-13 12:35:00.269] VERBOSE[2869][C-00000000] pbx.c: Executing [s@macro-get_headers_outbound:5] ExecIf("SIP/voxprox-dev01-00000000", "0?SetCallerPres(unavailable)") in new stack [2018-03-13 12:35:00.269] DEBUG[2869][C-00000000] app_macro.c: Executed application: ExecIf [2018-03-13 12:35:00.269] DEBUG[2869][C-00000000] pbx_variables.c: Evaluating 'SIP_HEADER(x-privacy)' (from 'SIP_HEADER(x-privacy)}" = "1"' len 21) [2018-03-13 12:35:00.269] DEBUG[2869][C-00000000] pbx_variables.c: Function SIP_HEADER(x-privacy) result is '(null)' [2018-03-13 12:35:00.269] DEBUG[2869][C-00000000] pbx_variables.c: Expression result is '0' [2018-03-13 12:35:00.269] DEBUG[2869][C-00000000] pbx_variables.c: Function SIP_HEADER(X-IBP-Unique-ID) result is '6LqvrJwpKonqyLMHDIKGyIEEGsEzILqKGGxsHwnF' [2018-03-13 12:35:00.269] DEBUG[2869][C-00000000] pbx.c: Launching 'Set' [2018-03-13 12:35:00.269] VERBOSE[2869][C-00000000] pbx.c: Executing [s@macro-get_headers_outbound:6] Set("SIP/voxprox-dev01-00000000", "X-IBP-Unique-ID=6LqvrJwpKonqyLMHDIKGyIEEGsEzILqKGGxsHwnF") in new stack [2018-03-13 12:35:00.270] DEBUG[2869][C-00000000] app_macro.c: Executed application: Set [2018-03-13 12:35:00.270] DEBUG[2869][C-00000000] pbx_variables.c: Function SIP_HEADER(x-accountcode) result is 'c1nb2-095889235626776' [2018-03-13 12:35:00.270] DEBUG[2869][C-00000000] pbx_variables.c: Expression result is '1' [2018-03-13 12:35:00.270] DEBUG[2869][C-00000000] pbx_variables.c: Function SIP_HEADER(x-accountcode) result is 'c1nb2-095889235626776' [2018-03-13 12:35:00.270] DEBUG[2869][C-00000000] pbx.c: Launching 'ExecIf' [2018-03-13 12:35:00.270] VERBOSE[2869][C-00000000] pbx.c: Executing [s@macro-get_headers_outbound:7] ExecIf("SIP/voxprox-dev01-00000000", "1?Set(__accountcode=c1nb2-095889235626776)") in new stack [2018-03-13 12:35:00.271] DEBUG[2869][C-00000000] app_macro.c: Executed application: ExecIf [2018-03-13 12:35:00.271] DEBUG[2869][C-00000000] pbx_variables.c: Evaluating 'SIP_HEADER(x-accountcode)' (from 'SIP_HEADER(x-accountcode)}" != ""' len 25) [2018-03-13 12:35:00.271] DEBUG[2869][C-00000000] pbx_variables.c: Function SIP_HEADER(x-accountcode) result is 'c1nb2-095889235626776' [2018-03-13 12:35:00.271] DEBUG[2869][C-00000000] pbx_variables.c: Expression result is '1' [2018-03-13 12:35:00.272] DEBUG[2869][C-00000000] pbx_variables.c: Evaluating 'SIP_HEADER(x-accountcode)' (from 'SIP_HEADER(x-accountcode)})' len 25) [2018-03-13 12:35:00.272] DEBUG[2869][C-00000000] pbx_variables.c: Function SIP_HEADER(x-accountcode) result is 'c1nb2-095889235626776' [2018-03-13 12:35:00.272] DEBUG[2869][C-00000000] pbx_variables.c: Result of 'ext' is '' [2018-03-13 12:35:00.272] DEBUG[2869][C-00000000] pbx_variables.c: Expression result is '1' [2018-03-13 12:35:00.272] DEBUG[2869][C-00000000] pbx_variables.c: Function SIP_HEADER(x-ext) result is '(null)' [2018-03-13 12:35:00.272] DEBUG[2869][C-00000000] pbx.c: Launching 'ExecIf' [2018-03-13 12:35:00.272] VERBOSE[2869][C-00000000] pbx.c: Executing [s@macro-get_headers_outbound:8] ExecIf("SIP/voxprox-dev01-00000000", "1?Set(ext=)") in new stack [2018-03-13 12:35:00.273] DEBUG[2869][C-00000000] app_macro.c: Executed application: ExecIf [2018-03-13 12:35:00.273] DEBUG[2869][C-00000000] pbx_variables.c: Evaluating 'ext' (from 'ext}" = ""' len 3) [2018-03-13 12:35:00.273] DEBUG[2869][C-00000000] pbx_variables.c: Result of 'ext' is '' [2018-03-13 12:35:00.273] DEBUG[2869][C-00000000] pbx_variables.c: Expression result is '1' [2018-03-13 12:35:00.273] DEBUG[2869][C-00000000] pbx_variables.c: Evaluating 'SIP_HEADER(x-ext)' (from 'SIP_HEADER(x-ext)})' len 17) [2018-03-13 12:35:00.273] DEBUG[2869][C-00000000] pbx_variables.c: Function SIP_HEADER(x-ext) result is '(null)' [2018-03-13 12:35:00.273] DEBUG[2869][C-00000000] pbx_variables.c: Result of 'x-carrier-id' is NULL [2018-03-13 12:35:00.274] DEBUG[2869][C-00000000] pbx_variables.c: Function ISNULL() result is '1' [2018-03-13 12:35:00.274] DEBUG[2869][C-00000000] pbx_variables.c: Expression result is '1' [2018-03-13 12:35:00.274] DEBUG[2869][C-00000000] pbx_variables.c: Function SIP_HEADER(x-carrier-id) result is '666' [2018-03-13 12:35:00.274] DEBUG[2869][C-00000000] pbx.c: Launching 'ExecIf' [2018-03-13 12:35:00.274] VERBOSE[2869][C-00000000] pbx.c: Executing [s@macro-get_headers_outbound:9] ExecIf("SIP/voxprox-dev01-00000000", "1?Set(x-carrier-id=666)") in new stack [2018-03-13 12:35:00.275] DEBUG[2869][C-00000000] app_macro.c: Executed application: ExecIf [2018-03-13 12:35:00.275] DEBUG[2869][C-00000000] pbx_variables.c: Evaluating 'ISNULL(${x-carrier-id})' (from 'ISNULL(${x-carrier-id})} = 1' len 23) [2018-03-13 12:35:00.275] DEBUG[2869][C-00000000] pbx_variables.c: Evaluating 'x-carrier-id' (from 'x-carrier-id})' len 12) [2018-03-13 12:35:00.275] DEBUG[2869][C-00000000] pbx_variables.c: Result of 'x-carrier-id' is '666' [2018-03-13 12:35:00.275] DEBUG[2869][C-00000000] pbx_variables.c: Function ISNULL(666) result is '0' [2018-03-13 12:35:00.275] DEBUG[2869][C-00000000] pbx_variables.c: Expression result is '0' [2018-03-13 12:35:00.275] DEBUG[2869][C-00000000] pbx_variables.c: Evaluating 'SIP_HEADER(x-carrier-id)' (from 'SIP_HEADER(x-carrier-id)})' len 24) [2018-03-13 12:35:00.275] DEBUG[2869][C-00000000] pbx_variables.c: Function SIP_HEADER(x-carrier-id) result is '666' [2018-03-13 12:35:00.275] DEBUG[2869][C-00000000] pbx_variables.c: Function SIP_HEADER(x-firstleg) result is '(null)' [2018-03-13 12:35:00.275] DEBUG[2869][C-00000000] pbx_variables.c: Expression result is '0' [2018-03-13 12:35:00.275] DEBUG[2869][C-00000000] pbx.c: Launching 'GotoIf' [2018-03-13 12:35:00.275] VERBOSE[2869][C-00000000] pbx.c: Executing [s@macro-get_headers_outbound:10] GotoIf("SIP/voxprox-dev01-00000000", "0?firstlegyes:firstlegno") in new stack [2018-03-13 12:35:00.276] VERBOSE[2869][C-00000000] pbx_builtins.c: Goto (macro-get_headers_outbound,s,13) [2018-03-13 12:35:00.276] DEBUG[2869][C-00000000] app_macro.c: Executed application: GotoIf [2018-03-13 12:35:00.276] DEBUG[2869][C-00000000] pbx.c: Launching 'NoOp' [2018-03-13 12:35:00.276] VERBOSE[2869][C-00000000] pbx.c: Executing [s@macro-get_headers_outbound:13] NoOp("SIP/voxprox-dev01-00000000", "Done") in new stack [2018-03-13 12:35:00.276] DEBUG[2869][C-00000000] app_macro.c: Executed application: NoOp [2018-03-13 12:35:00.277] DEBUG[2869][C-00000000] pbx.c: Launching 'Macro' [2018-03-13 12:35:00.277] VERBOSE[2869][C-00000000] pbx.c: Executing [17732507208@default:12] Macro("SIP/voxprox-dev01-00000000", "set_headers_outbound") in new stack [2018-03-13 12:35:00.278] DEBUG[2869][C-00000000] pbx.c: Launching 'NoOp' [2018-03-13 12:35:00.278] VERBOSE[2869][C-00000000] pbx.c: Executing [s@macro-set_headers_outbound:1] NoOp("SIP/voxprox-dev01-00000000", "Setting SIP headers for outbound call") in new stack [2018-03-13 12:35:00.278] DEBUG[2869][C-00000000] app_macro.c: Executed application: NoOp [2018-03-13 12:35:00.279] DEBUG[2869][C-00000000] pbx.c: Launching 'SIPRemoveHeader' [2018-03-13 12:35:00.279] VERBOSE[2869][C-00000000] pbx.c: Executing [s@macro-set_headers_outbound:2] SIPRemoveHeader("SIP/voxprox-dev01-00000000", "x-asterisk-outbound:") in new stack [2018-03-13 12:35:00.279] DEBUG[2869][C-00000000] app_macro.c: Executed application: SIPRemoveHeader [2018-03-13 12:35:00.279] DEBUG[2869][C-00000000] pbx.c: Launching 'SIPAddHeader' [2018-03-13 12:35:00.279] VERBOSE[2869][C-00000000] pbx.c: Executing [s@macro-set_headers_outbound:3] SIPAddHeader("SIP/voxprox-dev01-00000000", "x-asterisk-outbound: yes") in new stack [2018-03-13 12:35:00.280] DEBUG[2869][C-00000000] app_macro.c: Executed application: SipAddHeader [2018-03-13 12:35:00.280] DEBUG[2869][C-00000000] pbx.c: Launching 'SIPRemoveHeader' [2018-03-13 12:35:00.280] VERBOSE[2869][C-00000000] pbx.c: Executing [s@macro-set_headers_outbound:4] SIPRemoveHeader("SIP/voxprox-dev01-00000000", "X-IBP-NoRecord:") in new stack [2018-03-13 12:35:00.280] DEBUG[2869][C-00000000] app_macro.c: Executed application: SIPRemoveHeader [2018-03-13 12:35:00.290] DEBUG[2869][C-00000000] pbx_variables.c: Result of 'x-ibp-norecord' is NULL [2018-03-13 12:35:00.290] DEBUG[2869][C-00000000] pbx_variables.c: Result of 'firstleg' is NULL [2018-03-13 12:35:00.290] DEBUG[2869][C-00000000] pbx_variables.c: Expression result is '1' [2018-03-13 12:35:00.290] DEBUG[2869][C-00000000] pbx.c: Launching 'ExecIf' [2018-03-13 12:35:00.290] VERBOSE[2869][C-00000000] pbx.c: Executing [s@macro-set_headers_outbound:5] ExecIf("SIP/voxprox-dev01-00000000", "1?Set(__x-ibp-norecord=-ccap)") in new stack [2018-03-13 12:35:00.291] DEBUG[2869][C-00000000] app_macro.c: Executed application: ExecIf [2018-03-13 12:35:00.291] DEBUG[2869][C-00000000] pbx_variables.c: Evaluating 'x-ibp-norecord' (from 'x-ibp-norecord}" = "" && "${firstleg}" = ""' len 14) [2018-03-13 12:35:00.291] DEBUG[2869][C-00000000] pbx_variables.c: Result of 'x-ibp-norecord' is '-ccap' [2018-03-13 12:35:00.291] DEBUG[2869][C-00000000] pbx_variables.c: Evaluating 'firstleg' (from 'firstleg}" = ""' len 8) [2018-03-13 12:35:00.291] DEBUG[2869][C-00000000] pbx_variables.c: Result of 'firstleg' is NULL [2018-03-13 12:35:00.291] DEBUG[2869][C-00000000] pbx_variables.c: Expression result is '0' [2018-03-13 12:35:00.291] DEBUG[2869][C-00000000] pbx_variables.c: Result of 'x-ibp-norecord' is '-ccap' [2018-03-13 12:35:00.291] DEBUG[2869][C-00000000] pbx_variables.c: Expression result is '1' [2018-03-13 12:35:00.291] DEBUG[2869][C-00000000] pbx_variables.c: Result of 'x-ibp-norecord' is '-ccap' [2018-03-13 12:35:00.291] DEBUG[2869][C-00000000] pbx.c: Launching 'ExecIf' [2018-03-13 12:35:00.292] VERBOSE[2869][C-00000000] pbx.c: Executing [s@macro-set_headers_outbound:6] ExecIf("SIP/voxprox-dev01-00000000", "1?SipAddHeader(X-IBP-NoRecord: -ccap)") in new stack [2018-03-13 12:35:00.292] DEBUG[2869][C-00000000] app_macro.c: Executed application: ExecIf [2018-03-13 12:35:00.292] DEBUG[2869][C-00000000] pbx_variables.c: Evaluating 'x-ibp-norecord' (from 'x-ibp-norecord}" != ""' len 14) [2018-03-13 12:35:00.292] DEBUG[2869][C-00000000] pbx_variables.c: Result of 'x-ibp-norecord' is '-ccap' [2018-03-13 12:35:00.293] DEBUG[2869][C-00000000] pbx_variables.c: Expression result is '1' [2018-03-13 12:35:00.293] DEBUG[2869][C-00000000] pbx_variables.c: Evaluating 'x-ibp-norecord' (from 'x-ibp-norecord})' len 14) [2018-03-13 12:35:00.293] DEBUG[2869][C-00000000] pbx_variables.c: Result of 'x-ibp-norecord' is '-ccap' [2018-03-13 12:35:00.293] DEBUG[2869][C-00000000] pbx.c: Launching 'SIPRemoveHeader' [2018-03-13 12:35:00.293] VERBOSE[2869][C-00000000] pbx.c: Executing [s@macro-set_headers_outbound:7] SIPRemoveHeader("SIP/voxprox-dev01-00000000", "X-IBP-Unique-ID:") in new stack [2018-03-13 12:35:00.293] DEBUG[2869][C-00000000] app_macro.c: Executed application: SIPRemoveHeader [2018-03-13 12:35:00.293] DEBUG[2869][C-00000000] pbx_variables.c: Result of 'X-IBP-Unique-ID' is '6LqvrJwpKonqyLMHDIKGyIEEGsEzILqKGGxsHwnF' [2018-03-13 12:35:00.293] DEBUG[2869][C-00000000] pbx_variables.c: Expression result is '1' [2018-03-13 12:35:00.294] DEBUG[2869][C-00000000] pbx_variables.c: Result of 'X-IBP-Unique-ID' is '6LqvrJwpKonqyLMHDIKGyIEEGsEzILqKGGxsHwnF' [2018-03-13 12:35:00.294] DEBUG[2869][C-00000000] pbx.c: Launching 'ExecIf' [2018-03-13 12:35:00.294] VERBOSE[2869][C-00000000] pbx.c: Executing [s@macro-set_headers_outbound:8] ExecIf("SIP/voxprox-dev01-00000000", "1?SipAddHeader(X-IBP-Unique-ID: 6LqvrJwpKonqyLMHDIKGyIEEGsEzILqKGGxsHwnF)") in new stack [2018-03-13 12:35:00.294] DEBUG[2869][C-00000000] app_macro.c: Executed application: ExecIf [2018-03-13 12:35:00.295] DEBUG[2869][C-00000000] pbx_variables.c: Evaluating 'X-IBP-Unique-ID' (from 'X-IBP-Unique-ID}" != ""' len 15) [2018-03-13 12:35:00.295] DEBUG[2869][C-00000000] pbx_variables.c: Result of 'X-IBP-Unique-ID' is '6LqvrJwpKonqyLMHDIKGyIEEGsEzILqKGGxsHwnF' [2018-03-13 12:35:00.295] DEBUG[2869][C-00000000] pbx_variables.c: Expression result is '1' [2018-03-13 12:35:00.295] DEBUG[2869][C-00000000] pbx_variables.c: Evaluating 'X-IBP-Unique-ID' (from 'X-IBP-Unique-ID})' len 15) [2018-03-13 12:35:00.295] DEBUG[2869][C-00000000] pbx_variables.c: Result of 'X-IBP-Unique-ID' is '6LqvrJwpKonqyLMHDIKGyIEEGsEzILqKGGxsHwnF' [2018-03-13 12:35:00.295] DEBUG[2869][C-00000000] pbx.c: Launching 'SIPRemoveHeader' [2018-03-13 12:35:00.295] VERBOSE[2869][C-00000000] pbx.c: Executing [s@macro-set_headers_outbound:9] SIPRemoveHeader("SIP/voxprox-dev01-00000000", "x-carrier-id:") in new stack [2018-03-13 12:35:00.295] DEBUG[2869][C-00000000] app_macro.c: Executed application: SIPRemoveHeader [2018-03-13 12:35:00.296] DEBUG[2869][C-00000000] pbx_variables.c: Result of 'accountcode' is 'c1nb2-095889235626776' [2018-03-13 12:35:00.296] DEBUG[2869][C-00000000] pbx.c: Launching 'Set' [2018-03-13 12:35:00.296] VERBOSE[2869][C-00000000] pbx.c: Executing [s@macro-set_headers_outbound:10] Set("SIP/voxprox-dev01-00000000", "CDR(accountcode)=c1nb2-095889235626776") in new stack [2018-03-13 12:35:00.296] WARNING[2869][C-00000000] func_cdr.c: Using the CDR function to set 'accountcode' is deprecated. Please use the CHANNEL function instead. [2018-03-13 12:35:00.296] DEBUG[2869][C-00000000] app_macro.c: Executed application: Set [2018-03-13 12:35:00.297] DEBUG[2869][C-00000000] pbx_variables.c: Result of 'x-carrier-id' is '666' [2018-03-13 12:35:00.297] DEBUG[2869][C-00000000] pbx_variables.c: Expression result is '1' [2018-03-13 12:35:00.297] DEBUG[2869][C-00000000] pbx_variables.c: Result of 'x-carrier-id' is '666' [2018-03-13 12:35:00.297] DEBUG[2869][C-00000000] pbx.c: Launching 'ExecIf' [2018-03-13 12:35:00.297] VERBOSE[2869][C-00000000] pbx.c: Executing [s@macro-set_headers_outbound:11] ExecIf("SIP/voxprox-dev01-00000000", "1?SIPAddHeader(x-carrier-id: 666)") in new stack [2018-03-13 12:35:00.298] DEBUG[2869][C-00000000] app_macro.c: Executed application: ExecIf [2018-03-13 12:35:00.298] DEBUG[2869][C-00000000] pbx_variables.c: Evaluating 'x-carrier-id' (from 'x-carrier-id}" != ""' len 12) [2018-03-13 12:35:00.298] DEBUG[2869][C-00000000] pbx_variables.c: Result of 'x-carrier-id' is '666' [2018-03-13 12:35:00.298] DEBUG[2869][C-00000000] pbx_variables.c: Expression result is '1' [2018-03-13 12:35:00.298] DEBUG[2869][C-00000000] pbx_variables.c: Evaluating 'x-carrier-id' (from 'x-carrier-id})' len 12) [2018-03-13 12:35:00.298] DEBUG[2869][C-00000000] pbx_variables.c: Result of 'x-carrier-id' is '666' [2018-03-13 12:35:00.299] DEBUG[2869][C-00000000] pbx_variables.c: Result of 'x-dial_timeout' is NULL [2018-03-13 12:35:00.299] DEBUG[2869][C-00000000] pbx_variables.c: Function ISNULL() result is '1' [2018-03-13 12:35:00.299] DEBUG[2869][C-00000000] pbx_variables.c: Expression result is '1' [2018-03-13 12:35:00.299] DEBUG[2869][C-00000000] pbx.c: Launching 'ExecIf' [2018-03-13 12:35:00.299] VERBOSE[2869][C-00000000] pbx.c: Executing [17732507208@default:13] ExecIf("SIP/voxprox-dev01-00000000", "1?Set(x-dial_timeout=120)") in new stack [2018-03-13 12:35:00.300] DEBUG[2869][C-00000000] pbx_variables.c: Result of 'SIPREFER' is NULL [2018-03-13 12:35:00.300] DEBUG[2869][C-00000000] pbx_variables.c: Expression result is '0' [2018-03-13 12:35:00.300] DEBUG[2869][C-00000000] pbx_variables.c: Result of 'SIPREFER' is NULL [2018-03-13 12:35:00.300] DEBUG[2869][C-00000000] pbx.c: Launching 'ExecIf' [2018-03-13 12:35:00.300] VERBOSE[2869][C-00000000] pbx.c: Executing [17732507208@default:14] ExecIf("SIP/voxprox-dev01-00000000", "0?AGI(get_refer_params.php,)") in new stack [2018-03-13 12:35:00.300] DEBUG[2869][C-00000000] pbx.c: Launching 'AGI' [2018-03-13 12:35:00.300] VERBOSE[2869][C-00000000] pbx.c: Executing [17732507208@default:15] AGI("SIP/voxprox-dev01-00000000", "get_proxy_ip.php") in new stack [2018-03-13 12:35:00.303] VERBOSE[2869][C-00000000] res_agi.c: Launched AGI Script /var/lib/asterisk/agi-bin/get_proxy_ip.php [2018-03-13 12:35:00.347] DEBUG[2869][C-00000000] utils.c: write() failed due to reading end being closed: Broken pipe [2018-03-13 12:35:00.347] VERBOSE[2869][C-00000000] res_agi.c: AGI Script get_proxy_ip.php completed, returning 0 [2018-03-13 12:35:00.347] DEBUG[2869][C-00000000] pbx_variables.c: Result of 'CHANNEL' is 'SIP/voxprox-dev01-00000000' [2018-03-13 12:35:00.348] DEBUG[2869][C-00000000] pbx.c: Launching 'Set' [2018-03-13 12:35:00.348] VERBOSE[2869][C-00000000] pbx.c: Executing [17732507208@default:16] Set("SIP/voxprox-dev01-00000000", "_parent_channel=SIP/voxprox-dev01-00000000") in new stack [2018-03-13 12:35:00.348] DEBUG[2869][C-00000000] pbx_variables.c: Function STRFTIME(,,%s.%3q) result is '1520958900.348' [2018-03-13 12:35:00.348] DEBUG[2869][C-00000000] pbx.c: Launching 'Set' [2018-03-13 12:35:00.348] VERBOSE[2869][C-00000000] pbx.c: Executing [17732507208@default:17] Set("SIP/voxprox-dev01-00000000", "dialtime=1520958900.348") in new stack [2018-03-13 12:35:00.349] DEBUG[2869][C-00000000] pbx.c: Launching 'DumpChan' [2018-03-13 12:35:00.349] VERBOSE[2869][C-00000000] pbx.c: Executing [17732507208@default:18] DumpChan("SIP/voxprox-dev01-00000000", "") in new stack [2018-03-13 12:35:00.349] VERBOSE[2869][C-00000000] app_dumpchan.c: Dumping Info For Channel: SIP/voxprox-dev01-00000000: ================================================================================ Info: Name= SIP/voxprox-dev01-00000000 Type= SIP UniqueID= ast-dev01.dialogtech.com-1520958900.0 LinkedID= ast-dev01.dialogtech.com-1520958900.0 CallerIDNum= 13129990302 CallerIDName= 13129990302 ConnectedLineIDNum= (N/A) ConnectedLineIDName=(N/A) DNIDDigits= 17732507208 RDNIS= (N/A) Parkinglot= default Language= en State= Ring (4) Rings= 0 NativeFormat= (ulaw) WriteFormat= ulaw ReadFormat= ulaw RawWriteFormat= ulaw RawReadFormat= ulaw WriteTranscode= No ReadTranscode= No 1stFileDescriptor= 17 Framesin= 0 Framesout= 0 TimetoHangup= 0 ElapsedTime= 0h0m0s BridgeID= (Not bridged) Context= default Extension= 17732507208 Priority= 18 CallGroup= PickupGroup= Application= DumpChan Data= (Empty) Blocking_in= (Not Blocking) Variables: dialtime=1520958900.348 parent_channel=SIP/voxprox-dev01-00000000 AGISTATUS=SUCCESS proxy_ip=10.1.144.4 x-dial_timeout=120 MACRO_DEPTH=0 SIPADDHEADER04=x-carrier-id: 666 SIPADDHEADER03=X-IBP-Unique-ID: 6LqvrJwpKonqyLMHDIKGyIEEGsEzILqKGGxsHwnF SIPADDHEADER02=X-IBP-NoRecord: -ccap x-ibp-norecord=-ccap SIPADDHEADER01=x-asterisk-outbound: yes x-carrier-id=666 ext= accountcode=c1nb2-095889235626776 X-IBP-Unique-ID=6LqvrJwpKonqyLMHDIKGyIEEGsEzILqKGGxsHwnF x-limit_playaudio_caller=no warning-audio=this-call-may-be-monitored-or-recorded refercall= inboundmergehack=1 newdnis=17732507208 SIPCALLID=1520958900229-7f0c0893e430-0820b490-000006c5@10.1.144.14 SIPDOMAIN=10.1.144.6 SIPURI=sip:13129990302@10.1.144.14:5060 ================================================================================ [2018-03-13 12:35:00.349] DEBUG[2869][C-00000000] pbx_variables.c: Result of 'proxy_ip' is '10.1.144.4' [2018-03-13 12:35:00.349] DEBUG[2869][C-00000000] pbx_variables.c: Result of 'EXTEN' is '17732507208' [2018-03-13 12:35:00.349] DEBUG[2869][C-00000000] pbx_variables.c: Result of 'x-dial_timeout' is '120' [2018-03-13 12:35:00.349] DEBUG[2869][C-00000000] pbx_variables.c: Result of 'ext' is '' [2018-03-13 12:35:00.349] DEBUG[2869][C-00000000] pbx_variables.c: Result of 'dialtime' is '1520958900.348' [2018-03-13 12:35:00.349] DEBUG[2869][C-00000000] pbx_variables.c: Result of 'x-limit_playaudio_callee' is NULL [2018-03-13 12:35:00.349] DEBUG[2869][C-00000000] pbx_variables.c: Result of 'x-limit_connect_file' is NULL [2018-03-13 12:35:00.350] DEBUG[2869][C-00000000] pbx.c: Launching 'Dial' [2018-03-13 12:35:00.350] VERBOSE[2869][C-00000000] pbx.c: Executing [17732507208@default:19] Dial("SIP/voxprox-dev01-00000000", "SIP/10.1.144.4/17732507208,120,L(28800000)M(play_callee_warning,,1520958900.348,,)") in new stack [2018-03-13 12:35:00.351] VERBOSE[2869][C-00000000] features.c: Setting call duration limit to 28800.000 seconds. [2018-03-13 12:35:00.351] DEBUG[2869][C-00000000] chan_sip.c: Asked to create a SIP channel with formats: (ulaw) [2018-03-13 12:35:00.351] DEBUG[2869][C-00000000] chan_sip.c: Allocating new SIP dialog for 2c76df9c4b9a5cfa14abd11026dcf251@10.1.144.6:5060 - INVITE (No RTP) [2018-03-13 12:35:00.351] DEBUG[2869][C-00000000] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7f920c031b08' [2018-03-13 12:35:00.352] DEBUG[2869][C-00000000] res_rtp_asterisk.c: Allocated port 26406 for RTP instance '0x7f920c031b08' [2018-03-13 12:35:00.352] DEBUG[2869][C-00000000] rtp_engine.c: RTP instance '0x7f920c031b08' is setup and ready to go [2018-03-13 12:35:00.352] DEBUG[2869][C-00000000] netsock2.c: Splitting 'ast-dev01.dialogtech.com' into... [2018-03-13 12:35:00.352] DEBUG[2869][C-00000000] netsock2.c: ...host 'ast-dev01.dialogtech.com' and port ''. [2018-03-13 12:35:00.352] DEBUG[2869][C-00000000] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7f920c031b08' [2018-03-13 12:35:00.352] VERBOSE[2869][C-00000000] netsock2.c: Using SIP RTP CoS mark 5 [2018-03-13 12:35:00.352] DEBUG[2869][C-00000000] chan_sip.c: Setting NAT on RTP to Off [2018-03-13 12:35:00.356] DEBUG[2869][C-00000000] netsock2.c: Splitting '10.1.144.4' into... [2018-03-13 12:35:00.356] DEBUG[2869][C-00000000] netsock2.c: ...host '10.1.144.4' and port ''. [2018-03-13 12:35:00.356] DEBUG[2869][C-00000000] acl.c: For destination '10.1.144.4', our source address is '10.1.144.6'. [2018-03-13 12:35:00.357] DEBUG[2869][C-00000000] chan_sip.c: Setting AST_TRANSPORT_UDP with address 10.1.144.6:5060 [2018-03-13 12:35:00.357] DEBUG[2869][C-00000000] chan_sip.c: Setting NAT on RTP to Off [2018-03-13 12:35:00.357] DEBUG[2869][C-00000000] chan_sip.c: SIP call-id changed from '2c76df9c4b9a5cfa14abd11026dcf251@10.1.144.6:5060' to '53d350be226bf3ee6306cdd525115013@10.1.144.6:5060' [2018-03-13 12:35:00.357] DEBUG[2869][C-00000000] channel.c: Channel 0x7f920c02dba8 'SIP/10.1.144.4-00000001' allocated [2018-03-13 12:35:00.357] DEBUG[2869][C-00000000] chan_sip.c: *** Our native formats are (ulaw) [2018-03-13 12:35:00.358] DEBUG[2869][C-00000000] chan_sip.c: *** Joint capabilities are (ulaw) [2018-03-13 12:35:00.358] DEBUG[2869][C-00000000] chan_sip.c: *** Our capabilities are (ulaw) [2018-03-13 12:35:00.358] DEBUG[2869][C-00000000] chan_sip.c: *** AST_CODEC_CHOOSE formats are ulaw [2018-03-13 12:35:00.358] DEBUG[2869][C-00000000] chan_sip.c: *** Our preferred formats from the incoming channel are (ulaw) [2018-03-13 12:35:00.358] DEBUG[2869][C-00000000] chan_sip.c: This channel will not be able to handle video. [2018-03-13 12:35:00.358] DEBUG[2869][C-00000000] channel_internal_api.c: Channel Call ID changing from [C-00000000] to [C-00000000] [2018-03-13 12:35:00.358] DEBUG[2869][C-00000000] channel.c: Inheriting variable parent_channel from SIP/voxprox-dev01-00000000 to SIP/10.1.144.4-00000001. [2018-03-13 12:35:00.359] DEBUG[2869][C-00000000] channel.c: Inheriting variable __SIPADDHEADER04 from SIP/voxprox-dev01-00000000 to SIP/10.1.144.4-00000001. [2018-03-13 12:35:00.359] DEBUG[2869][C-00000000] channel.c: Inheriting variable __SIPADDHEADER03 from SIP/voxprox-dev01-00000000 to SIP/10.1.144.4-00000001. [2018-03-13 12:35:00.359] DEBUG[2869][C-00000000] channel.c: Inheriting variable __SIPADDHEADER02 from SIP/voxprox-dev01-00000000 to SIP/10.1.144.4-00000001. [2018-03-13 12:35:00.359] DEBUG[2869][C-00000000] channel.c: Inheriting variable __x-ibp-norecord from SIP/voxprox-dev01-00000000 to SIP/10.1.144.4-00000001. [2018-03-13 12:35:00.359] DEBUG[2869][C-00000000] channel.c: Inheriting variable __SIPADDHEADER01 from SIP/voxprox-dev01-00000000 to SIP/10.1.144.4-00000001. [2018-03-13 12:35:00.359] DEBUG[2869][C-00000000] channel.c: Inheriting variable __accountcode from SIP/voxprox-dev01-00000000 to SIP/10.1.144.4-00000001. [2018-03-13 12:35:00.360] DEBUG[2869][C-00000000] chan_sip.c: Outgoing Call for 17732507208 [2018-03-13 12:35:00.360] DEBUG[2869][C-00000000] chan_sip.c: Updating call counter for outgoing call [2018-03-13 12:35:00.362] DEBUG[2869][C-00000000] chan_sip.c: ** Our capability: (ulaw) Video flag: False Text flag: False [2018-03-13 12:35:00.362] DEBUG[2869][C-00000000] chan_sip.c: ** Our prefcodec: (ulaw) [2018-03-13 12:35:00.362] DEBUG[2869][C-00000000] chan_sip.c: -- Done with adding codecs to SDP [2018-03-13 12:35:00.362] DEBUG[2869][C-00000000] chan_sip.c: Done building SDP. Settling with this capability: (ulaw) [2018-03-13 12:35:00.362] DEBUG[2869][C-00000000] chan_sip.c: Initializing initreq for method INVITE - callid 53d350be226bf3ee6306cdd525115013@10.1.144.6:5060 [2018-03-13 12:35:00.362] DEBUG[2869][C-00000000] chan_sip.c: Trying to put 'INVITE sip:' onto UDP socket destined for 10.1.144.4:5060 [2018-03-13 12:35:00.363] VERBOSE[2869][C-00000000] app_dial.c: Called SIP/10.1.144.4/17732507208 [2018-03-13 12:35:00.365] DEBUG[2830] chan_sip.c: = Looking for Call ID: 53d350be226bf3ee6306cdd525115013@10.1.144.6:5060 (Checking To) --From tag as00a81d6c --To-tag [2018-03-13 12:35:00.365] DEBUG[2830][C-00000000] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '53d350be226bf3ee6306cdd525115013@10.1.144.6:5060' Request 102: Found [2018-03-13 12:35:00.365] DEBUG[2830][C-00000000] chan_sip.c: SIP response 100 to standard invite [2018-03-13 12:35:03.534] DEBUG[2830] chan_sip.c: = Looking for Call ID: 53d350be226bf3ee6306cdd525115013@10.1.144.6:5060 (Checking To) --From tag as00a81d6c --To-tag KU038D3Bj4jDK [2018-03-13 12:35:03.534] DEBUG[2830][C-00000000] chan_sip.c: Acked pending invite 102 [2018-03-13 12:35:03.534] DEBUG[2830][C-00000000] chan_sip.c: Stopping retransmission on '53d350be226bf3ee6306cdd525115013@10.1.144.6:5060' of Request 102: Match Found [2018-03-13 12:35:03.534] DEBUG[2830][C-00000000] chan_sip.c: SIP response 200 to standard invite [2018-03-13 12:35:03.534] DEBUG[2830][C-00000000] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED OR FAILED. [2018-03-13 12:35:03.534] DEBUG[2830][C-00000000] chan_sip.c: Processing session-level SDP o=FreeSWITCH 1520928871 1520928872 IN IP4 192.168.11.176... OK. [2018-03-13 12:35:03.534] DEBUG[2830][C-00000000] chan_sip.c: Processing session-level SDP s=FreeSWITCH... UNSUPPORTED OR FAILED. [2018-03-13 12:35:03.534] DEBUG[2830][C-00000000] netsock2.c: Splitting '192.168.11.176' into... [2018-03-13 12:35:03.534] DEBUG[2830][C-00000000] netsock2.c: ...host '192.168.11.176' and port ''. [2018-03-13 12:35:03.534] DEBUG[2830][C-00000000] chan_sip.c: Processing session-level SDP c=IN IP4 192.168.11.176... OK. [2018-03-13 12:35:03.534] DEBUG[2830][C-00000000] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED. [2018-03-13 12:35:03.534] DEBUG[2830][C-00000000] rtp_engine.c: Setting tx payload type 0 based on m type on 0x7f91e14074f0 [2018-03-13 12:35:03.535] DEBUG[2830][C-00000000] rtp_engine.c: Setting tx payload type 101 based on m type on 0x7f91e14074f0 [2018-03-13 12:35:03.535] DEBUG[2830][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. [2018-03-13 12:35:03.535] DEBUG[2830][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [2018-03-13 12:35:03.535] DEBUG[2830][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-16... UNSUPPORTED OR FAILED. [2018-03-13 12:35:03.535] DEBUG[2830][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=ptime:20... OK. [2018-03-13 12:35:03.535] DEBUG[2830][C-00000000] acl.c: For destination '192.168.11.176', our source address is '10.1.144.6'. [2018-03-13 12:35:03.535] DEBUG[2830][C-00000000] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7f920c031b08' [2018-03-13 12:35:03.535] VERBOSE[2830][C-00000000] res_rtp_asterisk.c: 0x7f920c01ce90 -- Strict RTP learning after remote address set to: 192.168.11.176:30032 [2018-03-13 12:35:03.535] DEBUG[2830][C-00000000] rtp_engine.c: Copying payload 0 (0x7f921000dfb0) from 0x7f91e14074f0 to 0x7f920c031cd0 [2018-03-13 12:35:03.535] DEBUG[2830][C-00000000] rtp_engine.c: Copying payload 101 (0x7f921000e850) from 0x7f91e14074f0 to 0x7f920c031cd0 [2018-03-13 12:35:03.535] DEBUG[2830][C-00000000] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x7f920c031b08' [2018-03-13 12:35:03.535] DEBUG[2830][C-00000000] chan_sip.c: We're settling with these formats: (ulaw) [2018-03-13 12:35:03.535] DEBUG[2830][C-00000000] chan_sip.c: We have an owner, now see if we need to change this call [2018-03-13 12:35:03.536] DEBUG[2830][C-00000000] chan_sip.c: Updating call counter for outgoing call [2018-03-13 12:35:03.536] DEBUG[2830][C-00000000] sip/route.c: sip_route_process_header: [2018-03-13 12:35:03.536] DEBUG[2830][C-00000000] netsock2.c: Splitting '192.168.11.176:5060' into... [2018-03-13 12:35:03.536] DEBUG[2830][C-00000000] netsock2.c: ...host '192.168.11.176' and port '5060'. [2018-03-13 12:35:03.536] DEBUG[2830][C-00000000] netsock2.c: Splitting '10.1.144.4' into... [2018-03-13 12:35:03.536] DEBUG[2830][C-00000000] netsock2.c: ...host '10.1.144.4' and port ''. [2018-03-13 12:35:03.536] DEBUG[2830][C-00000000] chan_sip.c: Trying to put 'ACK sip:177' onto UDP socket destined for 10.1.144.4:5060 [2018-03-13 12:35:03.537] VERBOSE[2869][C-00000000] app_dial.c: SIP/10.1.144.4-00000001 answered SIP/voxprox-dev01-00000000 [2018-03-13 12:35:03.538] DEBUG[2869][C-00000000] app.c: SIP/10.1.144.4-00000001 Original location: default,17732507208,1 [2018-03-13 12:35:03.540] DEBUG[2869][C-00000000] pbx_variables.c: Result of 'ARG1' is '' [2018-03-13 12:35:03.540] DEBUG[2869][C-00000000] pbx_variables.c: Result of 'ARG2' is '1520958900.348' [2018-03-13 12:35:03.540] DEBUG[2869][C-00000000] pbx.c: Launching 'Macro' [2018-03-13 12:35:03.540] VERBOSE[2869][C-00000000] pbx.c: Executing [s@macro-play_callee_warning:1] Macro("SIP/10.1.144.4-00000001", "ext,,1520958900.348") in new stack [2018-03-13 12:35:03.542] DEBUG[2869][C-00000000] pbx_variables.c: Function STRFTIME(,,%s.%3q) result is '1520958903.542' [2018-03-13 12:35:03.542] DEBUG[2869][C-00000000] pbx_variables.c: Result of 'ARG2' is '1520958900.348' [2018-03-13 12:35:03.542] DEBUG[2869][C-00000000] pbx.c: Launching 'NoOp' [2018-03-13 12:35:03.542] VERBOSE[2869][C-00000000] pbx.c: Executing [s@macro-ext:1] NoOp("SIP/10.1.144.4-00000001", "Set(SHARED(elapsed_ringing_time)=1520958903.542 - 1520958900.348)") in new stack [2018-03-13 12:35:03.542] DEBUG[2869][C-00000000] app_macro.c: Executed application: NoOp [2018-03-13 12:35:03.543] DEBUG[2869][C-00000000] pbx_variables.c: Result of 'parent_channel' is 'SIP/voxprox-dev01-00000000' [2018-03-13 12:35:03.543] DEBUG[2869][C-00000000] pbx_variables.c: Function STRFTIME(,,%s.%3q) result is '1520958903.543' [2018-03-13 12:35:03.543] DEBUG[2869][C-00000000] pbx_variables.c: Result of 'ARG2' is '1520958900.348' [2018-03-13 12:35:03.543] DEBUG[2869][C-00000000] pbx_variables.c: Expression result is '3.19499999994877726' [2018-03-13 12:35:03.543] DEBUG[2869][C-00000000] pbx.c: Launching 'Set' [2018-03-13 12:35:03.543] VERBOSE[2869][C-00000000] pbx.c: Executing [s@macro-ext:2] Set("SIP/10.1.144.4-00000001", "SHARED(elapsed_ringing_time,SIP/voxprox-dev01-00000000)=3.19499999994877726") in new stack [2018-03-13 12:35:03.544] DEBUG[2869][C-00000000] app_macro.c: Executed application: Set [2018-03-13 12:35:03.544] DEBUG[2869][C-00000000] pbx_variables.c: Result of 'SIPCALLID' is '53d350be226bf3ee6306cdd525115013@10.1.144.6:5060' [2018-03-13 12:35:03.544] DEBUG[2869][C-00000000] pbx.c: Launching 'NoOp' [2018-03-13 12:35:03.544] VERBOSE[2869][C-00000000] pbx.c: Executing [s@macro-ext:3] NoOp("SIP/10.1.144.4-00000001", "Outbound Call-ID: 53d350be226bf3ee6306cdd525115013@10.1.144.6:5060") in new stack [2018-03-13 12:35:03.544] DEBUG[2869][C-00000000] app_macro.c: Executed application: NoOp [2018-03-13 12:35:03.545] DEBUG[2869][C-00000000] pbx_variables.c: Result of 'ARG1' is '' [2018-03-13 12:35:03.545] DEBUG[2869][C-00000000] pbx_variables.c: Expression result is '0' [2018-03-13 12:35:03.545] DEBUG[2869][C-00000000] pbx.c: Launching 'ExecIf' [2018-03-13 12:35:03.545] VERBOSE[2869][C-00000000] pbx.c: Executing [s@macro-ext:4] ExecIf("SIP/10.1.144.4-00000001", "0?Playback(silence)") in new stack [2018-03-13 12:35:03.545] DEBUG[2869][C-00000000] app_macro.c: Executed application: ExecIf [2018-03-13 12:35:03.545] DEBUG[2869][C-00000000] pbx_variables.c: Evaluating 'ARG1' (from 'ARG1}" != ""' len 4) [2018-03-13 12:35:03.545] DEBUG[2869][C-00000000] pbx_variables.c: Result of 'ARG1' is '' [2018-03-13 12:35:03.545] DEBUG[2869][C-00000000] pbx_variables.c: Expression result is '0' [2018-03-13 12:35:03.546] DEBUG[2869][C-00000000] pbx_variables.c: Result of 'ARG1' is '' [2018-03-13 12:35:03.546] DEBUG[2869][C-00000000] pbx_variables.c: Expression result is '0' [2018-03-13 12:35:03.546] DEBUG[2869][C-00000000] pbx_variables.c: Result of 'ARG1' is '' [2018-03-13 12:35:03.546] DEBUG[2869][C-00000000] pbx.c: Launching 'ExecIf' [2018-03-13 12:35:03.546] VERBOSE[2869][C-00000000] pbx.c: Executing [s@macro-ext:5] ExecIf("SIP/10.1.144.4-00000001", "0?SendDTMF()") in new stack [2018-03-13 12:35:03.546] DEBUG[2869][C-00000000] app_macro.c: Executed application: ExecIf [2018-03-13 12:35:03.546] DEBUG[2869][C-00000000] pbx_variables.c: Evaluating 'ARG1' (from 'ARG1}" != ""' len 4) [2018-03-13 12:35:03.546] DEBUG[2869][C-00000000] pbx_variables.c: Result of 'ARG1' is '' [2018-03-13 12:35:03.546] DEBUG[2869][C-00000000] pbx_variables.c: Expression result is '0' [2018-03-13 12:35:03.546] DEBUG[2869][C-00000000] pbx_variables.c: Evaluating 'ARG1' (from 'ARG1})' len 4) [2018-03-13 12:35:03.546] DEBUG[2869][C-00000000] pbx_variables.c: Result of 'ARG1' is '' [2018-03-13 12:35:03.547] DEBUG[2869][C-00000000] app_macro.c: Executed application: Macro [2018-03-13 12:35:03.550] DEBUG[2808] devicestate.c: No provider found, checking channel drivers for SIP - 10.1.144.4 [2018-03-13 12:35:03.550] DEBUG[2808] chan_sip.c: Checking device state for peer 10.1.144.4 [2018-03-13 12:35:03.550] DEBUG[2808] devicestate.c: Changing state for SIP/10.1.144.4 - state 4 (Invalid) [2018-03-13 12:35:03.548] DEBUG[2869][C-00000000] pbx_variables.c: Result of 'ARG3' is '' [2018-03-13 12:35:03.551] DEBUG[2869][C-00000000] pbx_variables.c: Expression result is '0' [2018-03-13 12:35:03.551] DEBUG[2869][C-00000000] pbx_variables.c: Result of 'ARG4' is '' [2018-03-13 12:35:03.552] DEBUG[2869][C-00000000] pbx.c: Launching 'ExecIf' [2018-03-13 12:35:03.552] VERBOSE[2869][C-00000000] pbx.c: Executing [s@macro-play_callee_warning:2] ExecIf("SIP/10.1.144.4-00000001", "0?Playback()") in new stack [2018-03-13 12:35:03.552] DEBUG[2869][C-00000000] app_macro.c: Executed application: ExecIf [2018-03-13 12:35:03.552] DEBUG[2869][C-00000000] pbx_variables.c: Evaluating 'ARG3' (from 'ARG3}" = "yes"' len 4) [2018-03-13 12:35:03.552] DEBUG[2869][C-00000000] pbx_variables.c: Result of 'ARG3' is '' [2018-03-13 12:35:03.552] DEBUG[2869][C-00000000] pbx_variables.c: Expression result is '0' [2018-03-13 12:35:03.552] DEBUG[2869][C-00000000] pbx_variables.c: Evaluating 'ARG4' (from 'ARG4})' len 4) [2018-03-13 12:35:03.552] DEBUG[2869][C-00000000] pbx_variables.c: Result of 'ARG4' is '' [2018-03-13 12:35:03.553] DEBUG[2869][C-00000000] app.c: Macro exited with status 0 [2018-03-13 12:35:03.553] DEBUG[2869][C-00000000] app.c: SIP/10.1.144.4-00000001 Ending location: default,17732507208,1 [2018-03-13 12:35:03.555] DEBUG[2869][C-00000000] chan_sip.c: SIP answering channel: SIP/voxprox-dev01-00000000 [2018-03-13 12:35:03.555] DEBUG[2869][C-00000000] res_rtp_asterisk.c: Setting the marker bit due to a source update [2018-03-13 12:35:03.556] DEBUG[2869][C-00000000] chan_sip.c: ** Our capability: (ulaw) Video flag: True Text flag: True [2018-03-13 12:35:03.556] DEBUG[2869][C-00000000] chan_sip.c: ** Our prefcodec: (nothing) [2018-03-13 12:35:03.556] DEBUG[2869][C-00000000] chan_sip.c: -- Done with adding codecs to SDP [2018-03-13 12:35:03.556] DEBUG[2869][C-00000000] chan_sip.c: Setting framing on incoming call: 20 [2018-03-13 12:35:03.556] DEBUG[2869][C-00000000] chan_sip.c: Done building SDP. Settling with this capability: (ulaw) [2018-03-13 12:35:03.556] DEBUG[2869][C-00000000] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.1.174.33:5060 [2018-03-13 12:35:03.557] DEBUG[2869][C-00000000] bridge_native_rtp.c: Bridge 'f621f610-ee87-442e-bfdf-022922edda0d' can not use native RTP bridge as two channels are required [2018-03-13 12:35:03.557] DEBUG[2869][C-00000000] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge. [2018-03-13 12:35:03.557] DEBUG[2869][C-00000000] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [2018-03-13 12:35:03.557] DEBUG[2869][C-00000000] bridge.c: Chose bridge technology simple_bridge [2018-03-13 12:35:03.557] DEBUG[2869][C-00000000] bridge.c: Bridge f621f610-ee87-442e-bfdf-022922edda0d: calling simple_bridge technology constructor [2018-03-13 12:35:03.557] DEBUG[2869][C-00000000] bridge.c: Bridge f621f610-ee87-442e-bfdf-022922edda0d: calling simple_bridge technology start [2018-03-13 12:35:03.558] DEBUG[2808] devicestate.c: No provider found, checking channel drivers for SIP - voxprox-dev01 [2018-03-13 12:35:03.558] DEBUG[2808] chan_sip.c: Checking device state for peer voxprox-dev01 [2018-03-13 12:35:03.558] DEBUG[2808] devicestate.c: Changing state for SIP/voxprox-dev01 - state 1 (Not in use) [2018-03-13 12:35:03.558] DEBUG[2874][C-00000000] bridge_channel.c: Bridge f621f610-ee87-442e-bfdf-022922edda0d: 0x7f920c00cd78(SIP/10.1.144.4-00000001) is joining [2018-03-13 12:35:03.559] DEBUG[2874][C-00000000] bridge_channel.c: Bridge f621f610-ee87-442e-bfdf-022922edda0d: pushing 0x7f920c00cd78(SIP/10.1.144.4-00000001) [2018-03-13 12:35:03.559] VERBOSE[2874][C-00000000] bridge_channel.c: Channel SIP/10.1.144.4-00000001 joined 'simple_bridge' basic-bridge [2018-03-13 12:35:03.559] DEBUG[2874][C-00000000] bridge.c: Bridge technology softmix does not have any capabilities we want. [2018-03-13 12:35:03.559] DEBUG[2874][C-00000000] bridge_native_rtp.c: Bridge 'f621f610-ee87-442e-bfdf-022922edda0d' can not use native RTP bridge as two channels are required [2018-03-13 12:35:03.559] DEBUG[2874][C-00000000] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge. [2018-03-13 12:35:03.559] DEBUG[2874][C-00000000] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [2018-03-13 12:35:03.559] DEBUG[2874][C-00000000] bridge.c: Chose bridge technology simple_bridge [2018-03-13 12:35:03.559] DEBUG[2874][C-00000000] bridge.c: Bridge f621f610-ee87-442e-bfdf-022922edda0d is already using the new technology. [2018-03-13 12:35:03.559] DEBUG[2874][C-00000000] bridge.c: Bridge f621f610-ee87-442e-bfdf-022922edda0d: 0x7f920c00cd78(SIP/10.1.144.4-00000001) is joining simple_bridge technology [2018-03-13 12:35:03.560] DEBUG[2874][C-00000000] res_rtp_asterisk.c: Not changing SSRC since we haven't sent any RTP yet [2018-03-13 12:35:03.560] DEBUG[2830] chan_sip.c: = Looking for Call ID: 1520958900229-7f0c0893e430-0820b490-000006c5@10.1.144.14 (Checking From) --From tag 1c78725c-422bf87e-3361a7-8052ab8-0-13c4-7217 --To-tag as1f37e8d1 [2018-03-13 12:35:03.560] DEBUG[2830][C-00000000] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [2018-03-13 12:35:03.560] DEBUG[2830][C-00000000] chan_sip.c: Stopping retransmission on '1520958900229-7f0c0893e430-0820b490-000006c5@10.1.144.14' of Response 1: Match Found [2018-03-13 12:35:03.561] DEBUG[2869][C-00000000] bridge_channel.c: Bridge f621f610-ee87-442e-bfdf-022922edda0d: 0x7f920c01c138(SIP/voxprox-dev01-00000000) is joining [2018-03-13 12:35:03.561] DEBUG[2869][C-00000000] bridge_channel.c: Bridge f621f610-ee87-442e-bfdf-022922edda0d: pushing 0x7f920c01c138(SIP/voxprox-dev01-00000000) [2018-03-13 12:35:03.561] DEBUG[2869][C-00000000] bridge_channel.c: Setting channel SIP/voxprox-dev01-00000000 peeraccount with channel SIP/10.1.144.4-00000001 accountcode 'c1nb2-095889235626776'. [2018-03-13 12:35:03.562] VERBOSE[2869][C-00000000] bridge_channel.c: Channel SIP/voxprox-dev01-00000000 joined 'simple_bridge' basic-bridge [2018-03-13 12:35:03.562] DEBUG[2869][C-00000000] bridge.c: Bridge technology softmix does not have any capabilities we want. [2018-03-13 12:35:03.562] DEBUG[2869][C-00000000] bridge_native_rtp.c: Bridge 'f621f610-ee87-442e-bfdf-022922edda0d'. Checking compatability for channels 'SIP/10.1.144.4-00000001' and 'SIP/voxprox-dev01-00000000' [2018-03-13 12:35:03.562] DEBUG[2869][C-00000000] bridge.c: Bridge technology simple_bridge has less preference than native_rtp (50 <= 90). Skipping. [2018-03-13 12:35:03.562] DEBUG[2869][C-00000000] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [2018-03-13 12:35:03.563] DEBUG[2869][C-00000000] bridge.c: Chose bridge technology native_rtp [2018-03-13 12:35:03.563] VERBOSE[2869][C-00000000] bridge.c: Bridge f621f610-ee87-442e-bfdf-022922edda0d: switching from simple_bridge technology to native_rtp [2018-03-13 12:35:03.563] DEBUG[2869][C-00000000] bridge.c: Bridge f621f610-ee87-442e-bfdf-022922edda0d: calling native_rtp technology constructor [2018-03-13 12:35:03.563] DEBUG[2869][C-00000000] bridge.c: Bridge f621f610-ee87-442e-bfdf-022922edda0d: moving 0x7f920c00cd78(SIP/10.1.144.4-00000001) to dummy bridge temporarily [2018-03-13 12:35:03.563] DEBUG[2869][C-00000000] bridge.c: Bridge f621f610-ee87-442e-bfdf-022922edda0d: 0x7f920c00cd78(SIP/10.1.144.4-00000001) is leaving simple_bridge technology (dummy) [2018-03-13 12:35:03.563] DEBUG[2869][C-00000000] bridge.c: Bridge f621f610-ee87-442e-bfdf-022922edda0d: calling simple_bridge technology stop [2018-03-13 12:35:03.563] DEBUG[2869][C-00000000] bridge.c: Bridge f621f610-ee87-442e-bfdf-022922edda0d: 0x7f920c01c138(SIP/voxprox-dev01-00000000) is joining native_rtp technology [2018-03-13 12:35:03.563] DEBUG[2869][C-00000000] bridge_native_rtp.c: Bridge 'f621f610-ee87-442e-bfdf-022922edda0d'. Channel 'SIP/voxprox-dev01-00000000' is joining bridge tech [2018-03-13 12:35:03.563] DEBUG[2869][C-00000000] bridge_native_rtp.c: Bridge 'f621f610-ee87-442e-bfdf-022922edda0d'. Attaching hook data 0x7f920c03ce10 to 'SIP/voxprox-dev01-00000000' [2018-03-13 12:35:03.563] DEBUG[2869][C-00000000] bridge.c: Bridge f621f610-ee87-442e-bfdf-022922edda0d: 0x7f920c00cd78(SIP/10.1.144.4-00000001) is joining native_rtp technology [2018-03-13 12:35:03.563] DEBUG[2869][C-00000000] bridge_native_rtp.c: Bridge 'f621f610-ee87-442e-bfdf-022922edda0d'. Channel 'SIP/10.1.144.4-00000001' is joining bridge tech [2018-03-13 12:35:03.563] DEBUG[2869][C-00000000] bridge_native_rtp.c: Bridge 'f621f610-ee87-442e-bfdf-022922edda0d'. Attaching hook data 0x7f920c022140 to 'SIP/10.1.144.4-00000001' [2018-03-13 12:35:03.563] DEBUG[2869][C-00000000] bridge_native_rtp.c: Bridge 'f621f610-ee87-442e-bfdf-022922edda0d'. Tech starting 'SIP/voxprox-dev01-00000000' and 'SIP/10.1.144.4-00000001' with target 'none' [2018-03-13 12:35:03.563] VERBOSE[2869][C-00000000] bridge_native_rtp.c: Locally RTP bridged 'SIP/voxprox-dev01-00000000' and 'SIP/10.1.144.4-00000001' in stack [2018-03-13 12:35:03.563] DEBUG[2869][C-00000000] bridge.c: Bridge f621f610-ee87-442e-bfdf-022922edda0d: calling native_rtp technology start [2018-03-13 12:35:03.563] DEBUG[2869][C-00000000] bridge.c: Bridge f621f610-ee87-442e-bfdf-022922edda0d: calling simple_bridge technology destructor [2018-03-13 12:35:03.565] DEBUG[2869][C-00000000] res_rtp_asterisk.c: Not changing SSRC since we haven't sent any RTP yet [2018-03-13 12:35:03.565] DEBUG[2869][C-00000000] bridge.c: Bridge technology softmix does not have any capabilities we want. [2018-03-13 12:35:03.565] DEBUG[2869][C-00000000] bridge_native_rtp.c: Bridge 'f621f610-ee87-442e-bfdf-022922edda0d'. Checking compatability for channels 'SIP/voxprox-dev01-00000000' and 'SIP/10.1.144.4-00000001' [2018-03-13 12:35:03.565] DEBUG[2869][C-00000000] bridge.c: Bridge technology simple_bridge has less preference than native_rtp (50 <= 90). Skipping. [2018-03-13 12:35:03.566] DEBUG[2869][C-00000000] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [2018-03-13 12:35:03.566] DEBUG[2869][C-00000000] bridge.c: Chose bridge technology native_rtp [2018-03-13 12:35:03.566] DEBUG[2869][C-00000000] bridge.c: Bridge f621f610-ee87-442e-bfdf-022922edda0d is already using the new technology. [2018-03-13 12:35:03.567] VERBOSE[2869][C-00000000] res_rtp_asterisk.c: 0x7f9210012770 -- Strict RTP switching to RTP target address 10.1.144.14:10138 as source [2018-03-13 12:35:03.568] DEBUG[2869][C-00000000] res_rtp_asterisk.c: Feeding packet with duplicate timestamp to core [2018-03-13 12:35:03.570] DEBUG[2874][C-00000000] bridge.c: Bridge technology softmix does not have any capabilities we want. [2018-03-13 12:35:03.570] DEBUG[2874][C-00000000] bridge_native_rtp.c: Bridge 'f621f610-ee87-442e-bfdf-022922edda0d'. Checking compatability for channels 'SIP/voxprox-dev01-00000000' and 'SIP/10.1.144.4-00000001' [2018-03-13 12:35:03.570] DEBUG[2874][C-00000000] bridge.c: Bridge technology simple_bridge has less preference than native_rtp (50 <= 90). Skipping. [2018-03-13 12:35:03.570] DEBUG[2874][C-00000000] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [2018-03-13 12:35:03.570] DEBUG[2874][C-00000000] bridge.c: Chose bridge technology native_rtp [2018-03-13 12:35:03.570] DEBUG[2874][C-00000000] bridge.c: Bridge f621f610-ee87-442e-bfdf-022922edda0d is already using the new technology. [2018-03-13 12:35:03.572] DEBUG[2874][C-00000000] res_rtp_asterisk.c: Ooh, format changed from none to ulaw [2018-03-13 12:35:03.572] DEBUG[2874][C-00000000] res_rtp_asterisk.c: Starting RTCP transmission on RTP instance '0x7f920c031b08' [2018-03-13 12:35:03.621] VERBOSE[2874][C-00000000] res_rtp_asterisk.c: 0x7f920c01ce90 -- Strict RTP switching to RTP target address 192.168.11.176:30032 as source [2018-03-13 12:35:04.128] DEBUG[2830] chan_sip.c: = Looking for Call ID: 4f24d37f4243ed5f27fab5781883094e@192.168.10.202:5060 (Checking From) --From tag as3ec95e11 --To-tag [2018-03-13 12:35:04.129] DEBUG[2830] acl.c: For destination '192.168.10.202', our source address is '10.1.144.6'. [2018-03-13 12:35:04.129] DEBUG[2830] chan_sip.c: Setting AST_TRANSPORT_UDP with address 10.1.144.6:5060 [2018-03-13 12:35:04.129] DEBUG[2830] netsock2.c: Splitting '192.168.10.202:5060' into... [2018-03-13 12:35:04.129] DEBUG[2830] netsock2.c: ...host '192.168.10.202' and port '5060'. [2018-03-13 12:35:04.129] DEBUG[2830] chan_sip.c: Allocating new SIP dialog for 4f24d37f4243ed5f27fab5781883094e@192.168.10.202:5060 - INVITE (No RTP) [2018-03-13 12:35:04.129] DEBUG[2830][C-00000001] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [2018-03-13 12:35:04.129] DEBUG[2830][C-00000001] sip/reqresp_parser.c: Begin: parsing SIP "Supported: replaces, timer" [2018-03-13 12:35:04.129] DEBUG[2830][C-00000001] sip/reqresp_parser.c: Found SIP option: -replaces- [2018-03-13 12:35:04.129] DEBUG[2830][C-00000001] sip/reqresp_parser.c: Matched SIP option: replaces [2018-03-13 12:35:04.129] DEBUG[2830][C-00000001] sip/reqresp_parser.c: Found SIP option: -timer- [2018-03-13 12:35:04.129] DEBUG[2830][C-00000001] sip/reqresp_parser.c: Matched SIP option: timer [2018-03-13 12:35:04.129] DEBUG[2830][C-00000001] sip/reqresp_parser.c: Begin: parsing SIP "Supported: replaces" [2018-03-13 12:35:04.129] DEBUG[2830][C-00000001] sip/reqresp_parser.c: Found SIP option: -replaces- [2018-03-13 12:35:04.129] DEBUG[2830][C-00000001] sip/reqresp_parser.c: Matched SIP option: replaces [2018-03-13 12:35:04.129] DEBUG[2830][C-00000001] chan_sip.c: Looking for callid 1520958900229-7f0c0893e430-0820b490-000006c5@10.1.144.14 (fromtag 1c78725c-422bf87e-3361a7-8052ab8-0-13c4-7217 totag as1f37e8d1) [2018-03-13 12:35:04.129] DEBUG[2830][C-00000001] chan_sip.c: Matched INCOMING call - their tag is 1c78725c-422bf87e-3361a7-8052ab8-0-13c4-7217 Our tag is as1f37e8d1 [2018-03-13 12:35:04.129] DEBUG[2830][C-00000001] netsock2.c: Splitting '192.168.10.202:5060' into... [2018-03-13 12:35:04.129] DEBUG[2830][C-00000001] netsock2.c: ...host '192.168.10.202' and port '5060'. [2018-03-13 12:35:04.129] DEBUG[2830][C-00000001] netsock2.c: Splitting '192.168.10.202' into... [2018-03-13 12:35:04.129] DEBUG[2830][C-00000001] netsock2.c: ...host '192.168.10.202' and port ''. [2018-03-13 12:35:04.130] DEBUG[2830][C-00000001] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7f9210016788' [2018-03-13 12:35:04.130] DEBUG[2830][C-00000001] res_rtp_asterisk.c: Allocated port 16434 for RTP instance '0x7f9210016788' [2018-03-13 12:35:04.130] DEBUG[2830][C-00000001] rtp_engine.c: RTP instance '0x7f9210016788' is setup and ready to go [2018-03-13 12:35:04.130] DEBUG[2830][C-00000001] netsock2.c: Splitting 'ast-dev01.dialogtech.com' into... [2018-03-13 12:35:04.130] DEBUG[2830][C-00000001] netsock2.c: ...host 'ast-dev01.dialogtech.com' and port ''. [2018-03-13 12:35:04.130] DEBUG[2830][C-00000001] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7f9210016788' [2018-03-13 12:35:04.130] VERBOSE[2830][C-00000001] netsock2.c: Using SIP RTP CoS mark 5 [2018-03-13 12:35:04.130] DEBUG[2830][C-00000001] chan_sip.c: Setting NAT on RTP to Off [2018-03-13 12:35:04.130] DEBUG[2830][C-00000001] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED OR FAILED. [2018-03-13 12:35:04.130] DEBUG[2830][C-00000001] chan_sip.c: Processing session-level SDP o=root 2116235543 2116235543 IN IP4 192.168.10.202... OK. [2018-03-13 12:35:04.130] DEBUG[2830][C-00000001] chan_sip.c: Processing session-level SDP s=Asterisk PBX 1.8.13.0... UNSUPPORTED OR FAILED. [2018-03-13 12:35:04.130] DEBUG[2830][C-00000001] netsock2.c: Splitting '192.168.10.202' into... [2018-03-13 12:35:04.131] DEBUG[2830][C-00000001] netsock2.c: ...host '192.168.10.202' and port ''. [2018-03-13 12:35:04.131] DEBUG[2830][C-00000001] chan_sip.c: Processing session-level SDP c=IN IP4 192.168.10.202... OK. [2018-03-13 12:35:04.131] DEBUG[2830][C-00000001] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED. [2018-03-13 12:35:04.131] DEBUG[2830][C-00000001] rtp_engine.c: Setting tx payload type 0 based on m type on 0x7f91e1408200 [2018-03-13 12:35:04.131] DEBUG[2830][C-00000001] rtp_engine.c: Setting tx payload type 101 based on m type on 0x7f91e1408200 [2018-03-13 12:35:04.131] DEBUG[2830][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. [2018-03-13 12:35:04.131] DEBUG[2830][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [2018-03-13 12:35:04.131] DEBUG[2830][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-16... UNSUPPORTED OR FAILED. [2018-03-13 12:35:04.131] DEBUG[2830][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=silenceSupp:off - - - -... UNSUPPORTED OR FAILED. [2018-03-13 12:35:04.131] DEBUG[2830][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=ptime:20... OK. [2018-03-13 12:35:04.131] DEBUG[2830][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK. [2018-03-13 12:35:04.131] DEBUG[2830][C-00000001] acl.c: For destination '192.168.10.202', our source address is '10.1.144.6'. [2018-03-13 12:35:04.131] DEBUG[2830][C-00000001] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7f9210016788' [2018-03-13 12:35:04.131] VERBOSE[2830][C-00000001] res_rtp_asterisk.c: 0x7f921002c950 -- Strict RTP learning after remote address set to: 192.168.10.202:39452 [2018-03-13 12:35:04.131] DEBUG[2830][C-00000001] rtp_engine.c: Copying payload 0 (0x7f92100180f0) from 0x7f91e1408200 to 0x7f9210016950 [2018-03-13 12:35:04.132] DEBUG[2830][C-00000001] rtp_engine.c: Copying payload 101 (0x7f92100315d0) from 0x7f91e1408200 to 0x7f9210016950 [2018-03-13 12:35:04.132] DEBUG[2830][C-00000001] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x7f9210016788' [2018-03-13 12:35:04.132] DEBUG[2830][C-00000001] chan_sip.c: We're settling with these formats: (ulaw) [2018-03-13 12:35:04.132] DEBUG[2830][C-00000001] chan_sip.c: Checking SIP call limits for device [2018-03-13 12:35:04.132] DEBUG[2830][C-00000001] chan_sip.c: Updating call counter for incoming call [2018-03-13 12:35:04.132] DEBUG[2830][C-00000001] netsock2.c: Splitting '10.1.144.6' into... [2018-03-13 12:35:04.132] DEBUG[2830][C-00000001] netsock2.c: ...host '10.1.144.6' and port ''. [2018-03-13 12:35:04.132] DEBUG[2830][C-00000001] netsock2.c: Splitting '192.168.10.202' into... [2018-03-13 12:35:04.132] DEBUG[2830][C-00000001] netsock2.c: ...host '192.168.10.202' and port ''. [2018-03-13 12:35:04.132] DEBUG[2830][C-00000001] chan_sip.c: Incoming INVITE with 'timer' option supported [2018-03-13 12:35:04.133] DEBUG[2830][C-00000001] channel.c: Channel 0x7f9210035728 'SIP/c1nb2-00000002' allocated [2018-03-13 12:35:04.133] DEBUG[2830][C-00000001] chan_sip.c: *** Our native formats are (ulaw) [2018-03-13 12:35:04.133] DEBUG[2830][C-00000001] chan_sip.c: *** Joint capabilities are (ulaw) [2018-03-13 12:35:04.133] DEBUG[2830][C-00000001] chan_sip.c: *** Our capabilities are (ulaw) [2018-03-13 12:35:04.133] DEBUG[2830][C-00000001] chan_sip.c: *** AST_CODEC_CHOOSE formats are ulaw [2018-03-13 12:35:04.134] DEBUG[2830][C-00000001] chan_sip.c: This channel will not be able to handle video. [2018-03-13 12:35:04.134] DEBUG[2830][C-00000001] chan_sip.c: Trying to put 'SIP/2.0 100' onto UDP socket destined for 192.168.10.202:5060 [2018-03-13 12:35:04.135] DEBUG[2830][C-00000001] chan_sip.c: Invite/Replaces: preparing to replace SIP/voxprox-dev01-00000000 with SIP/c1nb2-00000002 [2018-03-13 12:35:04.135] DEBUG[2830][C-00000001] chan_sip.c: SIP answering channel: SIP/c1nb2-00000002 [2018-03-13 12:35:04.135] DEBUG[2830][C-00000001] res_rtp_asterisk.c: Setting the marker bit due to a source update [2018-03-13 12:35:04.135] DEBUG[2830][C-00000001] chan_sip.c: ** Our capability: (ulaw) Video flag: True Text flag: True [2018-03-13 12:35:04.135] DEBUG[2830][C-00000001] chan_sip.c: ** Our prefcodec: (nothing) [2018-03-13 12:35:04.136] DEBUG[2830][C-00000001] chan_sip.c: -- Done with adding codecs to SDP [2018-03-13 12:35:04.136] DEBUG[2830][C-00000001] chan_sip.c: Setting framing on incoming call: 20 [2018-03-13 12:35:04.136] DEBUG[2830][C-00000001] chan_sip.c: Done building SDP. Settling with this capability: (ulaw) [2018-03-13 12:35:04.136] DEBUG[2830][C-00000001] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 192.168.10.202:5060 [2018-03-13 12:35:04.138] DEBUG[2808] devicestate.c: No provider found, checking channel drivers for SIP - c1nb2 [2018-03-13 12:35:04.138] DEBUG[2808] chan_sip.c: Checking device state for peer c1nb2 [2018-03-13 12:35:04.138] DEBUG[2808] devicestate.c: Changing state for SIP/c1nb2 - state 1 (Not in use) [2018-03-13 12:35:04.138] DEBUG[2808] devicestate.c: No provider found, checking channel drivers for SIP - c1nb2 [2018-03-13 12:35:04.138] DEBUG[2808] chan_sip.c: Checking device state for peer c1nb2 [2018-03-13 12:35:04.138] DEBUG[2808] devicestate.c: Changing state for SIP/c1nb2 - state 1 (Not in use) [2018-03-13 12:35:04.139] DEBUG[2875][C-00000001] bridge_channel.c: Bridge f621f610-ee87-442e-bfdf-022922edda0d: 0x7f92100482f8(SIP/c1nb2-00000002) is joining [2018-03-13 12:35:04.140] DEBUG[2875][C-00000001] bridge_channel.c: Bridge f621f610-ee87-442e-bfdf-022922edda0d: pushing 0x7f92100482f8(SIP/c1nb2-00000002) by swapping with 0x7f920c01c138(SIP/voxprox-dev01-00000000) [2018-03-13 12:35:04.140] DEBUG[2875][C-00000001] bridge_channel.c: Setting channel SIP/c1nb2-00000002 peeraccount with channel SIP/10.1.144.4-00000001 accountcode 'c1nb2-095889235626776'. [2018-03-13 12:35:04.140] DEBUG[2875][C-00000001] bridge_channel.c: Setting channel SIP/c1nb2-00000002 accountcode with channel SIP/10.1.144.4-00000001 peeraccount 'c1nb2-095889235626776'. [2018-03-13 12:35:04.141] DEBUG[2875][C-00000001] bridge_channel.c: Setting 0x7f920c01c138(SIP/voxprox-dev01-00000000) state from:0 to:2 [2018-03-13 12:35:04.141] DEBUG[2875][C-00000001] bridge_channel.c: Bridge f621f610-ee87-442e-bfdf-022922edda0d: pulling 0x7f920c01c138(SIP/voxprox-dev01-00000000) [2018-03-13 12:35:04.141] VERBOSE[2875][C-00000001] bridge_channel.c: Channel SIP/voxprox-dev01-00000000 left 'native_rtp' basic-bridge [2018-03-13 12:35:04.141] DEBUG[2875][C-00000001] bridge_channel.c: Bridge f621f610-ee87-442e-bfdf-022922edda0d: 0x7f920c01c138(SIP/voxprox-dev01-00000000) is leaving native_rtp technology [2018-03-13 12:35:04.141] DEBUG[2875][C-00000001] bridge_native_rtp.c: Bridge 'f621f610-ee87-442e-bfdf-022922edda0d'. Channel 'SIP/voxprox-dev01-00000000' is leaving bridge tech [2018-03-13 12:35:04.141] DEBUG[2875][C-00000001] bridge_native_rtp.c: Bridge 'f621f610-ee87-442e-bfdf-022922edda0d'. Detaching hook data 0x7f920c00e080 from 'SIP/voxprox-dev01-00000000' [2018-03-13 12:35:04.142] DEBUG[2875][C-00000001] bridge_native_rtp.c: Bridge 'f621f610-ee87-442e-bfdf-022922edda0d'. Tech stopping 'SIP/voxprox-dev01-00000000' and 'SIP/10.1.144.4-00000001' with target 'none' [2018-03-13 12:35:04.142] DEBUG[2875][C-00000001] bridge_native_rtp.c: Discontinued RTP bridging of 'SIP/voxprox-dev01-00000000' and 'SIP/10.1.144.4-00000001' - media will flow through Asterisk core [2018-03-13 12:35:04.142] DEBUG[2875][C-00000001] bridge_native_rtp.c: Destroying channel tech_pvt data 0x7f920c03ce10 [2018-03-13 12:35:04.142] VERBOSE[2875][C-00000001] bridge_channel.c: Channel SIP/c1nb2-00000002 swapped with SIP/voxprox-dev01-00000000 into 'native_rtp' basic-bridge [2018-03-13 12:35:04.142] DEBUG[2875][C-00000001] bridge.c: Bridge technology softmix does not have any capabilities we want. [2018-03-13 12:35:04.142] DEBUG[2875][C-00000001] bridge_native_rtp.c: Bridge 'f621f610-ee87-442e-bfdf-022922edda0d'. Checking compatability for channels 'SIP/10.1.144.4-00000001' and 'SIP/c1nb2-00000002' [2018-03-13 12:35:04.143] DEBUG[2875][C-00000001] bridge.c: Bridge technology simple_bridge has less preference than native_rtp (50 <= 90). Skipping. [2018-03-13 12:35:04.143] DEBUG[2875][C-00000001] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [2018-03-13 12:35:04.143] DEBUG[2875][C-00000001] bridge.c: Chose bridge technology native_rtp [2018-03-13 12:35:04.143] DEBUG[2875][C-00000001] bridge.c: Bridge f621f610-ee87-442e-bfdf-022922edda0d is already using the new technology. [2018-03-13 12:35:04.143] DEBUG[2875][C-00000001] bridge.c: Bridge f621f610-ee87-442e-bfdf-022922edda0d: 0x7f92100482f8(SIP/c1nb2-00000002) is joining native_rtp technology [2018-03-13 12:35:04.143] DEBUG[2875][C-00000001] bridge_native_rtp.c: Bridge 'f621f610-ee87-442e-bfdf-022922edda0d'. Channel 'SIP/c1nb2-00000002' is joining bridge tech [2018-03-13 12:35:04.143] DEBUG[2875][C-00000001] bridge_native_rtp.c: Bridge 'f621f610-ee87-442e-bfdf-022922edda0d'. Attaching hook data 0x7f920c0414b0 to 'SIP/c1nb2-00000002' [2018-03-13 12:35:04.143] DEBUG[2875][C-00000001] bridge_native_rtp.c: Bridge 'f621f610-ee87-442e-bfdf-022922edda0d'. Tech starting 'SIP/10.1.144.4-00000001' and 'SIP/c1nb2-00000002' with target 'none' [2018-03-13 12:35:04.143] VERBOSE[2875][C-00000001] bridge_native_rtp.c: Locally RTP bridged 'SIP/10.1.144.4-00000001' and 'SIP/c1nb2-00000002' in stack [2018-03-13 12:35:04.144] DEBUG[2875][C-00000001] res_rtp_asterisk.c: Not changing SSRC since we haven't sent any RTP yet [2018-03-13 12:35:04.144] DEBUG[2875][C-00000001] bridge.c: Bridge technology softmix does not have any capabilities we want. [2018-03-13 12:35:04.145] DEBUG[2875][C-00000001] bridge_native_rtp.c: Bridge 'f621f610-ee87-442e-bfdf-022922edda0d'. Checking compatability for channels 'SIP/10.1.144.4-00000001' and 'SIP/c1nb2-00000002' [2018-03-13 12:35:04.145] DEBUG[2875][C-00000001] bridge.c: Bridge technology simple_bridge has less preference than native_rtp (50 <= 90). Skipping. [2018-03-13 12:35:04.145] DEBUG[2875][C-00000001] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [2018-03-13 12:35:04.145] DEBUG[2875][C-00000001] bridge.c: Chose bridge technology native_rtp [2018-03-13 12:35:04.145] DEBUG[2875][C-00000001] bridge.c: Bridge f621f610-ee87-442e-bfdf-022922edda0d is already using the new technology. [2018-03-13 12:35:04.147] VERBOSE[2875][C-00000001] res_rtp_asterisk.c: 0x7f921002c950 -- Strict RTP switching to RTP target address 192.168.10.202:39452 as source [2018-03-13 12:35:04.149] DEBUG[2797] threadpool.c: Increasing threadpool stasis-core's size by 1 [2018-03-13 12:35:04.150] DEBUG[2869][C-00000000] bridge.c: Bridge technology softmix does not have any capabilities we want. [2018-03-13 12:35:04.150] DEBUG[2869][C-00000000] bridge_native_rtp.c: Bridge 'f621f610-ee87-442e-bfdf-022922edda0d'. Checking compatability for channels 'SIP/10.1.144.4-00000001' and 'SIP/c1nb2-00000002' [2018-03-13 12:35:04.150] DEBUG[2869][C-00000000] bridge.c: Bridge technology simple_bridge has less preference than native_rtp (50 <= 90). Skipping. [2018-03-13 12:35:04.150] DEBUG[2869][C-00000000] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [2018-03-13 12:35:04.150] DEBUG[2869][C-00000000] bridge.c: Chose bridge technology native_rtp [2018-03-13 12:35:04.150] DEBUG[2869][C-00000000] bridge.c: Bridge f621f610-ee87-442e-bfdf-022922edda0d is already using the new technology. [2018-03-13 12:35:04.152] DEBUG[2869][C-00000000] res_rtp_asterisk.c: Not changing SSRC since we haven't sent any RTP yet [2018-03-13 12:35:04.153] DEBUG[2869][C-00000000] app_dial.c: Exiting with DIALSTATUS=ANSWER. [2018-03-13 12:35:04.153] DEBUG[2869][C-00000000] pbx.c: Spawn extension (default,17732507208,19) exited non-zero on 'SIP/voxprox-dev01-00000000' [2018-03-13 12:35:04.153] VERBOSE[2869][C-00000000] pbx.c: Spawn extension (default, 17732507208, 19) exited non-zero on 'SIP/voxprox-dev01-00000000' [2018-03-13 12:35:04.153] DEBUG[2869][C-00000000] channel.c: Soft-Hanging (0x10) up channel 'SIP/voxprox-dev01-00000000' [2018-03-13 12:35:04.154] DEBUG[2869][C-00000000] channel.c: Soft-Hanging (0x80) up channel 'SIP/voxprox-dev01-00000000' [2018-03-13 12:35:04.154] DEBUG[2869][C-00000000] pbx_variables.c: Function SIP_HEADER(x-clickto) result is '(null)' [2018-03-13 12:35:04.154] DEBUG[2869][C-00000000] pbx_variables.c: Expression result is '0' [2018-03-13 12:35:04.154] DEBUG[2869][C-00000000] pbx.c: Launching 'GotoIf' [2018-03-13 12:35:04.154] VERBOSE[2869][C-00000000] pbx.c: Executing [h@default:1] GotoIf("SIP/voxprox-dev01-00000000", "0?nopca") in new stack [2018-03-13 12:35:04.154] DEBUG[2869][C-00000000] pbx_builtins.c: Not taking any branch [2018-03-13 12:35:04.154] DEBUG[2869][C-00000000] pbx.c: Launching 'DumpChan' [2018-03-13 12:35:04.154] VERBOSE[2869][C-00000000] pbx.c: Executing [h@default:2] DumpChan("SIP/voxprox-dev01-00000000", "") in new stack [2018-03-13 12:35:04.155] VERBOSE[2869][C-00000000] app_dumpchan.c: Dumping Info For Channel: SIP/voxprox-dev01-00000000: ================================================================================ Info: Name= SIP/voxprox-dev01-00000000 Type= SIP UniqueID= ast-dev01.dialogtech.com-1520958900.0 LinkedID= ast-dev01.dialogtech.com-1520958900.0 CallerIDNum= 13129990302 CallerIDName= 13129990302 ConnectedLineIDNum= (N/A) ConnectedLineIDName=(N/A) DNIDDigits= 17732507208 RDNIS= (N/A) Parkinglot= default Language= en State= Up (6) Rings= 0 NativeFormat= (ulaw) WriteFormat= ulaw ReadFormat= ulaw RawWriteFormat= ulaw RawReadFormat= ulaw WriteTranscode= No ReadTranscode= No 1stFileDescriptor= 17 Framesin= 32 Framesout= 0 TimetoHangup= 0 ElapsedTime= 0h0m3s BridgeID= (Not bridged) Context= default Extension= h Priority= 2 CallGroup= PickupGroup= Application= DumpChan Data= (Empty) Blocking_in= (Not Blocking) Variables: DIALSTATUS=ANSWER DIALEDTIME=3 ANSWEREDTIME=0 DIALEDPEERNUMBER=10.1.144.4/17732507208 DIALEDPEERNAME=SIP/10.1.144.4-00000001 dialtime=1520958900.348 parent_channel=SIP/voxprox-dev01-00000000 AGISTATUS=SUCCESS proxy_ip=10.1.144.4 x-dial_timeout=120 MACRO_DEPTH=0 SIPADDHEADER04=x-carrier-id: 666 SIPADDHEADER03=X-IBP-Unique-ID: 6LqvrJwpKonqyLMHDIKGyIEEGsEzILqKGGxsHwnF SIPADDHEADER02=X-IBP-NoRecord: -ccap x-ibp-norecord=-ccap SIPADDHEADER01=x-asterisk-outbound: yes x-carrier-id=666 ext= accountcode=c1nb2-095889235626776 X-IBP-Unique-ID=6LqvrJwpKonqyLMHDIKGyIEEGsEzILqKGGxsHwnF x-limit_playaudio_caller=no warning-audio=this-call-may-be-monitored-or-recorded refercall= inboundmergehack=1 newdnis=17732507208 SIPCALLID=1520958900229-7f0c0893e430-0820b490-000006c5@10.1.144.14 SIPDOMAIN=10.1.144.6 SIPURI=sip:13129990302@10.1.144.14:5060 ================================================================================ [2018-03-13 12:35:04.155] DEBUG[2869][C-00000000] pbx_variables.c: Result of 'refercall' is '' [2018-03-13 12:35:04.155] DEBUG[2869][C-00000000] pbx_variables.c: Expression result is '0' [2018-03-13 12:35:04.155] DEBUG[2869][C-00000000] pbx.c: Launching 'GotoIf' [2018-03-13 12:35:04.155] VERBOSE[2869][C-00000000] pbx.c: Executing [h@default:3] GotoIf("SIP/voxprox-dev01-00000000", "0?nopca") in new stack [2018-03-13 12:35:04.155] DEBUG[2869][C-00000000] pbx_builtins.c: Not taking any branch [2018-03-13 12:35:04.155] DEBUG[2869][C-00000000] pbx_variables.c: Result of 'outboundmergehack' is NULL [2018-03-13 12:35:04.155] DEBUG[2869][C-00000000] pbx_variables.c: Function SIP_HEADER(x-merged) result is '(null)' [2018-03-13 12:35:04.156] DEBUG[2869][C-00000000] pbx_variables.c: Expression result is '0' [2018-03-13 12:35:04.156] DEBUG[2869][C-00000000] pbx.c: Launching 'GotoIf' [2018-03-13 12:35:04.156] VERBOSE[2869][C-00000000] pbx.c: Executing [h@default:4] GotoIf("SIP/voxprox-dev01-00000000", "0?nopca") in new stack [2018-03-13 12:35:04.156] DEBUG[2869][C-00000000] pbx_builtins.c: Not taking any branch [2018-03-13 12:35:04.156] DEBUG[2869][C-00000000] pbx_variables.c: Result of 'tfp_start' is NULL [2018-03-13 12:35:04.156] DEBUG[2869][C-00000000] pbx_variables.c: Expression result is '0' [2018-03-13 12:35:04.156] DEBUG[2869][C-00000000] pbx.c: Launching 'ExecIf' [2018-03-13 12:35:04.156] VERBOSE[2869][C-00000000] pbx.c: Executing [h@default:5] ExecIf("SIP/voxprox-dev01-00000000", "0?Macro(tollfree_pumping_report)") in new stack [2018-03-13 12:35:04.156] DEBUG[2869][C-00000000] pbx_variables.c: Result of 'CONTROLLER' is 'ctrl-dev.ifbyphone.com' [2018-03-13 12:35:04.157] DEBUG[2869][C-00000000] pbx_variables.c: Result of 'accountcode' is 'c1nb2-095889235626776' [2018-03-13 12:35:04.157] DEBUG[2869][C-00000000] pbx_variables.c: Result of 'DIALSTATUS' is 'ANSWER' [2018-03-13 12:35:04.157] DEBUG[2869][C-00000000] pbx_variables.c: Function SHARED(elapsed_ringing_time) result is '3.19499999994877726' [2018-03-13 12:35:04.157] DEBUG[2869][C-00000000] pbx_variables.c: Result of 'firstleg' is NULL [2018-03-13 12:35:04.157] DEBUG[2869][C-00000000] pbx_variables.c: Result of 'DIALEDTIME' is '3' [2018-03-13 12:35:04.157] DEBUG[2869][C-00000000] pbx_variables.c: Result of 'ANSWEREDTIME' is '0' [2018-03-13 12:35:04.157] DEBUG[2869][C-00000000] pbx_variables.c: Result of 'x-ani-ii' is NULL [2018-03-13 12:35:04.157] DEBUG[2869][C-00000000] pbx_variables.c: Result of 'tfp_results' is NULL [2018-03-13 12:35:04.157] DEBUG[2869][C-00000000] pbx_variables.c: Result of 'call_type' is NULL [2018-03-13 12:35:04.157] DEBUG[2869][C-00000000] pbx.c: Launching 'System' [2018-03-13 12:35:04.157] VERBOSE[2869][C-00000000] pbx.c: Executing [h@default:6] System("SIP/voxprox-dev01-00000000", "/opt/asterisk/var/lib/asterisk/agi-bin/system_scripts/apiwrapper "http://ctrl-dev.ifbyphone.com/asterisk_api.php?action=outcallstatus&accountcode=c1nb2-095889235626776&status=ANSWER&elapsed_ringing_time=3.19499999994877726&firstleg=&duration=3&ANSWEREDTIME=0&x-ani-ii=&capstream_mode=HCCAP&call_type=&trace"") in new stack [2018-03-13 12:35:04.160] DEBUG[2830] chan_sip.c: Session timer started: 30 - 4f24d37f4243ed5f27fab5781883094e@192.168.10.202:5060 900000ms [2018-03-13 12:35:04.160] DEBUG[2830] chan_sip.c: = Looking for Call ID: 4f24d37f4243ed5f27fab5781883094e@192.168.10.202:5060 (Checking From) --From tag as3ec95e11 --To-tag as5ecc5a7a [2018-03-13 12:35:04.160] DEBUG[2830][C-00000001] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [2018-03-13 12:35:04.160] DEBUG[2830][C-00000001] chan_sip.c: Stopping retransmission on '4f24d37f4243ed5f27fab5781883094e@192.168.10.202:5060' of Response 102: Match Found [2018-03-13 12:35:04.176] DEBUG[2869][C-00000000] pbx_variables.c: Result of 'accountcode' is 'c1nb2-095889235626776' [2018-03-13 12:35:04.176] DEBUG[2869][C-00000000] pbx_variables.c: Result of 'SIPCALLID' is '1520958900229-7f0c0893e430-0820b490-000006c5@10.1.144.14' [2018-03-13 12:35:04.176] DEBUG[2869][C-00000000] pbx_variables.c: Result of 'x-ani-ii' is NULL [2018-03-13 12:35:04.176] DEBUG[2869][C-00000000] pbx_variables.c: Function CALLERID(ani) result is '13129990302' [2018-03-13 12:35:04.176] DEBUG[2869][C-00000000] pbx_variables.c: Function CALLERID(dnid) result is '17732507208' [2018-03-13 12:35:04.176] DEBUG[2869][C-00000000] pbx_variables.c: Function SHARED(elapsed_ringing_time) result is '3.19499999994877726' [2018-03-13 12:35:04.176] DEBUG[2869][C-00000000] pbx_variables.c: Result of 'DIALSTATUS' is 'ANSWER' [2018-03-13 12:35:04.176] DEBUG[2869][C-00000000] pbx_variables.c: Result of 'DIALEDTIME' is '3' [2018-03-13 12:35:04.176] DEBUG[2869][C-00000000] pbx_variables.c: Result of 'ANSWEREDTIME' is '0' [2018-03-13 12:35:04.176] DEBUG[2869][C-00000000] pbx.c: Launching 'NoOp' [2018-03-13 12:35:04.176] VERBOSE[2869][C-00000000] pbx.c: Executing [h@default:7] NoOp("SIP/voxprox-dev01-00000000", "ACCOUNTCODE:c1nb2-095889235626776,Call-ID:1520958900229-7f0c0893e430-0820b490-000006c5@10.1.144.14,x-ani-ii:,ANI:13129990302,DNID:17732507208,SHARED(elapsed_ringing_time):3.19499999994877726,DIALSTATUS:ANSWER,DIALEDTIME:3,ANSWEREDTIME:0") in new stack [2018-03-13 12:35:04.177] DEBUG[2869][C-00000000] channel.c: Channel 0x7f9210020088 'SIP/voxprox-dev01-00000000' hanging up. Refs: 2 [2018-03-13 12:35:04.177] DEBUG[2869][C-00000000] chan_sip.c: Hangup call SIP/voxprox-dev01-00000000, SIP callid 1520958900229-7f0c0893e430-0820b490-000006c5@10.1.144.14 [2018-03-13 12:35:04.178] DEBUG[2869][C-00000000] netsock2.c: Splitting '10.1.174.33' into... [2018-03-13 12:35:04.178] DEBUG[2869][C-00000000] netsock2.c: ...host '10.1.174.33' and port ''. [2018-03-13 12:35:04.178] DEBUG[2869][C-00000000] chan_sip.c: Trying to put 'BYE sip:131' onto UDP socket destined for 10.1.174.33:5060 [2018-03-13 12:35:04.178] DEBUG[2869][C-00000000] channel.c: Channel 0x7f9210020088 'SIP/voxprox-dev01-00000000' destroying [2018-03-13 12:35:04.181] DEBUG[2830] chan_sip.c: = Looking for Call ID: 1520958900229-7f0c0893e430-0820b490-000006c5@10.1.144.14 (Checking To) --From tag as1f37e8d1 --To-tag 1c78725c-422bf87e-3361a7-8052ab8-0-13c4-7217 [2018-03-13 12:35:04.181] DEBUG[2830][C-00000000] chan_sip.c: Stopping retransmission on '1520958900229-7f0c0893e430-0820b490-000006c5@10.1.144.14' of Request 102: Match Found [2018-03-13 12:35:04.181] DEBUG[2830] chan_sip.c: Destroying SIP dialog 1520958900229-7f0c0893e430-0820b490-000006c5@10.1.144.14 [2018-03-13 12:35:04.181] DEBUG[2830] rtp_engine.c: Destroyed RTP instance '0x7f92100110d8' [2018-03-13 12:35:04.181] DEBUG[2808] devicestate.c: No provider found, checking channel drivers for SIP - voxprox-dev01 [2018-03-13 12:35:04.181] DEBUG[2808] chan_sip.c: Checking device state for peer voxprox-dev01 [2018-03-13 12:35:04.181] DEBUG[2808] devicestate.c: Changing state for SIP/voxprox-dev01 - state 1 (Not in use) [2018-03-13 12:35:24.171] DEBUG[2876] threadpool.c: Worker thread idle timeout reached. Dying. [2018-03-13 12:35:24.172] DEBUG[2797] threadpool.c: Destroying worker thread 10 [2018-03-13 12:35:24.183] DEBUG[2870] threadpool.c: Worker thread idle timeout reached. Dying. [2018-03-13 12:35:24.183] DEBUG[2797] threadpool.c: Destroying worker thread 9 [2018-03-13 12:35:25.021] DEBUG[2830] chan_sip.c: Allocating new SIP dialog for 5f25dfd6450dc945403ee27456f329e6@10.1.144.6:5060 - OPTIONS (No RTP) [2018-03-13 12:35:25.021] DEBUG[2830] acl.c: For destination '192.168.11.39', our source address is '10.1.144.6'. [2018-03-13 12:35:25.021] DEBUG[2830] chan_sip.c: Setting AST_TRANSPORT_UDP with address 10.1.144.6:5060 [2018-03-13 12:35:25.021] DEBUG[2830] chan_sip.c: SIP call-id changed from '5f25dfd6450dc945403ee27456f329e6@10.1.144.6:5060' to '3a514dd959d9374f521c15c54c9a0be9@10.1.144.6:5060' [2018-03-13 12:35:25.021] DEBUG[2830] chan_sip.c: Initializing initreq for method OPTIONS - callid 3a514dd959d9374f521c15c54c9a0be9@10.1.144.6:5060 [2018-03-13 12:35:25.022] DEBUG[2830] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 192.168.11.39:5060 [2018-03-13 12:35:25.022] DEBUG[2830] chan_sip.c: = Looking for Call ID: 3a514dd959d9374f521c15c54c9a0be9@10.1.144.6:5060 (Checking To) --From tag as3844b12f --To-tag b27e1a1d33761e85846fc98f5f3a7e58.62fe [2018-03-13 12:35:25.022] DEBUG[2830] chan_sip.c: Stopping retransmission on '3a514dd959d9374f521c15c54c9a0be9@10.1.144.6:5060' of Request 102: Match Found [2018-03-13 12:35:25.022] DEBUG[2830] chan_sip.c: Destroying SIP dialog 3a514dd959d9374f521c15c54c9a0be9@10.1.144.6:5060 [2018-03-13 12:35:25.534] DEBUG[2830] chan_sip.c: Allocating new SIP dialog for 77c656df659f0ec615fd84a7391b7228@10.1.144.6:5060 - OPTIONS (No RTP) [2018-03-13 12:35:25.534] DEBUG[2830] acl.c: For destination '10.1.174.42', our source address is '10.1.144.6'. [2018-03-13 12:35:25.534] DEBUG[2830] chan_sip.c: Setting AST_TRANSPORT_UDP with address 10.1.144.6:5060 [2018-03-13 12:35:25.534] DEBUG[2830] chan_sip.c: SIP call-id changed from '77c656df659f0ec615fd84a7391b7228@10.1.144.6:5060' to '612dbeb008e7925023307b571e6c0383@10.1.144.6:5060' [2018-03-13 12:35:25.535] DEBUG[2830] chan_sip.c: Initializing initreq for method OPTIONS - callid 612dbeb008e7925023307b571e6c0383@10.1.144.6:5060 [2018-03-13 12:35:25.535] DEBUG[2830] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 10.1.174.42:5060 [2018-03-13 12:35:25.535] DEBUG[2830] chan_sip.c: = Looking for Call ID: 612dbeb008e7925023307b571e6c0383@10.1.144.6:5060 (Checking To) --From tag as45547d88 --To-tag as6285434a [2018-03-13 12:35:25.535] DEBUG[2830] chan_sip.c: Stopping retransmission on '612dbeb008e7925023307b571e6c0383@10.1.144.6:5060' of Request 102: Match Found [2018-03-13 12:35:25.535] DEBUG[2830] chan_sip.c: Destroying SIP dialog 612dbeb008e7925023307b571e6c0383@10.1.144.6:5060 [2018-03-13 12:35:26.041] DEBUG[2830] chan_sip.c: Allocating new SIP dialog for 339fa8120b3355f4063ba79f4f0faa08@10.1.144.6:5060 - OPTIONS (No RTP) [2018-03-13 12:35:26.041] DEBUG[2830] acl.c: For destination '192.168.11.38', our source address is '10.1.144.6'. [2018-03-13 12:35:26.041] DEBUG[2830] chan_sip.c: Setting AST_TRANSPORT_UDP with address 10.1.144.6:5060 [2018-03-13 12:35:26.042] DEBUG[2830] chan_sip.c: SIP call-id changed from '339fa8120b3355f4063ba79f4f0faa08@10.1.144.6:5060' to '6a38d91d05410d952bfd06c9687f707e@10.1.144.6:5060' [2018-03-13 12:35:26.042] DEBUG[2830] chan_sip.c: Initializing initreq for method OPTIONS - callid 6a38d91d05410d952bfd06c9687f707e@10.1.144.6:5060 [2018-03-13 12:35:26.042] DEBUG[2830] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 192.168.11.38:5060 [2018-03-13 12:35:26.042] DEBUG[2830] chan_sip.c: = Looking for Call ID: 6a38d91d05410d952bfd06c9687f707e@10.1.144.6:5060 (Checking To) --From tag as3d0c8d5f --To-tag b27e1a1d33761e85846fc98f5f3a7e58.838f [2018-03-13 12:35:26.042] DEBUG[2830] chan_sip.c: Stopping retransmission on '6a38d91d05410d952bfd06c9687f707e@10.1.144.6:5060' of Request 102: Match Found [2018-03-13 12:35:26.043] DEBUG[2830] chan_sip.c: Destroying SIP dialog 6a38d91d05410d952bfd06c9687f707e@10.1.144.6:5060 [2018-03-13 12:35:26.536] DEBUG[2830] chan_sip.c: Allocating new SIP dialog for 67e92f35248e31432dbf03647aec8af3@10.1.144.6:5060 - OPTIONS (No RTP) [2018-03-13 12:35:26.537] DEBUG[2830] acl.c: For destination '192.168.11.229', our source address is '10.1.144.6'. [2018-03-13 12:35:26.537] DEBUG[2830] chan_sip.c: Setting AST_TRANSPORT_UDP with address 10.1.144.6:5060 [2018-03-13 12:35:26.537] DEBUG[2830] chan_sip.c: SIP call-id changed from '67e92f35248e31432dbf03647aec8af3@10.1.144.6:5060' to '6d6031c345608b2b18f153a50c9c4d00@10.1.144.6:5060' [2018-03-13 12:35:26.537] DEBUG[2830] chan_sip.c: Initializing initreq for method OPTIONS - callid 6d6031c345608b2b18f153a50c9c4d00@10.1.144.6:5060 [2018-03-13 12:35:26.537] DEBUG[2830] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 192.168.11.229:5060 [2018-03-13 12:35:26.537] DEBUG[2830] chan_sip.c: = Looking for Call ID: 6d6031c345608b2b18f153a50c9c4d00@10.1.144.6:5060 (Checking To) --From tag as5821386e --To-tag as542795c1 [2018-03-13 12:35:26.538] DEBUG[2830] chan_sip.c: Stopping retransmission on '6d6031c345608b2b18f153a50c9c4d00@10.1.144.6:5060' of Request 102: Match Found [2018-03-13 12:35:26.538] DEBUG[2830] chan_sip.c: Destroying SIP dialog 6d6031c345608b2b18f153a50c9c4d00@10.1.144.6:5060 [2018-03-13 12:35:27.035] DEBUG[2830] chan_sip.c: Allocating new SIP dialog for 32f81c2a5712cf741e3ba0120381116c@10.1.144.6:5060 - OPTIONS (No RTP) [2018-03-13 12:35:27.035] DEBUG[2830] acl.c: For destination '192.168.11.188', our source address is '10.1.144.6'. [2018-03-13 12:35:27.035] DEBUG[2830] chan_sip.c: Setting AST_TRANSPORT_UDP with address 10.1.144.6:5060 [2018-03-13 12:35:27.035] DEBUG[2830] chan_sip.c: SIP call-id changed from '32f81c2a5712cf741e3ba0120381116c@10.1.144.6:5060' to '734f08cb652498402493657f6ac78d2c@10.1.144.6:5060' [2018-03-13 12:35:27.035] DEBUG[2830] chan_sip.c: Initializing initreq for method OPTIONS - callid 734f08cb652498402493657f6ac78d2c@10.1.144.6:5060 [2018-03-13 12:35:27.035] DEBUG[2830] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 192.168.11.188:5060 [2018-03-13 12:35:27.036] DEBUG[2830] chan_sip.c: = Looking for Call ID: 734f08cb652498402493657f6ac78d2c@10.1.144.6:5060 (Checking To) --From tag as77d3cf94 --To-tag as2859258c [2018-03-13 12:35:27.036] DEBUG[2830] chan_sip.c: Stopping retransmission on '734f08cb652498402493657f6ac78d2c@10.1.144.6:5060' of Request 102: Match Found [2018-03-13 12:35:27.036] DEBUG[2830] chan_sip.c: Destroying SIP dialog 734f08cb652498402493657f6ac78d2c@10.1.144.6:5060 [2018-03-13 12:35:27.522] DEBUG[2830] chan_sip.c: Allocating new SIP dialog for 185c16bf5ea115214fdde1417d8a35fe@10.1.144.6:5060 - OPTIONS (No RTP) [2018-03-13 12:35:27.522] DEBUG[2830] acl.c: For destination '192.168.10.201', our source address is '10.1.144.6'. [2018-03-13 12:35:27.522] DEBUG[2830] chan_sip.c: Setting AST_TRANSPORT_UDP with address 10.1.144.6:5060 [2018-03-13 12:35:27.522] DEBUG[2830] chan_sip.c: SIP call-id changed from '185c16bf5ea115214fdde1417d8a35fe@10.1.144.6:5060' to '2d96d63a055c5af65aa681be74f72148@10.1.144.6:5060' [2018-03-13 12:35:27.522] DEBUG[2830] chan_sip.c: Initializing initreq for method OPTIONS - callid 2d96d63a055c5af65aa681be74f72148@10.1.144.6:5060 [2018-03-13 12:35:27.522] DEBUG[2830] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 192.168.10.201:5060 [2018-03-13 12:35:27.523] DEBUG[2830] chan_sip.c: = Looking for Call ID: 2d96d63a055c5af65aa681be74f72148@10.1.144.6:5060 (Checking To) --From tag as76686311 --To-tag as17a7d6bf [2018-03-13 12:35:27.523] DEBUG[2830] chan_sip.c: Stopping retransmission on '2d96d63a055c5af65aa681be74f72148@10.1.144.6:5060' of Request 102: Match Found [2018-03-13 12:35:27.523] DEBUG[2830] chan_sip.c: Destroying SIP dialog 2d96d63a055c5af65aa681be74f72148@10.1.144.6:5060 [2018-03-13 12:35:33.385] DEBUG[2830] chan_sip.c: = Looking for Call ID: 4f24d37f4243ed5f27fab5781883094e@192.168.10.202:5060 (Checking From) --From tag as3ec95e11 --To-tag as5ecc5a7a [2018-03-13 12:35:33.385] DEBUG[2830][C-00000001] chan_sip.c: **** Received BYE (8) - Command in SIP BYE [2018-03-13 12:35:33.385] DEBUG[2830][C-00000001] netsock2.c: Splitting '192.168.10.202:5060' into... [2018-03-13 12:35:33.385] DEBUG[2830][C-00000001] netsock2.c: ...host '192.168.10.202' and port '5060'. [2018-03-13 12:35:33.385] DEBUG[2830][C-00000001] chan_sip.c: Setting SIP_ALREADYGONE on dialog 4f24d37f4243ed5f27fab5781883094e@192.168.10.202:5060 [2018-03-13 12:35:33.389] DEBUG[2830][C-00000001] chan_sip.c: Received bye, issuing owner hangup [2018-03-13 12:35:33.389] DEBUG[2830][C-00000001] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 192.168.10.202:5060 [2018-03-13 12:35:33.389] DEBUG[2830] chan_sip.c: Session timer stopped: 30 - 4f24d37f4243ed5f27fab5781883094e@192.168.10.202:5060 [2018-03-13 12:35:33.391] DEBUG[2797] threadpool.c: Increasing threadpool stasis-core's size by 1 [2018-03-13 12:35:33.391] DEBUG[2875][C-00000001] bridge_channel.c: Setting 0x7f92100482f8(SIP/c1nb2-00000002) state from:0 to:1 [2018-03-13 12:35:33.391] DEBUG[2875][C-00000001] bridge_channel.c: Bridge f621f610-ee87-442e-bfdf-022922edda0d: pulling 0x7f92100482f8(SIP/c1nb2-00000002) [2018-03-13 12:35:33.391] VERBOSE[2875][C-00000001] bridge_channel.c: Channel SIP/c1nb2-00000002 left 'native_rtp' basic-bridge [2018-03-13 12:35:33.392] DEBUG[2875][C-00000001] bridge_channel.c: Bridge f621f610-ee87-442e-bfdf-022922edda0d: 0x7f92100482f8(SIP/c1nb2-00000002) is leaving native_rtp technology [2018-03-13 12:35:33.392] DEBUG[2875][C-00000001] bridge_native_rtp.c: Bridge 'f621f610-ee87-442e-bfdf-022922edda0d'. Channel 'SIP/c1nb2-00000002' is leaving bridge tech [2018-03-13 12:35:33.392] DEBUG[2875][C-00000001] bridge_native_rtp.c: Bridge 'f621f610-ee87-442e-bfdf-022922edda0d'. Detaching hook data 0x7f920c041520 from 'SIP/c1nb2-00000002' [2018-03-13 12:35:33.392] DEBUG[2875][C-00000001] bridge_native_rtp.c: Bridge 'f621f610-ee87-442e-bfdf-022922edda0d'. Tech stopping 'SIP/10.1.144.4-00000001' and 'SIP/c1nb2-00000002' with target 'none' [2018-03-13 12:35:33.392] DEBUG[2875][C-00000001] bridge_native_rtp.c: Discontinued RTP bridging of 'SIP/10.1.144.4-00000001' and 'SIP/c1nb2-00000002' - media will flow through Asterisk core [2018-03-13 12:35:33.392] DEBUG[2875][C-00000001] bridge_native_rtp.c: Destroying channel tech_pvt data 0x7f920c0414b0 [2018-03-13 12:35:33.392] DEBUG[2875][C-00000001] bridge.c: Bridge f621f610-ee87-442e-bfdf-022922edda0d: dissolving bridge with cause 16(Normal Clearing) [2018-03-13 12:35:33.392] DEBUG[2875][C-00000001] bridge_channel.c: Setting 0x7f920c00cd78(SIP/10.1.144.4-00000001) state from:0 to:2 [2018-03-13 12:35:33.392] DEBUG[2875][C-00000001] bridge.c: Bridge f621f610-ee87-442e-bfdf-022922edda0d: queueing action type:13 sub:1001 [2018-03-13 12:35:33.393] DEBUG[2875][C-00000001] bridge.c: Bridge f621f610-ee87-442e-bfdf-022922edda0d is dissolved, not performing smart bridge operation. [2018-03-13 12:35:33.393] DEBUG[2875][C-00000001] channel.c: Channel 0x7f9210035728 'SIP/c1nb2-00000002' hanging up. Refs: 3 [2018-03-13 12:35:33.393] DEBUG[2875][C-00000001] chan_sip.c: Hangup call SIP/c1nb2-00000002, SIP callid 4f24d37f4243ed5f27fab5781883094e@192.168.10.202:5060 [2018-03-13 12:35:33.393] DEBUG[2874][C-00000000] bridge_channel.c: Bridge f621f610-ee87-442e-bfdf-022922edda0d: pulling 0x7f920c00cd78(SIP/10.1.144.4-00000001) [2018-03-13 12:35:33.393] VERBOSE[2874][C-00000000] bridge_channel.c: Channel SIP/10.1.144.4-00000001 left 'native_rtp' basic-bridge [2018-03-13 12:35:33.393] DEBUG[2874][C-00000000] bridge_channel.c: Bridge f621f610-ee87-442e-bfdf-022922edda0d: 0x7f920c00cd78(SIP/10.1.144.4-00000001) is leaving native_rtp technology [2018-03-13 12:35:33.393] DEBUG[2874][C-00000000] bridge_native_rtp.c: Bridge 'f621f610-ee87-442e-bfdf-022922edda0d'. Channel 'SIP/10.1.144.4-00000001' is leaving bridge tech [2018-03-13 12:35:33.393] DEBUG[2874][C-00000000] bridge_native_rtp.c: Bridge 'f621f610-ee87-442e-bfdf-022922edda0d'. Detaching hook data 0x7f920c074230 from 'SIP/10.1.144.4-00000001' [2018-03-13 12:35:33.393] DEBUG[2874][C-00000000] bridge_native_rtp.c: Destroying channel tech_pvt data 0x7f920c022140 [2018-03-13 12:35:33.394] DEBUG[2874][C-00000000] bridge_channel.c: Channel SIP/10.1.144.4-00000001 will survive this bridge; clearing outgoing (dialed) flag [2018-03-13 12:35:33.394] DEBUG[2874][C-00000000] bridge.c: Bridge f621f610-ee87-442e-bfdf-022922edda0d is dissolved, not performing smart bridge operation. [2018-03-13 12:35:33.394] DEBUG[2874][C-00000000] res_rtp_asterisk.c: Not changing SSRC since we haven't sent any RTP yet [2018-03-13 12:35:33.394] DEBUG[2874][C-00000000] channel.c: Channel 0x7f920c02dba8 'SIP/10.1.144.4-00000001' hanging up. Refs: 2 [2018-03-13 12:35:33.394] DEBUG[2874][C-00000000] chan_sip.c: Hangup call SIP/10.1.144.4-00000001, SIP callid 53d350be226bf3ee6306cdd525115013@10.1.144.6:5060 [2018-03-13 12:35:33.395] DEBUG[2874][C-00000000] netsock2.c: Splitting '10.1.144.4' into... [2018-03-13 12:35:33.395] DEBUG[2874][C-00000000] netsock2.c: ...host '10.1.144.4' and port ''. [2018-03-13 12:35:33.395] DEBUG[2874][C-00000000] chan_sip.c: Trying to put 'BYE sip:177' onto UDP socket destined for 10.1.144.4:5060 [2018-03-13 12:35:33.396] DEBUG[2874][C-00000000] channel.c: Channel 0x7f920c02dba8 'SIP/10.1.144.4-00000001' destroying [2018-03-13 12:35:33.396] DEBUG[2807][C-00000000] bridge.c: Bridge f621f610-ee87-442e-bfdf-022922edda0d: actually destroying basic bridge, nobody wants it anymore [2018-03-13 12:35:33.397] DEBUG[2807][C-00000000] bridge.c: Bridge f621f610-ee87-442e-bfdf-022922edda0d: calling basic bridge destructor [2018-03-13 12:35:33.397] DEBUG[2807][C-00000000] bridge.c: Bridge f621f610-ee87-442e-bfdf-022922edda0d: calling native_rtp technology stop [2018-03-13 12:35:33.397] DEBUG[2807][C-00000000] bridge.c: Bridge f621f610-ee87-442e-bfdf-022922edda0d: calling native_rtp technology destructor [2018-03-13 12:35:33.397] DEBUG[2808] devicestate.c: No provider found, checking channel drivers for SIP - 10.1.144.4 [2018-03-13 12:35:33.397] DEBUG[2808] chan_sip.c: Checking device state for peer 10.1.144.4 [2018-03-13 12:35:33.397] DEBUG[2808] devicestate.c: Changing state for SIP/10.1.144.4 - state 4 (Invalid) [2018-03-13 12:35:33.412] DEBUG[2830] chan_sip.c: = Looking for Call ID: 53d350be226bf3ee6306cdd525115013@10.1.144.6:5060 (Checking To) --From tag as00a81d6c --To-tag KU038D3Bj4jDK [2018-03-13 12:35:33.412] DEBUG[2830][C-00000000] chan_sip.c: Stopping retransmission on '53d350be226bf3ee6306cdd525115013@10.1.144.6:5060' of Request 103: Match Found [2018-03-13 12:35:33.412] DEBUG[2830] chan_sip.c: Destroying SIP dialog 53d350be226bf3ee6306cdd525115013@10.1.144.6:5060 [2018-03-13 12:35:33.412] DEBUG[2830] rtp_engine.c: Destroyed RTP instance '0x7f920c031b08' [2018-03-13 12:35:39.771] DEBUG[2794] cdr.c: CDR Engine termination request received; waiting on messages... [2018-03-13 12:35:39.772] VERBOSE[2794] asterisk.c: Asterisk cleanly ending (0). [2018-03-13 12:35:39.772] VERBOSE[2794] asterisk.c: Executing last minute cleanups [2018-03-13 12:35:39.773] VERBOSE[2794] res_musiconhold.c: Destroying musiconhold processes [2018-03-13 12:35:39.773] DEBUG[2794] res_musiconhold.c: Destroying MOH class 'default' [2018-03-13 12:35:39.774] VERBOSE[2794] manager.c: Manager unregistered action DBGet [2018-03-13 12:35:39.774] VERBOSE[2794] manager.c: Manager unregistered action DBPut [2018-03-13 12:35:39.774] VERBOSE[2794] manager.c: Manager unregistered action DBDel [2018-03-13 12:35:39.774] VERBOSE[2794] manager.c: Manager unregistered action DBDelTree [2018-03-13 12:35:39.774] DEBUG[2794] asterisk.c: Asterisk ending (0).