*CLI> [Jul 24 08:57:51] DEBUG[1908]: chan_sip.c:15040 sipsock_read: Invalid SIP message - rejected , no callid, len 537 [Jul 24 08:57:54] DEBUG[1908]: chan_sip.c:2624 do_setnat: Setting NAT on RTP to Off [Jul 24 08:57:54] DEBUG[1908]: chan_sip.c:2634 do_setnat: Setting NAT on UDPTL to Off [Jul 24 08:57:54] DEBUG[1908]: chan_sip.c:4375 sip_alloc: Allocating new SIP dialog for c8c5e2e08b4d9202-65c9-46a5f67b-7918@8.7.177.101 - INVITE (With RTP) [Jul 24 08:57:54] DEBUG[1908]: chan_sip.c:2624 do_setnat: Setting NAT on RTP to Off [Jul 24 08:57:54] DEBUG[1908]: chan_sip.c:2634 do_setnat: Setting NAT on UDPTL to Off [Jul 24 08:57:54] DEBUG[1908]: chan_sip.c:5226 process_sdp: T38 state changed to 0 on channel [Jul 24 08:57:54] DEBUG[1908]: chan_sip.c:5306 process_sdp: We're settling with these formats: 0x4 (ulaw) [Jul 24 08:57:54] DEBUG[1908]: chan_sip.c:13540 handle_request_invite: Checking SIP call limits for device [Jul 24 08:57:54] DEBUG[1908]: chan_sip.c:3058 update_call_counter: Updating call counter for incoming call [Jul 24 08:57:54] DEBUG[1908]: chan_sip.c:3867 sip_new: *** Our native formats are 0x4 (ulaw) [Jul 24 08:57:54] DEBUG[1908]: chan_sip.c:3868 sip_new: *** Joint capabilities are 0x4 (ulaw) [Jul 24 08:57:54] DEBUG[1908]: chan_sip.c:3869 sip_new: *** Our capabilities are 0x4 (ulaw) [Jul 24 08:57:54] DEBUG[1908]: chan_sip.c:3870 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Jul 24 08:57:54] DEBUG[1908]: chan_sip.c:3893 sip_new: This channel will not be able to handle video. [Jul 24 08:57:54] DEBUG[1908]: chan_sip.c:8036 build_route: build_route: Record-Route hop: [Jul 24 08:57:54] DEBUG[1908]: chan_sip.c:13615 handle_request_invite: SIP/ss1tampa.mixnetworks.com-0970c2c0: New call is still down.... Trying... [Jul 24 08:57:54] DEBUG[1908]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/ss1tampa.mixnetworks.com-0970c2c0 [Jul 24 08:57:54] DEBUG[1892]: chan_sip.c:15481 sip_devicestate: Checking device state for peer ss1tampa.mixnetworks.com [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1809 pbx_extension_helper: Launching 'Goto' -- Executing [14166287392@from-voip:1] Goto("SIP/ss1tampa.mixnetworks.com-0970c2c0", "4166287392|1") in new stack -- Goto (from-voip,4166287392,1) [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1809 pbx_extension_helper: Launching 'Verbose' -- Executing [4166287392@from-voip:1] Verbose("SIP/ss1tampa.mixnetworks.com-0970c2c0", "1|Sending call to routing Macro") in new stack Sending call to routing Macro [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1809 pbx_extension_helper: Launching 'Gosub' -- Executing [4166287392@from-voip:2] Gosub("SIP/ss1tampa.mixnetworks.com-0970c2c0", "sub-route|s|1(4166287392)") in new stack [Jul 24 08:57:54] DEBUG[1917]: app_stack.c:174 gosub_exec: Setting 'ARG1' to '4166287392' [Jul 24 08:57:54] DEBUG[1917]: app_stack.c:179 gosub_exec: Setting gosub return address to '1:from-voip|4166287392|3' [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '"" <4163653075>' [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1809 pbx_extension_helper: Launching 'Verbose' -- Executing [s@sub-route:1] Verbose("SIP/ss1tampa.mixnetworks.com-0970c2c0", "1|"" <4163653075> is Entering Routing Process from SIP/ss1tampa.mixnetworks.com-0970c2c0... Please stand by") in new stack "" <4163653075> is Entering Routing Process from SIP/ss1tampa.mixnetworks.com-0970c2c0... Please stand by [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1809 pbx_extension_helper: Launching 'Set' -- Executing [s@sub-route:2] Set("SIP/ss1tampa.mixnetworks.com-0970c2c0", "DID=4166287392") in new stack [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '14166287392' [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1809 pbx_extension_helper: Launching 'Verbose' -- Executing [s@sub-route:3] Verbose("SIP/ss1tampa.mixnetworks.com-0970c2c0", "1|Sending to TRUNK GROUP check for 14166287392") in new stack Sending to TRUNK GROUP check for 14166287392 [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1809 pbx_extension_helper: Launching 'Gosub' -- Executing [s@sub-route:4] Gosub("SIP/ss1tampa.mixnetworks.com-0970c2c0", "sub-callgroups|s|1(did|4166287392)") in new stack [Jul 24 08:57:54] DEBUG[1917]: app_stack.c:174 gosub_exec: Setting 'ARG1' to 'did' [Jul 24 08:57:54] DEBUG[1917]: app_stack.c:174 gosub_exec: Setting 'ARG2' to '4166287392' [Jul 24 08:57:54] DEBUG[1917]: app_stack.c:179 gosub_exec: Setting gosub return address to '2:sub-route|s|5' [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1809 pbx_extension_helper: Launching 'Verbose' -- Executing [s@sub-callgroups:1] Verbose("SIP/ss1tampa.mixnetworks.com-0970c2c0", "1|Performing call-group check for 4166287392") in new stack Performing call-group check for 4166287392 [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1809 pbx_extension_helper: Launching 'Set' -- Executing [s@sub-callgroups:2] Set("SIP/ss1tampa.mixnetworks.com-0970c2c0", "TYPE=did") in new stack [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1809 pbx_extension_helper: Launching 'Set' -- Executing [s@sub-callgroups:3] Set("SIP/ss1tampa.mixnetworks.com-0970c2c0", "DATA=4166287392") in new stack [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1730 pbx_substitute_variables_helper_full: Expression result is '0' [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1809 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@sub-callgroups:4] GotoIf("SIP/ss1tampa.mixnetworks.com-0970c2c0", "0?dev|1") in new stack [Jul 24 08:57:54] DEBUG[1917]: pbx.c:5976 pbx_builtin_gotoif: Not taking any branch [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1730 pbx_substitute_variables_helper_full: Expression result is '1' [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1809 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@sub-callgroups:5] GotoIf("SIP/ss1tampa.mixnetworks.com-0970c2c0", "1?did|1") in new stack -- Goto (sub-callgroups,did,1) [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1809 pbx_extension_helper: Launching 'Verbose' -- Executing [did@sub-callgroups:1] Verbose("SIP/ss1tampa.mixnetworks.com-0970c2c0", "1|CALLGROUP: Checking for our DID --> 4166287392") in new stack CALLGROUP: Checking for our DID --> 4166287392 [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1809 pbx_extension_helper: Launching 'Set' -- Executing [did@sub-callgroups:2] Set("SIP/ss1tampa.mixnetworks.com-0970c2c0", "DID=4166287392") in new stack [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is 'xfertest' [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1809 pbx_extension_helper: Launching 'Set' -- Executing [did@sub-callgroups:3] Set("SIP/ss1tampa.mixnetworks.com-0970c2c0", "PBX=xfertest") in new stack [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '' [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1809 pbx_extension_helper: Launching 'Set' -- Executing [did@sub-callgroups:4] Set("SIP/ss1tampa.mixnetworks.com-0970c2c0", "ARRAY(CALLGROUP|MAXCALLS)=") in new stack [Jul 24 08:57:54] DEBUG[1917]: func_strings.c:188 array: array (CALLGROUP|MAXCALLS=) [Jul 24 08:57:54] DEBUG[1917]: func_strings.c:201 array: array set value (CALLGROUP=(null)) [Jul 24 08:57:54] DEBUG[1917]: func_strings.c:201 array: array set value (MAXCALLS=(null)) [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '0' [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1809 pbx_extension_helper: Launching 'Set' -- Executing [did@sub-callgroups:5] Set("SIP/ss1tampa.mixnetworks.com-0970c2c0", "BLOCK_POOL=0") in new stack [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '0' [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1730 pbx_substitute_variables_helper_full: Expression result is '0' [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1809 pbx_extension_helper: Launching 'GotoIf' -- Executing [did@sub-callgroups:6] GotoIf("SIP/ss1tampa.mixnetworks.com-0970c2c0", "0?error_handler|null_val|1") in new stack [Jul 24 08:57:54] DEBUG[1917]: pbx.c:5976 pbx_builtin_gotoif: Not taking any branch [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '0' [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '0' [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1730 pbx_substitute_variables_helper_full: Expression result is '0' [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is 'Goto(chk|1)' [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1809 pbx_extension_helper: Launching 'Exec' -- Executing [did@sub-callgroups:7] Exec("SIP/ss1tampa.mixnetworks.com-0970c2c0", "Goto(chk|1)") in new stack -- Goto (sub-callgroups,chk,1) [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '1' [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '1' [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1730 pbx_substitute_variables_helper_full: Expression result is '1' [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1730 pbx_substitute_variables_helper_full: Expression result is '0' [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1730 pbx_substitute_variables_helper_full: Expression result is '0' [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1809 pbx_extension_helper: Launching 'GotoIf' -- Executing [chk@sub-callgroups:1] GotoIf("SIP/ss1tampa.mixnetworks.com-0970c2c0", "0?block|1") in new stack [Jul 24 08:57:54] DEBUG[1917]: pbx.c:5976 pbx_builtin_gotoif: Not taking any branch [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '1' [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '1' [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1730 pbx_substitute_variables_helper_full: Expression result is '1' [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1730 pbx_substitute_variables_helper_full: Expression result is '1' [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1730 pbx_substitute_variables_helper_full: Expression result is '1' [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1809 pbx_extension_helper: Launching 'GotoIf' -- Executing [chk@sub-callgroups:2] GotoIf("SIP/ss1tampa.mixnetworks.com-0970c2c0", "1?return|1") in new stack -- Goto (sub-callgroups,return,1) [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '1' [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1730 pbx_substitute_variables_helper_full: Expression result is '1' [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is 'NON-BLOCKING' [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1809 pbx_extension_helper: Launching 'Verbose' -- Executing [return@sub-callgroups:1] Verbose("SIP/ss1tampa.mixnetworks.com-0970c2c0", "1|Allowing call from SIP/ss1tampa.mixnetworks.com-0970c2c0 due to room in NON-BLOCKING trunk pool") in new stack Allowing call from SIP/ss1tampa.mixnetworks.com-0970c2c0 due to room in NON-BLOCKING trunk pool [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1809 pbx_extension_helper: Launching 'Return' -- Executing [return@sub-callgroups:2] Return("SIP/ss1tampa.mixnetworks.com-0970c2c0", "") in new stack [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1809 pbx_extension_helper: Launching 'Verbose' -- Executing [s@sub-route:5] Verbose("SIP/ss1tampa.mixnetworks.com-0970c2c0", "1|Discovering entry point for 4166287392") in new stack Discovering entry point for 4166287392 [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is 'Telic Main,Queue,7,xfertest' [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1809 pbx_extension_helper: Launching 'Set' -- Executing [s@sub-route:6] Set("SIP/ss1tampa.mixnetworks.com-0970c2c0", "HASH(ROUTE_ROUTE)=Telic Main,Queue,7,xfertest") in new stack [Jul 24 08:57:54] DEBUG[1917]: func_odbc.c:170 array: array (did_source,did_destination,did_dest_address_id,did_pbx=Telic Main,Queue,7,xfertest) [Jul 24 08:57:54] DEBUG[1917]: func_odbc.c:182 array: array set value (did_source=Telic Main) [Jul 24 08:57:54] DEBUG[1917]: func_odbc.c:182 array: array set value (did_destination=Queue) [Jul 24 08:57:54] DEBUG[1917]: func_odbc.c:182 array: array set value (did_dest_address_id=7) [Jul 24 08:57:54] DEBUG[1917]: func_odbc.c:182 array: array set value (did_pbx=xfertest) [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is 'xfertest' [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1809 pbx_extension_helper: Launching 'Set' -- Executing [s@sub-route:7] Set("SIP/ss1tampa.mixnetworks.com-0970c2c0", "CDR(accountcode)=xfertest") in new stack [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1809 pbx_extension_helper: Launching 'Verbose' -- Executing [s@sub-route:8] Verbose("SIP/ss1tampa.mixnetworks.com-0970c2c0", "1|Building route string...") in new stack Building route string... [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is 'Queue' [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1809 pbx_extension_helper: Launching 'Set' -- Executing [s@sub-route:9] Set("SIP/ss1tampa.mixnetworks.com-0970c2c0", "CMD=Queue") in new stack [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '0' [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1730 pbx_substitute_variables_helper_full: Expression result is '0' [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1809 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@sub-route:10] GotoIf("SIP/ss1tampa.mixnetworks.com-0970c2c0", "0?reject|1") in new stack [Jul 24 08:57:54] DEBUG[1917]: pbx.c:5976 pbx_builtin_gotoif: Not taking any branch [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1730 pbx_substitute_variables_helper_full: Expression result is '0' [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1809 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@sub-route:11] GotoIf("SIP/ss1tampa.mixnetworks.com-0970c2c0", "0?device|1") in new stack [Jul 24 08:57:54] DEBUG[1917]: pbx.c:5976 pbx_builtin_gotoif: Not taking any branch [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1730 pbx_substitute_variables_helper_full: Expression result is '0' [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1809 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@sub-route:12] GotoIf("SIP/ss1tampa.mixnetworks.com-0970c2c0", "0?meetme|1") in new stack [Jul 24 08:57:54] DEBUG[1917]: pbx.c:5976 pbx_builtin_gotoif: Not taking any branch [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1730 pbx_substitute_variables_helper_full: Expression result is '0' [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1809 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@sub-route:13] GotoIf("SIP/ss1tampa.mixnetworks.com-0970c2c0", "0?softswitch|1") in new stack [Jul 24 08:57:54] DEBUG[1917]: pbx.c:5976 pbx_builtin_gotoif: Not taking any branch [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1730 pbx_substitute_variables_helper_full: Expression result is '0' [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1809 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@sub-route:14] GotoIf("SIP/ss1tampa.mixnetworks.com-0970c2c0", "0?aa|1") in new stack [Jul 24 08:57:54] DEBUG[1917]: pbx.c:5976 pbx_builtin_gotoif: Not taking any branch [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1730 pbx_substitute_variables_helper_full: Expression result is '0' [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1809 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@sub-route:15] GotoIf("SIP/ss1tampa.mixnetworks.com-0970c2c0", "0?hg|1") in new stack [Jul 24 08:57:54] DEBUG[1917]: pbx.c:5976 pbx_builtin_gotoif: Not taking any branch [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1730 pbx_substitute_variables_helper_full: Expression result is '1' [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1809 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@sub-route:16] GotoIf("SIP/ss1tampa.mixnetworks.com-0970c2c0", "1?qq|1") in new stack -- Goto (sub-route,qq,1) [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1809 pbx_extension_helper: Launching 'NoOp' -- Executing [qq@sub-route:1] NoOp("SIP/ss1tampa.mixnetworks.com-0970c2c0", "") in new stack [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1809 pbx_extension_helper: Launching 'Verbose' -- Executing [qq@sub-route:2] Verbose("SIP/ss1tampa.mixnetworks.com-0970c2c0", "1|Routing 4166287392 to Queue") in new stack Routing 4166287392 to Queue [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '7' [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1809 pbx_extension_helper: Launching 'Gosub' -- Executing [qq@sub-route:3] Gosub("SIP/ss1tampa.mixnetworks.com-0970c2c0", "sub-queues|4166287392|1(7|CONNECT-NEW)") in new stack [Jul 24 08:57:54] DEBUG[1917]: app_stack.c:174 gosub_exec: Setting 'ARG1' to '7' [Jul 24 08:57:54] DEBUG[1917]: app_stack.c:174 gosub_exec: Setting 'ARG2' to 'CONNECT-NEW' [Jul 24 08:57:54] DEBUG[1917]: app_stack.c:179 gosub_exec: Setting gosub return address to '2:sub-route|qq|4' [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1809 pbx_extension_helper: Launching 'Verbose' -- Executing [4166287392@sub-queues:1] Verbose("SIP/ss1tampa.mixnetworks.com-0970c2c0", "1|Starting the queue routine") in new stack Starting the queue routine [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1809 pbx_extension_helper: Launching 'Set' -- Executing [4166287392@sub-queues:2] Set("SIP/ss1tampa.mixnetworks.com-0970c2c0", "__FORWARD_CONTEXT=origination") in new stack [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1809 pbx_extension_helper: Launching 'Set' -- Executing [4166287392@sub-queues:3] Set("SIP/ss1tampa.mixnetworks.com-0970c2c0", "Q_ID=7") in new stack [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1809 pbx_extension_helper: Launching 'Set' -- Executing [4166287392@sub-queues:4] Set("SIP/ss1tampa.mixnetworks.com-0970c2c0", "ACTION=CONNECT-NEW") in new stack [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '0' [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1730 pbx_substitute_variables_helper_full: Expression result is '0' [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is 'NoOp()' [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1809 pbx_extension_helper: Launching 'Exec' -- Executing [4166287392@sub-queues:5] Exec("SIP/ss1tampa.mixnetworks.com-0970c2c0", "NoOp()") in new stack [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '0' [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1730 pbx_substitute_variables_helper_full: Expression result is '0' [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is 'NoOp()' [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1809 pbx_extension_helper: Launching 'Exec' -- Executing [4166287392@sub-queues:6] Exec("SIP/ss1tampa.mixnetworks.com-0970c2c0", "NoOp()") in new stack [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is 'xfertest_CQ_39,Transfer Test Queue' [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1809 pbx_extension_helper: Launching 'Set' -- Executing [4166287392@sub-queues:7] Set("SIP/ss1tampa.mixnetworks.com-0970c2c0", "HASH(queue)=xfertest_CQ_39,Transfer Test Queue") in new stack [Jul 24 08:57:54] DEBUG[1917]: func_odbc.c:170 array: array (name,description=xfertest_CQ_39,Transfer Test Queue) [Jul 24 08:57:54] DEBUG[1917]: func_odbc.c:182 array: array set value (name=xfertest_CQ_39) [Jul 24 08:57:54] DEBUG[1917]: func_odbc.c:182 array: array set value (description=Transfer Test Queue) [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is 'xfertest_CQ_39' [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1809 pbx_extension_helper: Launching 'Set' -- Executing [4166287392@sub-queues:8] Set("SIP/ss1tampa.mixnetworks.com-0970c2c0", "__MY_QUEUE=xfertest_CQ_39") in new stack [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is 'Transfer Test Queue' [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1809 pbx_extension_helper: Launching 'Set' -- Executing [4166287392@sub-queues:9] Set("SIP/ss1tampa.mixnetworks.com-0970c2c0", "CALLERID(name)=Transfer Test Queue") in new stack [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '0' [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1730 pbx_substitute_variables_helper_full: Expression result is '0' [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is 'NoOp()' [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1809 pbx_extension_helper: Launching 'Exec' -- Executing [4166287392@sub-queues:10] Exec("SIP/ss1tampa.mixnetworks.com-0970c2c0", "NoOp()") in new stack [Jul 24 08:57:54] WARNING[1917]: ast_expr2.y:742 op_minus: non-numeric argument [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1730 pbx_substitute_variables_helper_full: Expression result is '0' [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1809 pbx_extension_helper: Launching 'GotoIf' -- Executing [4166287392@sub-queues:11] GotoIf("SIP/ss1tampa.mixnetworks.com-0970c2c0", "0?new|1") in new stack [Jul 24 08:57:54] DEBUG[1917]: pbx.c:5976 pbx_builtin_gotoif: Not taking any branch [Jul 24 08:57:54] WARNING[1917]: ast_expr2.y:742 op_minus: non-numeric argument [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1730 pbx_substitute_variables_helper_full: Expression result is '0' [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1809 pbx_extension_helper: Launching 'GotoIf' -- Executing [4166287392@sub-queues:12] GotoIf("SIP/ss1tampa.mixnetworks.com-0970c2c0", "0?conn|1") in new stack [Jul 24 08:57:54] DEBUG[1917]: pbx.c:5976 pbx_builtin_gotoif: Not taking any branch [Jul 24 08:57:54] WARNING[1917]: ast_expr2.y:742 op_minus: non-numeric argument [Jul 24 08:57:54] WARNING[1917]: ast_expr2.y:742 op_minus: non-numeric argument [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1730 pbx_substitute_variables_helper_full: Expression result is '1' [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1809 pbx_extension_helper: Launching 'GotoIf' -- Executing [4166287392@sub-queues:13] GotoIf("SIP/ss1tampa.mixnetworks.com-0970c2c0", "1?conn|1") in new stack -- Goto (sub-queues,conn,1) [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1809 pbx_extension_helper: Launching 'NoOp' -- Executing [conn@sub-queues:1] NoOp("SIP/ss1tampa.mixnetworks.com-0970c2c0", "") in new stack [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1809 pbx_extension_helper: Launching 'Verbose' -- Executing [conn@sub-queues:2] Verbose("SIP/ss1tampa.mixnetworks.com-0970c2c0", "1|Looking for conference xfertest_CQ_39 in xfertest locally") in new stack Looking for conference xfertest_CQ_39 in xfertest locally [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '0' [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1809 pbx_extension_helper: Launching 'Set' -- Executing [conn@sub-queues:3] Set("SIP/ss1tampa.mixnetworks.com-0970c2c0", "Q_CHECK=0") in new stack [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1730 pbx_substitute_variables_helper_full: Expression result is '0' [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is 'Verbose(1|Queue xfertest_CQ_39@xfertestis not on this machine... LOCATING!)' [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1809 pbx_extension_helper: Launching 'Exec' -- Executing [conn@sub-queues:4] Exec("SIP/ss1tampa.mixnetworks.com-0970c2c0", "Verbose(1|Queue xfertest_CQ_39@xfertestis not on this machine... LOCATING!)") in new stack Queue xfertest_CQ_39@xfertestis not on this machine... LOCATING! [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1730 pbx_substitute_variables_helper_full: Expression result is '0' [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is 'Goto(find|1)' [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1809 pbx_extension_helper: Launching 'Exec' -- Executing [conn@sub-queues:5] Exec("SIP/ss1tampa.mixnetworks.com-0970c2c0", "Goto(find|1)") in new stack -- Goto (sub-queues,find,1) [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1809 pbx_extension_helper: Launching 'NoOp' -- Executing [find@sub-queues:1] NoOp("SIP/ss1tampa.mixnetworks.com-0970c2c0", "") in new stack [Jul 24 08:57:54] DEBUG[1917]: pbx_dundi.c:3386 register_request: Registering request for 'xfertest_CQ_39@queues' on behalf of '00:00:00:00:00:00' crc '00000000' [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '' [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1809 pbx_extension_helper: Launching 'Set' -- Executing [find@sub-queues:2] Set("SIP/ss1tampa.mixnetworks.com-0970c2c0", "REMOTE_Q_RES=") in new stack [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '' [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1809 pbx_extension_helper: Launching 'Set' -- Executing [find@sub-queues:3] Set("SIP/ss1tampa.mixnetworks.com-0970c2c0", "REMOTE_Q=") in new stack [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '' [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1730 pbx_substitute_variables_helper_full: Expression result is '0' [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is 'NoOp()' [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1809 pbx_extension_helper: Launching 'Exec' -- Executing [find@sub-queues:4] Exec("SIP/ss1tampa.mixnetworks.com-0970c2c0", "NoOp()") in new stack [Jul 24 08:57:54] WARNING[1917]: ast_expr2.y:742 op_minus: non-numeric argument [Jul 24 08:57:54] WARNING[1917]: ast_expr2.y:742 op_minus: non-numeric argument [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1730 pbx_substitute_variables_helper_full: Expression result is '1' [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1809 pbx_extension_helper: Launching 'GotoIf' -- Executing [find@sub-queues:5] GotoIf("SIP/ss1tampa.mixnetworks.com-0970c2c0", "1?new|create:no_q|1") in new stack -- Goto (sub-queues,new,8) [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1809 pbx_extension_helper: Launching 'Verbose' -- Executing [new@sub-queues:8] Verbose("SIP/ss1tampa.mixnetworks.com-0970c2c0", "1|Queue xfertest_CQ_39 in xfertest does not yet exist... CREATING!") in new stack Queue xfertest_CQ_39 in xfertest does not yet exist... CREATING! [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1809 pbx_extension_helper: Launching 'Verbose' -- Executing [new@sub-queues:9] Verbose("SIP/ss1tampa.mixnetworks.com-0970c2c0", "1|Building xfertest_CQ_39 in xfertest on this machine") in new stack Building xfertest_CQ_39 in xfertest on this machine [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1809 pbx_extension_helper: Launching 'Set' -- Executing [new@sub-queues:10] Set("SIP/ss1tampa.mixnetworks.com-0970c2c0", "GROUP(queues)=xfertest_CQ_39") in new stack [Jul 24 08:57:54] DEBUG[1917]: pbx.c:1809 pbx_extension_helper: Launching 'Queue' ** Calling the Queue ** -- Executing [new@sub-queues:11] Queue("SIP/ss1tampa.mixnetworks.com-0970c2c0", "xfertest_CQ_39|n") in new stack [Jul 24 08:57:54] DEBUG[1917]: app_queue.c:3343 queue_exec: NO QUEUE_PRIO variable found. Using default. [Jul 24 08:57:54] DEBUG[1917]: app_queue.c:3366 queue_exec: queue: xfertest_CQ_39, options: n, url: (null), announce: (null), expires: 0, priority: 0 [Jul 24 08:57:54] DEBUG[1917]: chan_sip.c:15481 sip_devicestate: Checking device state for peer u301#xfertest [Jul 24 08:57:54] DEBUG[1892]: devicestate.c:287 do_state_change: Changing state for SIP/ss1tampa.mixnetworks.com - state 4 (Invalid) [Jul 24 08:57:54] DEBUG[1918]: app_queue.c:546 changethread: Device 'SIP/ss1tampa.mixnetworks.com' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [Jul 24 08:57:54] DEBUG[1917]: chan_sip.c:2408 sip_destroy_peer: Destroying SIP peer u301#xfertest [Jul 24 08:57:54] DEBUG[1917]: app_queue.c:706 add_to_interfaces: Adding SIP/u301#xfertest to the list of interfaces that make up all of our queue members. [Jul 24 08:57:54] DEBUG[1917]: chan_sip.c:15481 sip_devicestate: Checking device state for peer u302#xfertest [Jul 24 08:57:54] DEBUG[1917]: chan_sip.c:2408 sip_destroy_peer: Destroying SIP peer u302#xfertest [Jul 24 08:57:54] DEBUG[1917]: app_queue.c:706 add_to_interfaces: Adding SIP/u302#xfertest to the list of interfaces that make up all of our queue members. [Jul 24 08:57:54] DEBUG[1917]: chan_sip.c:15481 sip_devicestate: Checking device state for peer u303#xfertest [Jul 24 08:57:54] DEBUG[1917]: chan_sip.c:2408 sip_destroy_peer: Destroying SIP peer u303#xfertest [Jul 24 08:57:54] DEBUG[1917]: app_queue.c:706 add_to_interfaces: Adding SIP/u303#xfertest to the list of interfaces that make up all of our queue members. [Jul 24 08:57:54] DEBUG[1917]: app_queue.c:1218 join_queue: Queue 'xfertest_CQ_39' Join, Channel 'SIP/ss1tampa.mixnetworks.com-0970c2c0', Position '1' [Jul 24 08:57:54] DEBUG[1917]: channel.c:2727 ast_prod: Prodding channel 'SIP/ss1tampa.mixnetworks.com-0970c2c0' [Jul 24 08:57:54] DEBUG[1917]: chan_sip.c:6499 transmit_response_with_sdp: Setting framing from config on incoming call [Jul 24 08:57:54] DEBUG[1917]: chan_sip.c:6263 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True [Jul 24 08:57:54] DEBUG[1917]: chan_sip.c:6264 add_sdp: ** Our prefcodec: 0x0 (nothing) [Jul 24 08:57:54] DEBUG[1917]: chan_sip.c:6395 add_sdp: -- Done with adding codecs to SDP [Jul 24 08:57:54] DEBUG[1917]: chan_sip.c:6440 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw) -- Started music on hold, class 'default', on SIP/ss1tampa.mixnetworks.com-0970c2c0 [Jul 24 08:57:54] DEBUG[1917]: channel.c:2064 ast_settimeout: Scheduling timer at 160 sample intervals [Jul 24 08:57:54] DEBUG[1917]: app_queue.c:2113 is_our_turn: It's our turn (SIP/ss1tampa.mixnetworks.com-0970c2c0). [Jul 24 08:57:54] DEBUG[1917]: app_queue.c:2371 try_calling: SIP/ss1tampa.mixnetworks.com-0970c2c0 is trying to call a queue member. [Jul 24 08:57:54] DEBUG[1917]: app_queue.c:1735 ring_one: Trying 'SIP/u301#xfertest' with metric 0 [Jul 24 08:57:54] DEBUG[1917]: chan_sip.c:15547 sip_request_call: Asked to create a SIP channel with formats: 0x4 (ulaw) [Jul 24 08:57:54] DEBUG[1917]: chan_sip.c:4375 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Jul 24 08:57:55] DEBUG[1917]: chan_sip.c:2670 create_addr_from_peer: Our T38 capability (3856) [Jul 24 08:57:55] DEBUG[1917]: chan_sip.c:2624 do_setnat: Setting NAT on RTP to On [Jul 24 08:57:55] DEBUG[1917]: chan_sip.c:2634 do_setnat: Setting NAT on UDPTL to On [Jul 24 08:57:55] DEBUG[1917]: chan_sip.c:2408 sip_destroy_peer: Destroying SIP peer u301#xfertest [Jul 24 08:57:55] DEBUG[1917]: chan_sip.c:3867 sip_new: *** Our native formats are 0x4 (ulaw) [Jul 24 08:57:55] DEBUG[1917]: chan_sip.c:3868 sip_new: *** Joint capabilities are 0x0 (nothing) [Jul 24 08:57:55] DEBUG[1917]: chan_sip.c:3869 sip_new: *** Our capabilities are 0x104 (ulaw|g729) [Jul 24 08:57:55] DEBUG[1917]: chan_sip.c:3870 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Jul 24 08:57:55] DEBUG[1917]: chan_sip.c:3872 sip_new: *** Our preferred formats from the incoming channel are 0x4 (ulaw) [Jul 24 08:57:55] DEBUG[1917]: chan_sip.c:3893 sip_new: This channel will not be able to handle video. [Jul 24 08:57:55] DEBUG[1917]: chan_sip.c:2882 sip_call: Outgoing Call for u301#xfertest [Jul 24 08:57:55] DEBUG[1917]: chan_sip.c:3058 update_call_counter: Updating call counter for outgoing call [Jul 24 08:57:55] DEBUG[1917]: chan_sip.c:2897 sip_call: Our T38 capability (3856), joint T38 capability (3856) [Jul 24 08:57:55] DEBUG[1917]: chan_sip.c:6263 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: False [Jul 24 08:57:55] DEBUG[1917]: chan_sip.c:6264 add_sdp: ** Our prefcodec: 0x4 (ulaw) [Jul 24 08:57:55] DEBUG[1917]: chan_sip.c:6395 add_sdp: -- Done with adding codecs to SDP [Jul 24 08:57:55] DEBUG[1917]: chan_sip.c:6440 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw) [Jul 24 08:57:55] DEBUG[1908]: chan_sip.c:2180 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '1d13e04f64a0f8ca1611499270ff3153@8.7.177.15' Request 102: Found [Jul 24 08:57:55] DEBUG[1917]: res_musiconhold.c:254 ast_moh_files_next: SIP/ss1tampa.mixnetworks.com-0970c2c0 Opened file 1 '/var/lib/asterisk/sounds/moh/ast_standard/fpm-world-mix' [Jul 24 08:57:55] DEBUG[1917]: rtp.c:2727 ast_rtp_write: Ooh, format changed from unknown to ulaw [Jul 24 08:57:55] DEBUG[1917]: rtp.c:2744 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160 [Jul 24 08:57:55] DEBUG[1917]: channel.c:2147 ast_read_generator_actions: Generator got voice, switching to phase locked mode [Jul 24 08:57:55] DEBUG[1917]: channel.c:2064 ast_settimeout: Scheduling timer at 0 sample intervals [Jul 24 08:57:55] DEBUG[1908]: chan_sip.c:2180 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '1d13e04f64a0f8ca1611499270ff3153@8.7.177.15' Request 102: Found [Jul 24 08:57:55] DEBUG[1908]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/u301#xfertest-09721690 -- SIP/u301#xfertest-09721690 is ringing [Jul 24 08:57:55] DEBUG[1892]: chan_sip.c:15481 sip_devicestate: Checking device state for peer u301#xfertest [Jul 24 08:57:55] DEBUG[1892]: chan_sip.c:2408 sip_destroy_peer: Destroying SIP peer u301#xfertest [Jul 24 08:57:55] DEBUG[1892]: devicestate.c:287 do_state_change: Changing state for SIP/u301#xfertest - state 1 (Not in use) [Jul 24 08:57:55] DEBUG[1919]: app_queue.c:552 changethread: Device 'SIP/u301#xfertest' changed to state '1' (Not in use) [Jul 24 08:57:58] DEBUG[1917]: rtp.c:875 ast_rtcp_read: Got RTCP report of 132 bytes [Jul 24 08:58:01] DEBUG[1917]: rtp.c:875 ast_rtcp_read: Got RTCP report of 132 bytes -- Nobody picked up in 7000 ms ** Calling 2nd phone ** [Jul 24 08:58:02] DEBUG[1917]: app_queue.c:1752 store_next: Next is 'SIP/u302#xfertest' with metric 1 [Jul 24 08:58:02] DEBUG[1917]: app_queue.c:2432 try_calling: SIP/ss1tampa.mixnetworks.com-0970c2c0: Nobody answered. [Jul 24 08:58:02] DEBUG[1917]: channel.c:1756 ast_hangup: Hanging up channel 'SIP/u301#xfertest-09721690' [Jul 24 08:58:02] DEBUG[1917]: chan_sip.c:3368 sip_hangup: Hangup call SIP/u301#xfertest-09721690, SIP callid 1d13e04f64a0f8ca1611499270ff3153@8.7.177.15) [Jul 24 08:58:02] DEBUG[1917]: chan_sip.c:2120 __sip_ack: Acked pending invite 102 [Jul 24 08:58:02] DEBUG[1917]: chan_sip.c:2138 __sip_ack: Stopping retransmission on '1d13e04f64a0f8ca1611499270ff3153@8.7.177.15' of Request 102: Match Not Found [Jul 24 08:58:02] DEBUG[1917]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/u301#xfertest-09721690 [Jul 24 08:58:02] DEBUG[1892]: chan_sip.c:15481 sip_devicestate: Checking device state for peer u301#xfertest [Jul 24 08:58:02] DEBUG[1908]: chan_sip.c:2138 __sip_ack: Stopping retransmission on '1d13e04f64a0f8ca1611499270ff3153@8.7.177.15' of Request 102: Match Not Found [Jul 24 08:58:02] DEBUG[1892]: chan_sip.c:2408 sip_destroy_peer: Destroying SIP peer u301#xfertest [Jul 24 08:58:02] DEBUG[1892]: devicestate.c:287 do_state_change: Changing state for SIP/u301#xfertest - state 1 (Not in use) [Jul 24 08:58:02] DEBUG[1920]: app_queue.c:552 changethread: Device 'SIP/u301#xfertest' changed to state '1' (Not in use) [Jul 24 08:58:02] DEBUG[1908]: chan_sip.c:2138 __sip_ack: Stopping retransmission on '1d13e04f64a0f8ca1611499270ff3153@8.7.177.15' of Request 102: Match Found [Jul 24 08:58:02] DEBUG[1908]: chan_sip.c:3058 update_call_counter: Updating call counter for outgoing call [Jul 24 08:58:02] DEBUG[1908]: chan_sip.c:1641 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 1d13e04f64a0f8ca1611499270ff3153@8.7.177.15 Really destroying SIP dialog '1d13e04f64a0f8ca1611499270ff3153@8.7.177.15' Method: INVITE [Jul 24 08:58:04] DEBUG[1917]: app_queue.c:2113 is_our_turn: It's our turn (SIP/ss1tampa.mixnetworks.com-0970c2c0). -- Stopped music on hold on SIP/ss1tampa.mixnetworks.com-0970c2c0 [Jul 24 08:58:04] DEBUG[1917]: channel.c:2064 ast_settimeout: Scheduling timer at 0 sample intervals [Jul 24 08:58:04] DEBUG[1917]: channel.c:2064 ast_settimeout: Scheduling timer at 160 sample intervals -- Playing 'queue-youarenext' (language 'en') [Jul 24 08:58:06] DEBUG[1908]: chan_sip.c:15040 sipsock_read: Invalid SIP message - rejected , no callid, len 537 [Jul 24 08:58:07] DEBUG[1917]: rtp.c:875 ast_rtcp_read: Got RTCP report of 132 bytes [Jul 24 08:58:09] DEBUG[1917]: channel.c:2064 ast_settimeout: Scheduling timer at 90 sample intervals [Jul 24 08:58:09] DEBUG[1917]: channel.c:2064 ast_settimeout: Scheduling timer at 0 sample intervals [Jul 24 08:58:09] DEBUG[1917]: channel.c:2064 ast_settimeout: Scheduling timer at 0 sample intervals -- Told SIP/ss1tampa.mixnetworks.com-0970c2c0 in xfertest_CQ_39 their queue position (which was 1) [Jul 24 08:58:09] DEBUG[1917]: channel.c:2064 ast_settimeout: Scheduling timer at 160 sample intervals -- Playing 'queue-thankyou' (language 'en') [Jul 24 08:58:11] DEBUG[1917]: channel.c:2064 ast_settimeout: Scheduling timer at 119 sample intervals [Jul 24 08:58:11] DEBUG[1917]: channel.c:2064 ast_settimeout: Scheduling timer at 0 sample intervals [Jul 24 08:58:11] DEBUG[1917]: channel.c:2064 ast_settimeout: Scheduling timer at 0 sample intervals [Jul 24 08:58:11] DEBUG[1917]: channel.c:2727 ast_prod: Prodding channel 'SIP/ss1tampa.mixnetworks.com-0970c2c0' -- Started music on hold, class 'default', on SIP/ss1tampa.mixnetworks.com-0970c2c0 [Jul 24 08:58:11] DEBUG[1917]: channel.c:2064 ast_settimeout: Scheduling timer at 160 sample intervals [Jul 24 08:58:11] DEBUG[1917]: app_queue.c:2371 try_calling: SIP/ss1tampa.mixnetworks.com-0970c2c0 is trying to call a queue member. [Jul 24 08:58:11] DEBUG[1917]: app_queue.c:1735 ring_one: Trying 'SIP/u302#xfertest' with metric 1 [Jul 24 08:58:11] DEBUG[1917]: chan_sip.c:15547 sip_request_call: Asked to create a SIP channel with formats: 0x4 (ulaw) [Jul 24 08:58:11] DEBUG[1917]: chan_sip.c:4375 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Jul 24 08:58:11] DEBUG[1917]: chan_sip.c:2670 create_addr_from_peer: Our T38 capability (3856) [Jul 24 08:58:11] DEBUG[1917]: chan_sip.c:2624 do_setnat: Setting NAT on RTP to On [Jul 24 08:58:11] DEBUG[1917]: chan_sip.c:2634 do_setnat: Setting NAT on UDPTL to On [Jul 24 08:58:11] DEBUG[1917]: chan_sip.c:2408 sip_destroy_peer: Destroying SIP peer u302#xfertest [Jul 24 08:58:11] DEBUG[1917]: chan_sip.c:3867 sip_new: *** Our native formats are 0x4 (ulaw) [Jul 24 08:58:11] DEBUG[1917]: chan_sip.c:3868 sip_new: *** Joint capabilities are 0x0 (nothing) [Jul 24 08:58:11] DEBUG[1917]: chan_sip.c:3869 sip_new: *** Our capabilities are 0x104 (ulaw|g729) [Jul 24 08:58:11] DEBUG[1917]: chan_sip.c:3870 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Jul 24 08:58:11] DEBUG[1917]: chan_sip.c:3872 sip_new: *** Our preferred formats from the incoming channel are 0x4 (ulaw) [Jul 24 08:58:11] DEBUG[1917]: chan_sip.c:3893 sip_new: This channel will not be able to handle video. [Jul 24 08:58:11] DEBUG[1917]: chan_sip.c:2882 sip_call: Outgoing Call for u302#xfertest [Jul 24 08:58:11] DEBUG[1917]: chan_sip.c:3058 update_call_counter: Updating call counter for outgoing call [Jul 24 08:58:11] DEBUG[1917]: chan_sip.c:2897 sip_call: Our T38 capability (3856), joint T38 capability (3856) [Jul 24 08:58:11] DEBUG[1917]: chan_sip.c:6263 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: False [Jul 24 08:58:11] DEBUG[1917]: chan_sip.c:6264 add_sdp: ** Our prefcodec: 0x4 (ulaw) [Jul 24 08:58:11] DEBUG[1917]: chan_sip.c:6395 add_sdp: -- Done with adding codecs to SDP [Jul 24 08:58:11] DEBUG[1917]: chan_sip.c:6440 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw) [Jul 24 08:58:11] DEBUG[1908]: chan_sip.c:2180 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '530d47ab6493273447148db83a3fcdfb@8.7.177.15' Request 102: Found [Jul 24 08:58:11] DEBUG[1917]: res_musiconhold.c:254 ast_moh_files_next: SIP/ss1tampa.mixnetworks.com-0970c2c0 Opened file 1 '/var/lib/asterisk/sounds/moh/ast_standard/fpm-world-mix' [Jul 24 08:58:11] DEBUG[1917]: rtp.c:2597 ast_rtp_raw_write: Difference is 912, ms is 134 [Jul 24 08:58:11] DEBUG[1917]: channel.c:2147 ast_read_generator_actions: Generator got voice, switching to phase locked mode [Jul 24 08:58:11] DEBUG[1917]: channel.c:2064 ast_settimeout: Scheduling timer at 0 sample intervals [Jul 24 08:58:11] DEBUG[1908]: chan_sip.c:2180 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '530d47ab6493273447148db83a3fcdfb@8.7.177.15' Request 102: Found [Jul 24 08:58:11] DEBUG[1908]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/u302#xfertest-09721690 -- SIP/u302#xfertest-09721690 is ringing [Jul 24 08:58:11] DEBUG[1892]: chan_sip.c:15481 sip_devicestate: Checking device state for peer u302#xfertest [Jul 24 08:58:11] DEBUG[1908]: chan_sip.c:2180 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '530d47ab6493273447148db83a3fcdfb@8.7.177.15' Request 102: Found -- SIP/u302#xfertest-09721690 is ringing [Jul 24 08:58:11] DEBUG[1892]: chan_sip.c:2408 sip_destroy_peer: Destroying SIP peer u302#xfertest [Jul 24 08:58:11] DEBUG[1892]: devicestate.c:287 do_state_change: Changing state for SIP/u302#xfertest - state 1 (Not in use) [Jul 24 08:58:11] DEBUG[1921]: app_queue.c:552 changethread: Device 'SIP/u302#xfertest' changed to state '1' (Not in use) [Jul 24 08:58:12] DEBUG[1908]: chan_sip.c:2059 __sip_autodestruct: Auto destroying SIP dialog '746e4908374d50de24977a7913755c3a@8.7.177.99' [Jul 24 08:58:12] DEBUG[1908]: chan_sip.c:3165 sip_destroy: Destroying SIP dialog 746e4908374d50de24977a7913755c3a@8.7.177.99 Really destroying SIP dialog '746e4908374d50de24977a7913755c3a@8.7.177.99' Method: OPTIONS [Jul 24 08:58:12] DEBUG[1917]: rtp.c:875 ast_rtcp_read: Got RTCP report of 132 bytes [Jul 24 08:58:15] DEBUG[1917]: rtp.c:875 ast_rtcp_read: Got RTCP report of 132 bytes [Jul 24 08:58:18] DEBUG[1917]: rtp.c:875 ast_rtcp_read: Got RTCP report of 132 bytes -- Nobody picked up in 7000 ms [Jul 24 08:58:18] DEBUG[1917]: app_queue.c:1752 store_next: Next is 'SIP/u303#xfertest' with metric 2 [Jul 24 08:58:18] DEBUG[1917]: app_queue.c:2432 try_calling: SIP/ss1tampa.mixnetworks.com-0970c2c0: Nobody answered. [Jul 24 08:58:18] DEBUG[1917]: channel.c:1756 ast_hangup: Hanging up channel 'SIP/u302#xfertest-09721690' [Jul 24 08:58:18] DEBUG[1917]: chan_sip.c:3368 sip_hangup: Hangup call SIP/u302#xfertest-09721690, SIP callid 530d47ab6493273447148db83a3fcdfb@8.7.177.15) [Jul 24 08:58:18] DEBUG[1917]: chan_sip.c:2120 __sip_ack: Acked pending invite 102 [Jul 24 08:58:18] DEBUG[1917]: chan_sip.c:2138 __sip_ack: Stopping retransmission on '530d47ab6493273447148db83a3fcdfb@8.7.177.15' of Request 102: Match Not Found [Jul 24 08:58:18] DEBUG[1917]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/u302#xfertest-09721690 [Jul 24 08:58:18] DEBUG[1892]: chan_sip.c:15481 sip_devicestate: Checking device state for peer u302#xfertest [Jul 24 08:58:18] DEBUG[1908]: chan_sip.c:2138 __sip_ack: Stopping retransmission on '530d47ab6493273447148db83a3fcdfb@8.7.177.15' of Request 102: Match Not Found [Jul 24 08:58:18] DEBUG[1908]: chan_sip.c:2138 __sip_ack: Stopping retransmission on '530d47ab6493273447148db83a3fcdfb@8.7.177.15' of Request 102: Match Found [Jul 24 08:58:18] DEBUG[1908]: chan_sip.c:3058 update_call_counter: Updating call counter for outgoing call [Jul 24 08:58:18] DEBUG[1908]: chan_sip.c:1641 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 530d47ab6493273447148db83a3fcdfb@8.7.177.15 Really destroying SIP dialog '530d47ab6493273447148db83a3fcdfb@8.7.177.15' Method: INVITE [Jul 24 08:58:18] DEBUG[1892]: chan_sip.c:2408 sip_destroy_peer: Destroying SIP peer u302#xfertest [Jul 24 08:58:18] DEBUG[1892]: devicestate.c:287 do_state_change: Changing state for SIP/u302#xfertest - state 1 (Not in use) [Jul 24 08:58:18] DEBUG[1922]: app_queue.c:552 changethread: Device 'SIP/u302#xfertest' changed to state '1' (Not in use) -- Exiting on time-out cycle -- Stopped music on hold on SIP/ss1tampa.mixnetworks.com-0970c2c0 ** We realized we should have called someone else... but we don't... ? ** [Jul 24 08:58:20] DEBUG[1917]: channel.c:2064 ast_settimeout: Scheduling timer at 0 sample intervals [Jul 24 08:58:20] DEBUG[1917]: app_queue.c:1416 leave_queue: Queue 'xfertest_CQ_39' Leave, Channel 'SIP/ss1tampa.mixnetworks.com-0970c2c0' [Jul 24 08:58:20] DEBUG[1917]: pbx.c:1809 pbx_extension_helper: Launching 'Verbose' -- Executing [new@sub-queues:12] Verbose("SIP/ss1tampa.mixnetworks.com-0970c2c0", "1|Queue is FULL or we returned from Queue") in new stack ** Left the Queue and continued on **