DEBUG[1033]: rtp.c:923 ast_rtcp_read: Got RTCP report of 64 bytes [Oct 1 13:02:31] DEBUG[657]: rtp.c:923 ast_rtcp_read: Got RTCP report of 64 bytes [Oct 1 13:02:31] DEBUG[686]: rtp.c:923 ast_rtcp_read: Got RTCP report of 64 bytes [Oct 1 13:02:31] DEBUG[32716]: rtp.c:923 ast_rtcp_read: Got RTCP report of 64 bytes [Oct 1 13:02:31] DEBUG[21537]: chan_sip.c:4761 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Oct 1 13:02:31] DEBUG[21537]: chan_sip.c:2258 __sip_ack: Stopping retransmission on '6f1f236c76fa52b50a1f36740a917374@192.168.30.165' of Request 102: Match Found [Oct 1 13:02:31] DEBUG[32728]: rtp.c:923 ast_rtcp_read: Got RTCP report of 64 bytes Really destroying SIP dialog '6f1f236c76fa52b50a1f36740a917374@192.168.30.165' Method: OPTIONS [Oct 1 13:02:31] DEBUG[1036]: rtp.c:923 ast_rtcp_read: Got RTCP report of 64 bytes [Oct 1 13:02:32] DEBUG[21537]: chan_sip.c:4761 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Oct 1 13:02:32] DEBUG[21537]: chan_sip.c:2258 __sip_ack: Stopping retransmission on '678d9f234d7f2fd44d1adb0d748209b3@192.168.30.165' of Request 102: Match Found [Oct 1 13:02:32] DEBUG[32694]: channel.c:1564 ast_hangup: Hanging up channel 'Local/1625@default-agent-df11,1' [Oct 1 13:02:32] DEBUG[32694]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel Local/1625@default-agent [Oct 1 13:02:32] DEBUG[21436]: chan_local.c:145 local_devicestate: Checking if extension 1625@default-agent exists (devicestate) [Oct 1 13:02:32] DEBUG[21436]: devicestate.c:287 do_state_change: Changing state for Local/1625@default-agent - state 1 (Not in use) [Oct 1 13:02:32] DEBUG[32694]: pbx.c:2392 __ast_pbx_run: Spawn extension (all-hangup,s,13) exited non-zero on 'SIP/siptrunk-b4ca9978' [Oct 1 13:02:32] DEBUG[21525]: app_queue.c:675 handle_statechange: Device 'Local/1625@default-agent' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. == Spawn extension (all-hangup, s, 13) exited non-zero on 'SIP/siptrunk-b4ca9978' [Oct 1 13:02:32] DEBUG[32694]: channel.c:1461 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/siptrunk-b4ca9978' [Oct 1 13:02:32] DEBUG[32694]: channel.c:1564 ast_hangup: Hanging up channel 'SIP/siptrunk-b4ca9978' [Oct 1 13:02:32] DEBUG[32694]: chan_sip.c:3683 sip_hangup: Hangup call SIP/siptrunk-b4ca9978, SIP callid 05a2343771ba72e528908aa674bb7e19@192.168.30.254) [Oct 1 13:02:32] DEBUG[21537]: chan_sip.c:2258 __sip_ack: Stopping retransmission on '05a2343771ba72e528908aa674bb7e19@192.168.30.254' of Request 102: Match Found [Oct 1 13:02:32] DEBUG[32694]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/siptrunk [Oct 1 13:02:32] DEBUG[21436]: chan_sip.c:17064 sip_devicestate: Checking device state for peer siptrunk [Oct 1 13:02:32] DEBUG[21436]: devicestate.c:287 do_state_change: Changing state for SIP/siptrunk - state 1 (Not in use) [Oct 1 13:02:32] DEBUG[21525]: app_queue.c:675 handle_statechange: Device 'SIP/siptrunk' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. Really destroying SIP dialog '678d9f234d7f2fd44d1adb0d748209b3@192.168.30.165' Method: OPTIONS Really destroying SIP dialog '05a2343771ba72e528908aa674bb7e19@192.168.30.254' Method: ACK [Oct 1 13:02:32] DEBUG[21537]: chan_sip.c:4761 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Oct 1 13:02:32] DEBUG[21537]: chan_sip.c:4761 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Oct 1 13:02:32] DEBUG[21537]: chan_sip.c:2258 __sip_ack: Stopping retransmission on '2b7ca30f440080241516a2935001547f@192.168.30.165' of Request 102: Match Found [Oct 1 13:02:32] DEBUG[21537]: chan_sip.c:2258 __sip_ack: Stopping retransmission on '60bff1721f73b8297773b83739ded1f9@192.168.30.165' of Request 102: Match Found [Oct 1 13:02:32] DEBUG[21537]: chan_sip.c:4761 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Oct 1 13:02:32] DEBUG[21537]: chan_sip.c:2258 __sip_ack: Stopping retransmission on '1b4b2a24708773ab4a60d59d7e8d4876@192.168.30.165' of Request 102: Match Found [Oct 1 13:02:32] DEBUG[21537]: chan_sip.c:4761 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Oct 1 13:02:32] DEBUG[21537]: chan_sip.c:2258 __sip_ack: Stopping retransmission on '59b4d25b776248842b1dc0f113e76d77@192.168.30.165' of Request 102: Match Found Really destroying SIP dialog '59b4d25b776248842b1dc0f113e76d77@192.168.30.165' Method: OPTIONS Really destroying SIP dialog '1b4b2a24708773ab4a60d59d7e8d4876@192.168.30.165' Method: OPTIONS Really destroying SIP dialog '60bff1721f73b8297773b83739ded1f9@192.168.30.165' Method: OPTIONS Really destroying SIP dialog '2b7ca30f440080241516a2935001547f@192.168.30.165' Method: OPTIONS [Oct 1 13:02:32] DEBUG[32718]: rtp.c:923 ast_rtcp_read: Got RTCP report of 64 bytes [Oct 1 13:02:32] DEBUG[836]: rtp.c:923 ast_rtcp_read: Got RTCP report of 64 bytes [Oct 1 13:02:32] DEBUG[688]: rtp.c:923 ast_rtcp_read: Got RTCP report of 64 bytes [Oct 1 13:02:32] DEBUG[1055]: rtp.c:923 ast_rtcp_read: Got RTCP report of 64 bytes [Oct 1 13:02:32] DEBUG[891]: rtp.c:923 ast_rtcp_read: Got RTCP report of 64 bytes [Oct 1 13:02:32] DEBUG[1057]: rtp.c:923 ast_rtcp_read: Got RTCP report of 64 bytes [Oct 1 13:02:33] DEBUG[896]: rtp.c:923 ast_rtcp_read: Got RTCP report of 64 bytes [Oct 1 13:02:33] DEBUG[841]: rtp.c:923 ast_rtcp_read: Got RTCP report of 64 bytes [Oct 1 13:02:33] DEBUG[575]: rtp.c:923 ast_rtcp_read: Got RTCP report of 64 bytes [Oct 1 13:02:33] DEBUG[419]: rtp.c:923 ast_rtcp_read: Got RTCP report of 64 bytes [Oct 1 13:02:33] DEBUG[32730]: rtp.c:923 ast_rtcp_read: Got RTCP report of 64 bytes [Oct 1 13:02:34] DEBUG[621]: rtp.c:923 ast_rtcp_read: Got RTCP report of 64 bytes [Oct 1 13:02:34] DEBUG[425]: rtp.c:923 ast_rtcp_read: Got RTCP report of 64 bytes [Oct 1 13:02:34] DEBUG[579]: rtp.c:923 ast_rtcp_read: Got RTCP report of 64 bytes [Oct 1 13:02:35] DEBUG[32628]: rtp.c:923 ast_rtcp_read: Got RTCP report of 64 bytes [Oct 1 13:02:35] DEBUG[634]: rtp.c:923 ast_rtcp_read: Got RTCP report of 64 bytes [Oct 1 13:02:35] DEBUG[655]: rtp.c:923 ast_rtcp_read: Got RTCP report of 64 bytes [Oct 1 13:02:35] DEBUG[32630]: rtp.c:923 ast_rtcp_read: Got RTCP report of 64 bytes [Oct 1 13:02:36] DEBUG[1033]: rtp.c:923 ast_rtcp_read: Got RTCP report of 64 bytes [Oct 1 13:02:36] DEBUG[657]: rtp.c:923 ast_rtcp_read: Got RTCP report of 64 bytes [Oct 1 13:02:36] DEBUG[686]: rtp.c:923 ast_rtcp_read: Got RTCP report of 64 bytes [Oct 1 13:02:36] DEBUG[21537]: chan_sip.c:4761 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Oct 1 13:02:36] DEBUG[21537]: chan_sip.c:2258 __sip_ack: Stopping retransmission on '32aae66a57f53baf5974fe2639880b1c@192.168.30.165' of Request 102: Match Found [Oct 1 13:02:36] DEBUG[32716]: rtp.c:923 ast_rtcp_read: Got RTCP report of 64 bytes Really destroying SIP dialog '32aae66a57f53baf5974fe2639880b1c@192.168.30.165' Method: OPTIONS [Oct 1 13:02:36] DEBUG[21537]: chan_sip.c:4761 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Oct 1 13:02:36] DEBUG[21537]: chan_sip.c:4761 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Oct 1 13:02:36] DEBUG[21537]: chan_sip.c:4761 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Oct 1 13:02:36] DEBUG[21537]: chan_sip.c:2258 __sip_ack: Stopping retransmission on '719c6d5730020b3d28f7cec25a8af8ec@192.168.30.165' of Request 102: Match Found [Oct 1 13:02:36] DEBUG[21537]: chan_sip.c:2258 __sip_ack: Stopping retransmission on '69d2156f1bcdec1d5cae6305715e2132@192.168.30.165' of Request 102: Match Found [Oct 1 13:02:36] DEBUG[21537]: chan_sip.c:4761 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Oct 1 13:02:36] DEBUG[21537]: chan_sip.c:2258 __sip_ack: Stopping retransmission on '174d250c4a9639a214a348117a68a08a@192.168.30.165' of Request 102: Match Found [Oct 1 13:02:36] DEBUG[21537]: chan_sip.c:2258 __sip_ack: Stopping retransmission on '04ba52b13e9fed5119562d683c1ad266@192.168.30.165' of Request 102: Match Found Really destroying SIP dialog '04ba52b13e9fed5119562d683c1ad266@192.168.30.165' Method: OPTIONS Really destroying SIP dialog '174d250c4a9639a214a348117a68a08a@192.168.30.165' Method: OPTIONS Really destroying SIP dialog '69d2156f1bcdec1d5cae6305715e2132@192.168.30.165' Method: OPTIONS Really destroying SIP dialog '719c6d5730020b3d28f7cec25a8af8ec@192.168.30.165' Method: OPTIONS [Oct 1 13:02:36] DEBUG[21537]: chan_sip.c:4761 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Oct 1 13:02:36] DEBUG[21537]: chan_sip.c:2258 __sip_ack: Stopping retransmission on '7d4795826d0d911d4f4623fe1749fd5e@192.168.30.165' of Request 102: Match Found [Oct 1 13:02:36] DEBUG[21537]: chan_sip.c:4761 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Oct 1 13:02:36] DEBUG[32728]: rtp.c:923 ast_rtcp_read: Got RTCP report of 64 bytes [Oct 1 13:02:36] DEBUG[21537]: chan_sip.c:2258 __sip_ack: Stopping retransmission on '1531f46a2c9f5b0561bbeaf77e68d5f4@192.168.30.165' of Request 102: Match Found [Oct 1 13:02:36] DEBUG[1036]: rtp.c:923 ast_rtcp_read: Got RTCP report of 64 bytes [Oct 1 13:02:36] DEBUG[21537]: chan_sip.c:4761 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Oct 1 13:02:36] DEBUG[21537]: chan_sip.c:4761 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Oct 1 13:02:36] DEBUG[21537]: chan_sip.c:2258 __sip_ack: Stopping retransmission on '2ba98e045d153e331487530b7074c9c1@192.168.30.165' of Request 102: Match Found [Oct 1 13:02:36] DEBUG[21537]: chan_sip.c:2258 __sip_ack: Stopping retransmission on '38a2c8325ec269b36d67bebf3944514e@192.168.30.165' of Request 102: Match Found Really destroying SIP dialog '38a2c8325ec269b36d67bebf3944514e@192.168.30.165' Method: OPTIONS Really destroying SIP dialog '2ba98e045d153e331487530b7074c9c1@192.168.30.165' Method: OPTIONS Really destroying SIP dialog '1531f46a2c9f5b0561bbeaf77e68d5f4@192.168.30.165' Method: OPTIONS Really destroying SIP dialog '7d4795826d0d911d4f4623fe1749fd5e@192.168.30.165' Method: OPTIONS [Oct 1 13:02:37] DEBUG[32718]: rtp.c:923 ast_rtcp_read: Got RTCP report of 64 bytes [Oct 1 13:02:37] DEBUG[836]: rtp.c:923 ast_rtcp_read: Got RTCP report of 64 bytes [Oct 1 13:02:37] DEBUG[688]: rtp.c:923 ast_rtcp_read: Got RTCP report of 64 bytes [Oct 1 13:02:37] DEBUG[21537]: chan_sip.c:2881 do_setnat: Setting NAT on RTP to Off [Oct 1 13:02:37] DEBUG[21537]: chan_sip.c:2886 do_setnat: Setting NAT on VRTP to Off [Oct 1 13:02:37] DEBUG[21537]: chan_sip.c:4761 sip_alloc: Allocating new SIP dialog for 403172b6584001bf2ad549f025c28e37@192.168.30.254 - INVITE (With RTP) [Oct 1 13:02:37] DEBUG[21537]: chan_sip.c:2881 do_setnat: Setting NAT on RTP to Off [Oct 1 13:02:37] DEBUG[21537]: chan_sip.c:2886 do_setnat: Setting NAT on VRTP to Off [Oct 1 13:02:37] DEBUG[21537]: chan_sip.c:2258 __sip_ack: Stopping retransmission on '403172b6584001bf2ad549f025c28e37@192.168.30.254' of Response 102: Match Found [Oct 1 13:02:37] DEBUG[21537]: chan_sip.c:2881 do_setnat: Setting NAT on RTP to Off [Oct 1 13:02:37] DEBUG[21537]: chan_sip.c:2886 do_setnat: Setting NAT on VRTP to Off [Oct 1 13:02:37] DEBUG[21537]: chan_sip.c:5778 process_sdp: T38 state changed to 0 on channel [Oct 1 13:02:37] DEBUG[21537]: chan_sip.c:5858 process_sdp: We're settling with these formats: 0x4 (ulaw) [Oct 1 13:02:37] DEBUG[21537]: chan_sip.c:14930 handle_request_invite: Checking SIP call limits for device siptrunk [Oct 1 13:02:37] DEBUG[21537]: chan_sip.c:3366 update_call_counter: Updating call counter for incoming call [Oct 1 13:02:37] DEBUG[21537]: chan_sip.c:4228 sip_new: *** Our native formats are 0x4 (ulaw) [Oct 1 13:02:37] DEBUG[21537]: chan_sip.c:4229 sip_new: *** Joint capabilities are 0x4 (ulaw) [Oct 1 13:02:37] DEBUG[21537]: chan_sip.c:4230 sip_new: *** Our capabilities are 0x6 (gsm|ulaw) [Oct 1 13:02:37] DEBUG[21537]: chan_sip.c:4231 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Oct 1 13:02:37] DEBUG[21537]: chan_sip.c:4254 sip_new: This channel will not be able to handle video. [Oct 1 13:02:37] DEBUG[21537]: chan_sip.c:8785 build_route: build_route: Contact hop: [Oct 1 13:02:37] DEBUG[21537]: chan_sip.c:15029 handle_request_invite: SIP/siptrunk-b4837b88: New call is still down.... Trying... [Oct 1 13:02:37] DEBUG[21537]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/siptrunk [Oct 1 13:02:37] DEBUG[21436]: chan_sip.c:17064 sip_devicestate: Checking device state for peer siptrunk [Oct 1 13:02:37] DEBUG[21436]: devicestate.c:287 do_state_change: Changing state for SIP/siptrunk - state 1 (Not in use) [Oct 1 13:02:37] DEBUG[21525]: app_queue.c:675 handle_statechange: Device 'SIP/siptrunk' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Oct 1 13:02:37] DEBUG[1055]: rtp.c:923 ast_rtcp_read: Got RTCP report of 64 bytes [Oct 1 13:02:37] DEBUG[1090]: pbx.c:1843 pbx_extension_helper: Launching 'Answer' -- Executing [5000@customer-siptrunk-incoming:1] Answer("SIP/siptrunk-b4837b88", "") in new stack [Oct 1 13:02:37] DEBUG[1090]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/siptrunk [Oct 1 13:02:37] DEBUG[21436]: chan_sip.c:17064 sip_devicestate: Checking device state for peer siptrunk [Oct 1 13:02:37] DEBUG[21436]: devicestate.c:287 do_state_change: Changing state for SIP/siptrunk - state 1 (Not in use) [Oct 1 13:02:37] DEBUG[21525]: app_queue.c:675 handle_statechange: Device 'SIP/siptrunk' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Oct 1 13:02:37] DEBUG[1090]: chan_sip.c:3856 sip_answer: SIP answering channel: SIP/siptrunk-b4837b88 [Oct 1 13:02:37] DEBUG[1090]: chan_sip.c:7112 transmit_response_with_sdp: Setting framing from config on incoming call [Oct 1 13:02:37] DEBUG[1090]: chan_sip.c:6827 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True [Oct 1 13:02:37] DEBUG[1090]: chan_sip.c:6828 add_sdp: ** Our prefcodec: 0x0 (nothing) [Oct 1 13:02:37] DEBUG[1090]: chan_sip.c:6945 add_sdp: -- Done with adding codecs to SDP [Oct 1 13:02:37] DEBUG[1090]: chan_sip.c:7054 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw) [Oct 1 13:02:37] DEBUG[1090]: pbx.c:1843 pbx_extension_helper: Launching 'Set' [Oct 1 13:02:37] DEBUG[21537]: chan_sip.c:2258 __sip_ack: Stopping retransmission on '403172b6584001bf2ad549f025c28e37@192.168.30.254' of Response 103: Match Found -- Executing [5000@customer-siptrunk-incoming:2] Set("SIP/siptrunk-b4837b88", "CHANNEL(musicclass)=default") in new stack [Oct 1 13:02:37] DEBUG[1090]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '1022' [Oct 1 13:02:37] DEBUG[1090]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '1022' [Oct 1 13:02:37] DEBUG[1090]: pbx.c:1843 pbx_extension_helper: Launching 'NoOp' -- Executing [5000@customer-siptrunk-incoming:3] NoOp("SIP/siptrunk-b4837b88", ""INCOMING CALL FROM CALLER ID: 1022 (1022)"") in new stack [Oct 1 13:02:37] DEBUG[1090]: pbx.c:1843 pbx_extension_helper: Launching 'Set' -- Executing [5000@customer-siptrunk-incoming:4] Set("SIP/siptrunk-b4837b88", "__INCOMING_DNIS=5000") in new stack [Oct 1 13:02:37] DEBUG[1090]: pbx.c:1843 pbx_extension_helper: Launching 'Set' [Oct 1 13:02:37] DEBUG[891]: rtp.c:923 ast_rtcp_read: Got RTCP report of 64 bytes -- Executing [5000@customer-siptrunk-incoming:5] Set("SIP/siptrunk-b4837b88", "CALLERID(dnid)=5000") in new stack [Oct 1 13:02:37] DEBUG[1090]: pbx.c:1843 pbx_extension_helper: Launching 'Set' -- Executing [5000@customer-siptrunk-incoming:6] Set("SIP/siptrunk-b4837b88", "CDR(userfield)=5000") in new stack [Oct 1 13:02:37] DEBUG[1090]: pbx.c:1843 pbx_extension_helper: Launching 'Goto' -- Executing [5000@customer-siptrunk-incoming:7] Goto("SIP/siptrunk-b4837b88", "10") in new stack -- Goto (customer-siptrunk-incoming,5000,10) [Oct 1 13:02:37] DEBUG[1090]: pbx.c:1843 pbx_extension_helper: Launching 'AGI' -- Executing [5000@customer-siptrunk-incoming:10] AGI("SIP/siptrunk-b4837b88", "/var/www/scopserv/telephony/scripts/agi/fixcidname.php") in new stack -- Launched AGI Script /var/www/scopserv/telephony/scripts/agi/fixcidname.php [Oct 1 13:02:37] DEBUG[1057]: rtp.c:923 ast_rtcp_read: Got RTCP report of 64 bytes -- AGI Script /var/www/scopserv/telephony/scripts/agi/fixcidname.php completed, returning 0 [Oct 1 13:02:38] DEBUG[1090]: pbx.c:1843 pbx_extension_helper: Launching 'Set' -- Executing [5000@customer-siptrunk-incoming:11] Set("SIP/siptrunk-b4837b88", "GROUP(siptrunk)=INCOMING") in new stack [Oct 1 13:02:38] DEBUG[1090]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '13' [Oct 1 13:02:38] DEBUG[1090]: pbx.c:1759 pbx_substitute_variables_helper_full: Expression result is '0' [Oct 1 13:02:38] DEBUG[1090]: pbx.c:1843 pbx_extension_helper: Launching 'GotoIf' -- Executing [5000@customer-siptrunk-incoming:12] GotoIf("SIP/siptrunk-b4837b88", "0?500") in new stack [Oct 1 13:02:38] DEBUG[1090]: pbx.c:6067 pbx_builtin_gotoif: Not taking any branch [Oct 1 13:02:38] DEBUG[1090]: pbx.c:1843 pbx_extension_helper: Launching 'Set' -- Executing [5000@customer-siptrunk-incoming:13] Set("SIP/siptrunk-b4837b88", "FAXNUMBER=5000") in new stack [Oct 1 13:02:38] DEBUG[1090]: pbx.c:1843 pbx_extension_helper: Launching 'Set' -- Executing [5000@customer-siptrunk-incoming:14] Set("SIP/siptrunk-b4837b88", "__INCOMINGLINE=1") in new stack [Oct 1 13:02:38] DEBUG[1090]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '1022' [Oct 1 13:02:38] DEBUG[1090]: pbx.c:1759 pbx_substitute_variables_helper_full: Expression result is '0' [Oct 1 13:02:38] DEBUG[1090]: pbx.c:1843 pbx_extension_helper: Launching 'GotoIf' -- Executing [5000@customer-siptrunk-incoming:15] GotoIf("SIP/siptrunk-b4837b88", "0?16:17") in new stack -- Goto (customer-siptrunk-incoming,5000,17) [Oct 1 13:02:38] DEBUG[1090]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '1022' [Oct 1 13:02:38] DEBUG[1090]: pbx.c:1759 pbx_substitute_variables_helper_full: Expression result is '0' [Oct 1 13:02:38] DEBUG[1090]: pbx.c:1843 pbx_extension_helper: Launching 'GotoIf' -- Executing [5000@customer-siptrunk-incoming:17] GotoIf("SIP/siptrunk-b4837b88", "0?18:19") in new stack -- Goto (customer-siptrunk-incoming,5000,19) [Oct 1 13:02:38] DEBUG[1090]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '1022' [Oct 1 13:02:38] DEBUG[1090]: pbx.c:1759 pbx_substitute_variables_helper_full: Expression result is '0' [Oct 1 13:02:38] DEBUG[1090]: pbx.c:1843 pbx_extension_helper: Launching 'GotoIf' -- Executing [5000@customer-siptrunk-incoming:19] GotoIf("SIP/siptrunk-b4837b88", "0?20:21") in new stack -- Goto (customer-siptrunk-incoming,5000,21) [Oct 1 13:02:38] DEBUG[1090]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '1022' [Oct 1 13:02:38] DEBUG[1090]: pbx.c:1759 pbx_substitute_variables_helper_full: Expression result is '0' [Oct 1 13:02:38] DEBUG[1090]: pbx.c:1843 pbx_extension_helper: Launching 'GotoIf' -- Executing [5000@customer-siptrunk-incoming:21] GotoIf("SIP/siptrunk-b4837b88", "0?22:23") in new stack -- Goto (customer-siptrunk-incoming,5000,23) [Oct 1 13:02:38] DEBUG[1090]: pbx.c:1843 pbx_extension_helper: Launching 'Set' -- Executing [5000@customer-siptrunk-incoming:23] Set("SIP/siptrunk-b4837b88", "CHANNEL(language)=en") in new stack [Oct 1 13:02:38] DEBUG[1090]: pbx.c:1843 pbx_extension_helper: Launching 'Set' -- Executing [5000@customer-siptrunk-incoming:24] Set("SIP/siptrunk-b4837b88", "QUEUE_PRIO=0") in new stack [Oct 1 13:02:38] DEBUG[1090]: pbx.c:1843 pbx_extension_helper: Launching 'Gosub' -- Executing [5000@customer-siptrunk-incoming:25] Gosub("SIP/siptrunk-b4837b88", "default-application-acd-queue-new-english|s|1") in new stack [Oct 1 13:02:38] DEBUG[1090]: pbx.c:1843 pbx_extension_helper: Launching 'NoOp' -- Executing [s@default-application-acd-queue-new-english:1] NoOp("SIP/siptrunk-b4837b88", ""=== START QUEUE (default-queue-new-english) ==="") in new stack [Oct 1 13:02:38] DEBUG[1090]: pbx.c:1843 pbx_extension_helper: Launching 'Set' -- Executing [s@default-application-acd-queue-new-english:2] Set("SIP/siptrunk-b4837b88", "__QUEUENAME=default-queue-new-english") in new stack [Oct 1 13:02:38] DEBUG[1090]: pbx.c:1759 pbx_substitute_variables_helper_full: Expression result is '0' [Oct 1 13:02:38] DEBUG[1090]: pbx.c:1759 pbx_substitute_variables_helper_full: Expression result is '6' [Oct 1 13:02:38] DEBUG[1090]: pbx.c:1843 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@default-application-acd-queue-new-english:3] GotoIf("SIP/siptrunk-b4837b88", "0?6") in new stack [Oct 1 13:02:38] DEBUG[1090]: pbx.c:6067 pbx_builtin_gotoif: Not taking any branch [Oct 1 13:02:38] DEBUG[1090]: pbx.c:1843 pbx_extension_helper: Launching 'Set' -- Executing [s@default-application-acd-queue-new-english:4] Set("SIP/siptrunk-b4837b88", "MONITOR_FILENAME=1254416557.32828") in new stack [Oct 1 13:02:38] DEBUG[1090]: pbx.c:1759 pbx_substitute_variables_helper_full: Expression result is '7' [Oct 1 13:02:38] DEBUG[1090]: pbx.c:1843 pbx_extension_helper: Launching 'Goto' -- Executing [s@default-application-acd-queue-new-english:5] Goto("SIP/siptrunk-b4837b88", "7") in new stack -- Goto (default-application-acd-queue-new-english,s,7) [Oct 1 13:02:38] DEBUG[1090]: pbx.c:1843 pbx_extension_helper: Launching 'Set' -- Executing [s@default-application-acd-queue-new-english:7] Set("SIP/siptrunk-b4837b88", "TIMEOUT(digit)=1") in new stack -- Digit timeout set to 1 [Oct 1 13:02:38] DEBUG[1090]: pbx.c:1843 pbx_extension_helper: Launching 'Set' -- Executing [s@default-application-acd-queue-new-english:8] Set("SIP/siptrunk-b4837b88", "TIMEOUT(response)=1") in new stack -- Response timeout set to 1 [Oct 1 13:02:38] DEBUG[1090]: pbx.c:1843 pbx_extension_helper: Launching 'Set' -- Executing [s@default-application-acd-queue-new-english:9] Set("SIP/siptrunk-b4837b88", "__ACD_TO_OUTGOING=1") in new stack [Oct 1 13:02:38] DEBUG[1090]: pbx.c:1843 pbx_extension_helper: Launching 'Set' -- Executing [s@default-application-acd-queue-new-english:10] Set("SIP/siptrunk-b4837b88", "CHANNEL(musicclass)=default") in new stack [Oct 1 13:02:38] DEBUG[1090]: pbx.c:1843 pbx_extension_helper: Launching 'Set' -- Executing [s@default-application-acd-queue-new-english:11] Set("SIP/siptrunk-b4837b88", "__ALLOW_TRANSFER=twk") in new stack [Oct 1 13:02:38] DEBUG[1090]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '1022' [Oct 1 13:02:38] DEBUG[1090]: pbx.c:1843 pbx_extension_helper: Launching 'Set' -- Executing [s@default-application-acd-queue-new-english:12] Set("SIP/siptrunk-b4837b88", "CALLERID(name)=queue-E:1022") in new stack [Oct 1 13:02:38] DEBUG[1090]: pbx.c:1843 pbx_extension_helper: Launching 'Queue' -- Executing [s@default-application-acd-queue-new-english:13] Queue("SIP/siptrunk-b4837b88", "default-queue-new-english|tH|||60|") in new stack [Oct 1 13:02:38] DEBUG[1090]: app_queue.c:3985 queue_exec: SIP/siptrunk-b4837b88: Got priority 0 from ${QUEUE_PRIO}. [Oct 1 13:02:38] DEBUG[1090]: app_queue.c:4017 queue_exec: queue: default-queue-new-english, options: tH, url: , announce: , expires: 1254416618, priority: 0 [Oct 1 13:02:38] DEBUG[1090]: app_queue.c:1352 update_realtime_members: Queue default-queue-new-english has no realtime members defined. No need for update [Oct 1 13:02:38] DEBUG[1090]: app_queue.c:1497 join_queue: Queue 'default-queue-new-english' Join, Channel 'SIP/siptrunk-b4837b88', Position '1' -- Started music on hold, class 'default', on SIP/siptrunk-b4837b88 [Oct 1 13:02:38] DEBUG[1090]: app_queue.c:2465 is_our_turn: There are 6 available members. [Oct 1 13:02:38] DEBUG[1090]: app_queue.c:2479 is_our_turn: It's our turn (SIP/siptrunk-b4837b88). [Oct 1 13:02:38] DEBUG[1090]: app_queue.c:2862 try_calling: SIP/siptrunk-b4837b88 is trying to call a queue member. [Oct 1 13:02:38] DEBUG[1090]: app_queue.c:2070 ring_one: Trying 'Local/1630@default-agent/n' with metric 2 [Oct 1 13:02:38] DEBUG[1090]: channel.c:3729 ast_channel_inherit_variables: Copying hard-transferable variable ALLOW_TRANSFER. [Oct 1 13:02:38] DEBUG[1090]: channel.c:3729 ast_channel_inherit_variables: Copying hard-transferable variable ACD_TO_OUTGOING. [Oct 1 13:02:38] DEBUG[1090]: channel.c:3734 ast_channel_inherit_variables: Not copying variable MONITOR_FILENAME. [Oct 1 13:02:38] DEBUG[1090]: channel.c:3729 ast_channel_inherit_variables: Copying hard-transferable variable QUEUENAME. [Oct 1 13:02:38] DEBUG[1090]: channel.c:3734 ast_channel_inherit_variables: Not copying variable ~GOSUB~STACK~. [Oct 1 13:02:38] DEBUG[1090]: channel.c:3734 ast_channel_inherit_variables: Not copying variable QUEUE_PRIO. [Oct 1 13:02:38] DEBUG[1090]: channel.c:3729 ast_channel_inherit_variables: Copying hard-transferable variable INCOMINGLINE. [Oct 1 13:02:38] DEBUG[1090]: channel.c:3734 ast_channel_inherit_variables: Not copying variable FAXNUMBER. [Oct 1 13:02:38] DEBUG[1090]: channel.c:3734 ast_channel_inherit_variables: Not copying variable AGISTATUS. [Oct 1 13:02:38] DEBUG[1090]: channel.c:3729 ast_channel_inherit_variables: Copying hard-transferable variable INCOMING_DNIS. [Oct 1 13:02:38] DEBUG[1090]: channel.c:3734 ast_channel_inherit_variables: Not copying variable SIPCALLID. [Oct 1 13:02:38] DEBUG[1090]: channel.c:3734 ast_channel_inherit_variables: Not copying variable SIPUSERAGENT. [Oct 1 13:02:38] DEBUG[1090]: channel.c:3734 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [Oct 1 13:02:38] DEBUG[1090]: channel.c:3734 ast_channel_inherit_variables: Not copying variable SIPURI. -- Called Local/1630@default-agent/n [Oct 1 13:02:38] DEBUG[1090]: chan_sip.c:17064 sip_devicestate: Checking device state for peer 1630 [Oct 1 13:02:38] DEBUG[1090]: res_musiconhold.c:261 ast_moh_files_next: SIP/siptrunk-b4837b88 Opened file 5 '/var/lib/asterisk/moh//macroform-cold_day' [Oct 1 13:02:38] DEBUG[1090]: rtp.c:2885 ast_rtp_write: Ooh, format changed from unknown to ulaw [Oct 1 13:02:38] DEBUG[1090]: rtp.c:2902 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160 [Oct 1 13:02:38] DEBUG[1093]: pbx.c:1843 pbx_extension_helper: Launching 'NoCDR' -- Executing [1630@default-agent:1] NoCDR("Local/1630@default-agent-a62e,2", "") in new stack [Oct 1 13:02:38] DEBUG[1093]: db.c:196 ast_db_get: Unable to find key '1630/DoNotDisturb' in family 'default' [Oct 1 13:02:38] DEBUG[1093]: func_db.c:70 function_db_read: DB: default/1630/DoNotDisturb not found in database. [Oct 1 13:02:38] DEBUG[1093]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '' [Oct 1 13:02:38] DEBUG[1093]: pbx.c:1843 pbx_extension_helper: Launching 'Set' -- Executing [1630@default-agent:2] Set("Local/1630@default-agent-a62e,2", "DND=") in new stack [Oct 1 13:02:38] DEBUG[1093]: pbx.c:1759 pbx_substitute_variables_helper_full: Expression result is '0' [Oct 1 13:02:38] DEBUG[1093]: pbx.c:1843 pbx_extension_helper: Launching 'GotoIf' -- Executing [1630@default-agent:3] GotoIf("Local/1630@default-agent-a62e,2", "0?30") in new stack [Oct 1 13:02:38] DEBUG[1093]: pbx.c:6067 pbx_builtin_gotoif: Not taking any branch [Oct 1 13:02:38] DEBUG[1093]: db.c:196 ast_db_get: Unable to find key '1630/OutOffice' in family 'default' [Oct 1 13:02:38] DEBUG[1093]: func_db.c:70 function_db_read: DB: default/1630/OutOffice not found in database. [Oct 1 13:02:38] DEBUG[1093]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '' [Oct 1 13:02:38] DEBUG[1093]: pbx.c:1843 pbx_extension_helper: Launching 'Set' -- Executing [1630@default-agent:4] Set("Local/1630@default-agent-a62e,2", "OutOffice=") in new stack [Oct 1 13:02:38] DEBUG[1093]: pbx.c:1759 pbx_substitute_variables_helper_full: Expression result is '0' [Oct 1 13:02:38] DEBUG[1093]: pbx.c:1843 pbx_extension_helper: Launching 'GotoIf' -- Executing [1630@default-agent:5] GotoIf("Local/1630@default-agent-a62e,2", "0?30") in new stack [Oct 1 13:02:38] DEBUG[1093]: pbx.c:6067 pbx_builtin_gotoif: Not taking any branch [Oct 1 13:02:38] DEBUG[1093]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '0' [Oct 1 13:02:38] DEBUG[1093]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '0' [Oct 1 13:02:38] DEBUG[1093]: pbx.c:1759 pbx_substitute_variables_helper_full: Expression result is '0' [Oct 1 13:02:38] DEBUG[1093]: pbx.c:1843 pbx_extension_helper: Launching 'Set' -- Executing [1630@default-agent:6] Set("Local/1630@default-agent-a62e,2", "GROUPCOUNT=0") in new stack [Oct 1 13:02:38] DEBUG[1093]: db.c:196 ast_db_get: Unable to find key 'agent//maxcalls' in family 'default' [Oct 1 13:02:38] DEBUG[1093]: func_db.c:70 function_db_read: DB: default/agent//maxcalls not found in database. [Oct 1 13:02:38] DEBUG[1093]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '' [Oct 1 13:02:38] DEBUG[1093]: pbx.c:1843 pbx_extension_helper: Launching 'Set' -- Executing [1630@default-agent:7] Set("Local/1630@default-agent-a62e,2", "AGENTMAXCALL=") in new stack [Oct 1 13:02:38] DEBUG[1093]: pbx.c:1759 pbx_substitute_variables_helper_full: Expression result is '1' [Oct 1 13:02:38] DEBUG[1093]: pbx.c:1759 pbx_substitute_variables_helper_full: Expression result is '9' [Oct 1 13:02:38] DEBUG[1093]: pbx.c:1759 pbx_substitute_variables_helper_full: Expression result is '12' [Oct 1 13:02:38] DEBUG[1093]: pbx.c:1843 pbx_extension_helper: Launching 'GotoIf' -- Executing [1630@default-agent:8] GotoIf("Local/1630@default-agent-a62e,2", "1?9:12") in new stack -- Goto (default-agent,1630,9) [Oct 1 13:02:38] DEBUG[1093]: pbx.c:1843 pbx_extension_helper: Launching 'Set' -- Executing [1630@default-agent:9] Set("Local/1630@default-agent-a62e,2", "AGENTMAXCALL=") in new stack [Oct 1 13:02:38] DEBUG[1093]: pbx.c:1759 pbx_substitute_variables_helper_full: Expression result is '1' [Oct 1 13:02:38] DEBUG[1093]: pbx.c:1759 pbx_substitute_variables_helper_full: Expression result is '11' [Oct 1 13:02:38] DEBUG[1093]: pbx.c:1759 pbx_substitute_variables_helper_full: Expression result is '12' [Oct 1 13:02:38] DEBUG[1093]: pbx.c:1843 pbx_extension_helper: Launching 'GotoIf' -- Executing [1630@default-agent:10] GotoIf("Local/1630@default-agent-a62e,2", "1?11:12") in new stack -- Goto (default-agent,1630,11) [Oct 1 13:02:38] DEBUG[1093]: pbx.c:1843 pbx_extension_helper: Launching 'Set' -- Executing [1630@default-agent:11] Set("Local/1630@default-agent-a62e,2", "AGENTMAXCALL=1") in new stack [Oct 1 13:02:38] DEBUG[1093]: pbx.c:1759 pbx_substitute_variables_helper_full: Expression result is '0' [Oct 1 13:02:38] DEBUG[1093]: pbx.c:1843 pbx_extension_helper: Launching 'GotoIf' -- Executing [1630@default-agent:12] GotoIf("Local/1630@default-agent-a62e,2", "0?30") in new stack [Oct 1 13:02:38] DEBUG[1093]: pbx.c:6067 pbx_builtin_gotoif: Not taking any branch [Oct 1 13:02:38] DEBUG[1093]: pbx.c:1759 pbx_substitute_variables_helper_full: Expression result is '1' [Oct 1 13:02:38] DEBUG[1093]: pbx.c:1759 pbx_substitute_variables_helper_full: Expression result is '16' [Oct 1 13:02:38] DEBUG[1093]: pbx.c:1843 pbx_extension_helper: Launching 'GotoIf' -- Executing [1630@default-agent:13] GotoIf("Local/1630@default-agent-a62e,2", "1?16") in new stack -- Goto (default-agent,1630,16) [Oct 1 13:02:38] DEBUG[1093]: pbx.c:1843 pbx_extension_helper: Launching 'Set' -- Executing [1630@default-agent:16] Set("Local/1630@default-agent-a62e,2", "OUTBOUND_GROUP_ONCE=1630@INCOMING") in new stack [Oct 1 13:02:38] DEBUG[1093]: pbx.c:1843 pbx_extension_helper: Launching 'Set' -- Executing [1630@default-agent:17] Set("Local/1630@default-agent-a62e,2", "DB(default/wrapup/1630/lastcall)=1254416558.32830") in new stack [Oct 1 13:02:38] DEBUG[1093]: db.c:196 ast_db_get: Unable to find key 'agent//monitor' in family 'default' [Oct 1 13:02:38] DEBUG[1093]: func_db.c:70 function_db_read: DB: default/agent//monitor not found in database. [Oct 1 13:02:38] DEBUG[1093]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '' [Oct 1 13:02:38] DEBUG[1093]: pbx.c:1843 pbx_extension_helper: Launching 'Set' -- Executing [1630@default-agent:18] Set("Local/1630@default-agent-a62e,2", "AGENTMONITOR=") in new stack [Oct 1 13:02:38] DEBUG[1093]: pbx.c:1759 pbx_substitute_variables_helper_full: Expression result is '1' [Oct 1 13:02:38] DEBUG[1093]: pbx.c:1759 pbx_substitute_variables_helper_full: Expression result is '23' [Oct 1 13:02:38] DEBUG[1093]: pbx.c:1843 pbx_extension_helper: Launching 'GotoIf' -- Executing [1630@default-agent:19] GotoIf("Local/1630@default-agent-a62e,2", "1?23") in new stack -- Goto (default-agent,1630,23) [Oct 1 13:02:38] DEBUG[1093]: pbx.c:1843 pbx_extension_helper: Launching 'Goto' -- Executing [1630@default-agent:23] Goto("Local/1630@default-agent-a62e,2", "default-local-devices|1630|1") in new stack -- Goto (default-local-devices,1630,1) [Oct 1 13:02:38] DEBUG[1093]: pbx.c:1843 pbx_extension_helper: Launching 'Set' -- Executing [1630@default-local-devices:1] Set("Local/1630@default-agent-a62e,2", "__PICKUPMARK=1630") in new stack [Oct 1 13:02:38] DEBUG[1093]: pbx.c:1843 pbx_extension_helper: Launching 'Set' -- Executing [1630@default-local-devices:2] Set("Local/1630@default-agent-a62e,2", "DB(default/wrapup/1630/lastcall)=1254416558.32830") in new stack [Oct 1 13:02:38] DEBUG[1093]: pbx.c:1843 pbx_extension_helper: Launching 'Dial' -- Executing [1630@default-local-devices:3] Dial("Local/1630@default-agent-a62e,2", "SIP/1630||twk") in new stack [Oct 1 13:02:38] DEBUG[1093]: chan_sip.c:17140 sip_request_call: Asked to create a SIP channel with formats: 0x4 (ulaw) [Oct 1 13:02:38] DEBUG[1093]: chan_sip.c:4761 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Oct 1 13:02:38] DEBUG[1093]: chan_sip.c:2881 do_setnat: Setting NAT on RTP to Off [Oct 1 13:02:38] DEBUG[1093]: chan_sip.c:4228 sip_new: *** Our native formats are 0x4 (ulaw) [Oct 1 13:02:38] DEBUG[1093]: chan_sip.c:4229 sip_new: *** Joint capabilities are 0x0 (nothing) [Oct 1 13:02:38] DEBUG[1093]: chan_sip.c:4230 sip_new: *** Our capabilities are 0x4 (ulaw) [Oct 1 13:02:38] DEBUG[1093]: chan_sip.c:4231 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Oct 1 13:02:38] DEBUG[1093]: chan_sip.c:4233 sip_new: *** Our preferred formats from the incoming channel are 0x4 (ulaw) [Oct 1 13:02:38] DEBUG[1093]: chan_sip.c:4254 sip_new: This channel will not be able to handle video. [Oct 1 13:02:38] DEBUG[1093]: rtp.c:1648 ast_rtp_make_compatible: Channel 'Local/1630@default-agent-a62e,2' has no RTP, not doing anything [Oct 1 13:02:38] DEBUG[1093]: channel.c:3734 ast_channel_inherit_variables: Not copying variable DIALEDTIME. [Oct 1 13:02:38] DEBUG[1093]: channel.c:3734 ast_channel_inherit_variables: Not copying variable ANSWEREDTIME. [Oct 1 13:02:38] DEBUG[1093]: channel.c:3734 ast_channel_inherit_variables: Not copying variable DIALEDPEERNAME. [Oct 1 13:02:38] DEBUG[1093]: channel.c:3734 ast_channel_inherit_variables: Not copying variable DIALEDPEERNUMBER. [Oct 1 13:02:38] DEBUG[1093]: channel.c:3734 ast_channel_inherit_variables: Not copying variable DIALSTATUS. [Oct 1 13:02:38] DEBUG[1093]: channel.c:3729 ast_channel_inherit_variables: Copying hard-transferable variable PICKUPMARK. [Oct 1 13:02:38] DEBUG[1093]: channel.c:3734 ast_channel_inherit_variables: Not copying variable AGENTMONITOR. [Oct 1 13:02:38] DEBUG[1093]: channel.c:3734 ast_channel_inherit_variables: Not copying variable AGENTMAXCALL. [Oct 1 13:02:38] DEBUG[1093]: channel.c:3734 ast_channel_inherit_variables: Not copying variable GROUPCOUNT. [Oct 1 13:02:38] DEBUG[1093]: channel.c:3734 ast_channel_inherit_variables: Not copying variable OutOffice. [Oct 1 13:02:38] DEBUG[1093]: channel.c:3734 ast_channel_inherit_variables: Not copying variable DND. [Oct 1 13:02:38] DEBUG[1093]: channel.c:3729 ast_channel_inherit_variables: Copying hard-transferable variable ALLOW_TRANSFER. [Oct 1 13:02:38] DEBUG[1093]: channel.c:3729 ast_channel_inherit_variables: Copying hard-transferable variable ACD_TO_OUTGOING. [Oct 1 13:02:38] DEBUG[1093]: channel.c:3729 ast_channel_inherit_variables: Copying hard-transferable variable QUEUENAME. [Oct 1 13:02:38] DEBUG[1093]: channel.c:3729 ast_channel_inherit_variables: Copying hard-transferable variable INCOMINGLINE. [Oct 1 13:02:38] DEBUG[1093]: channel.c:3729 ast_channel_inherit_variables: Copying hard-transferable variable INCOMING_DNIS. [Oct 1 13:02:38] DEBUG[1093]: chan_sip.c:3159 sip_call: Outgoing Call for 1630 [Oct 1 13:02:38] DEBUG[1093]: chan_sip.c:3366 update_call_counter: Updating call counter for outgoing call [Oct 1 13:02:38] DEBUG[1093]: chan_sip.c:3443 update_call_counter: Call to peer '1630' is 1 out of 16 [Oct 1 13:02:38] DEBUG[1093]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/1630 [Oct 1 13:02:38] DEBUG[1093]: chan_sip.c:3174 sip_call: Our T38 capability (0), joint T38 capability (0) [Oct 1 13:02:38] DEBUG[21436]: chan_sip.c:17064 sip_devicestate: Checking device state for peer 1630 [Oct 1 13:02:38] DEBUG[21436]: devicestate.c:287 do_state_change: Changing state for SIP/1630 - state 6 (Ringing) [Oct 1 13:02:38] DEBUG[1093]: chan_sip.c:6827 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: False [Oct 1 13:02:38] DEBUG[21436]: chan_sip.c:17064 sip_devicestate: Checking device state for peer 1630 [Oct 1 13:02:38] DEBUG[1093]: chan_sip.c:6828 add_sdp: ** Our prefcodec: 0x4 (ulaw) [Oct 1 13:02:38] DEBUG[21525]: app_queue.c:680 handle_statechange: Device 'SIP/1630' changed to state '6' (Ringing) [Oct 1 13:02:38] DEBUG[1093]: chan_sip.c:6945 add_sdp: -- Done with adding codecs to SDP [Oct 1 13:02:38] DEBUG[1093]: chan_sip.c:7054 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw) -- Called 1630 [Oct 1 13:02:38] DEBUG[896]: rtp.c:923 ast_rtcp_read: Got RTCP report of 64 bytes [Oct 1 13:02:38] DEBUG[21537]: chan_sip.c:2300 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '0eb85288437f222b3b13eb3965539ab2@192.168.30.165' Request 102: Found [Oct 1 13:02:38] DEBUG[841]: rtp.c:923 ast_rtcp_read: Got RTCP report of 64 bytes [Oct 1 13:02:38] DEBUG[21537]: chan_sip.c:2226 __sip_ack: Acked pending invite 102 [Oct 1 13:02:38] DEBUG[21537]: chan_sip.c:2258 __sip_ack: Stopping retransmission on '0eb85288437f222b3b13eb3965539ab2@192.168.30.165' of Request 102: Match Found [Oct 1 13:02:38] DEBUG[21537]: chan_sip.c:5778 process_sdp: T38 state changed to 0 on channel SIP/1630-09732e50 [Oct 1 13:02:38] DEBUG[21537]: chan_sip.c:5858 process_sdp: We're settling with these formats: 0x4 (ulaw) [Oct 1 13:02:38] DEBUG[21537]: chan_sip.c:3366 update_call_counter: Updating call counter for outgoing call [Oct 1 13:02:38] DEBUG[21537]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/1630 [Oct 1 13:02:38] DEBUG[21436]: chan_sip.c:17064 sip_devicestate: Checking device state for peer 1630 [Oct 1 13:02:38] DEBUG[21436]: devicestate.c:287 do_state_change: Changing state for SIP/1630 - state 2 (In use) [Oct 1 13:02:38] DEBUG[21436]: chan_sip.c:17064 sip_devicestate: Checking device state for peer 1630 [Oct 1 13:02:38] DEBUG[21525]: app_queue.c:680 handle_statechange: Device 'SIP/1630' changed to state '2' (In use) [Oct 1 13:02:38] DEBUG[21537]: chan_sip.c:8785 build_route: build_route: Contact hop: [Oct 1 13:02:38] DEBUG[1093]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/1630 -- SIP/1630-09732e50 answered Local/1630@default-agent-a62e,2 [Oct 1 13:02:38] DEBUG[21436]: chan_sip.c:17064 sip_devicestate: Checking device state for peer 1630 [Oct 1 13:02:38] DEBUG[21436]: devicestate.c:287 do_state_change: Changing state for SIP/1630 - state 2 (In use) [Oct 1 13:02:38] DEBUG[1093]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel Local/1630@default-agent [Oct 1 13:02:38] DEBUG[21436]: chan_sip.c:17064 sip_devicestate: Checking device state for peer 1630 [Oct 1 13:02:38] DEBUG[21436]: chan_local.c:145 local_devicestate: Checking if extension 1630@default-agent exists (devicestate) [Oct 1 13:02:38] DEBUG[21436]: channel.c:1132 channel_find_locked: Avoiding initial deadlock for channel '0x97821f0' [Oct 1 13:02:38] DEBUG[1090]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel Local/1630@default-agent -- Local/1630@default-agent-a62e,1 answered SIP/siptrunk-b4837b88 [Oct 1 13:02:38] DEBUG[21525]: app_queue.c:680 handle_statechange: Device 'SIP/1630' changed to state '2' (In use) [Oct 1 13:02:38] DEBUG[1090]: app_queue.c:2085 store_next: Next is 'Local/1620@default-agent/n' with metric 3 -- Stopped music on hold on SIP/siptrunk-b4837b88 [Oct 1 13:02:38] DEBUG[1090]: app_queue.c:1701 leave_queue: Queue 'default-queue-new-english' Leave, Channel 'SIP/siptrunk-b4837b88' [Oct 1 13:02:38] DEBUG[1090]: channel.c:4297 ast_generic_bridge: Got a FRAME_CONTROL (-1) frame on channel Local/1630@default-agent-a62e,1 [Oct 1 13:02:38] DEBUG[1090]: channel.c:4637 ast_channel_bridge: Bridge stops bridging channels SIP/siptrunk-b4837b88 and Local/1630@default-agent-a62e,1 [Oct 1 13:02:38] DEBUG[21436]: devicestate.c:287 do_state_change: Changing state for Local/1630@default-agent - state 2 (In use) [Oct 1 13:02:38] DEBUG[21436]: chan_local.c:145 local_devicestate: Checking if extension 1630@default-agent exists (devicestate) [Oct 1 13:02:38] DEBUG[21436]: devicestate.c:287 do_state_change: Changing state for Local/1630@default-agent - state 2 (In use) [Oct 1 13:02:38] DEBUG[21525]: app_queue.c:675 handle_statechange: Device 'Local/1630@default-agent' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Oct 1 13:02:38] DEBUG[21525]: app_queue.c:675 handle_statechange: Device 'Local/1630@default-agent' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Oct 1 13:02:38] DEBUG[1093]: rtp.c:2885 ast_rtp_write: Ooh, format changed from unknown to ulaw [Oct 1 13:02:38] DEBUG[1093]: rtp.c:2902 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160 [Oct 1 13:02:38] DEBUG[575]: rtp.c:923 ast_rtcp_read: Got RTCP report of 64 bytes [Oct 1 13:02:38] DEBUG[419]: rtp.c:923 ast_rtcp_read: Got RTCP report of 64 bytes [Oct 1 13:02:38] DEBUG[32730]: rtp.c:923 ast_rtcp_read: Got RTCP report of 64 bytes [Oct 1 13:02:39] DEBUG[621]: rtp.c:923 ast_rtcp_read: Got RTCP report of 64 bytes [Oct 1 13:02:39] DEBUG[425]: rtp.c:923 ast_rtcp_read: Got RTCP report of 64 bytes [Oct 1 13:02:39] DEBUG[579]: rtp.c:923 ast_rtcp_read: Got RTCP report of 64 bytes [Oct 1 13:02:40] DEBUG[32628]: rtp.c:923 ast_rtcp_read: Got RTCP report of 64 bytes [Oct 1 13:02:40] DEBUG[634]: rtp.c:923 ast_rtcp_read: Got RTCP report of 64 bytes [Oct 1 13:02:40] DEBUG[655]: rtp.c:923 ast_rtcp_read: Got RTCP report of 64 bytes [Oct 1 13:02:40] DEBUG[32630]: rtp.c:923 ast_rtcp_read: Got RTCP report of 64 bytes [Oct 1 13:02:41] DEBUG[1033]: rtp.c:923 ast_rtcp_read: Got RTCP report of 64 bytes [Oct 1 13:02:41] DEBUG[657]: rtp.c:923 ast_rtcp_read: Got RTCP report of 64 bytes [Oct 1 13:02:41] DEBUG[686]: rtp.c:923 ast_rtcp_read: Got RTCP report of 64 bytes [Oct 1 13:02:41] DEBUG[32716]: rtp.c:923 ast_rtcp_read: Got RTCP report of 64 bytes [Oct 1 13:02:41] DEBUG[32728]: rtp.c:923 ast_rtcp_read: Got RTCP report of 64 bytes [Oct 1 13:02:41] DEBUG[1036]: rtp.c:923 ast_rtcp_read: Got RTCP report of 64 bytes [Oct 1 13:02:42] DEBUG[32718]: rtp.c:923 ast_rtcp_read: Got RTCP report of 64 bytes [Oct 1 13:02:42] DEBUG[836]: rtp.c:923 ast_rtcp_read: Got RTCP report of 64 bytes [Oct 1 13:02:42] DEBUG[688]: rtp.c:923 ast_rtcp_read: Got RTCP report of 64 bytes [Oct 1 13:02:42] DEBUG[1055]: rtp.c:923 ast_rtcp_read: Got RTCP report of 64 bytes [Oct 1 13:02:42] DEBUG[891]: rtp.c:923 ast_rtcp_read: Got RTCP report of 64 bytes [Oct 1 13:02:42] DEBUG[1090]: rtp.c:923 ast_rtcp_read: Got RTCP report of 64 bytes [Oct 1 13:02:42] DEBUG[1115]: manager.c:2232 process_message: Manager received command 'login' == Parsing '/etc/asterisk/manager.conf': [Oct 1 13:02:42] DEBUG[1115]: config.c:895 config_text_file_load: Parsing /etc/asterisk/manager.conf Found [Oct 1 13:02:42] DEBUG[1115]: acl.c:355 ast_append_ha: 127.0.0.1/255.255.255.255 appended to acl for peer [Oct 1 13:02:42] DEBUG[1115]: acl.c:370 ast_apply_ha: ##### Testing 127.0.0.1 with 127.0.0.1 [Oct 1 13:02:42] DEBUG[1057]: rtp.c:923 ast_rtcp_read: Got RTCP report of 64 bytes [Oct 1 13:02:42] DEBUG[1115]: manager.c:2232 process_message: Manager received command 'Command' [Oct 1 13:02:43] DEBUG[896]: rtp.c:923 ast_rtcp_read: Got RTCP report of 64 bytes [Oct 1 13:02:43] DEBUG[841]: rtp.c:923 ast_rtcp_read: Got RTCP report of 64 bytes [Oct 1 13:02:43] DEBUG[1093]: rtp.c:923 ast_rtcp_read: Got RTCP report of 64 bytes [Oct 1 13:02:43] DEBUG[575]: rtp.c:923 ast_rtcp_read: Got RTCP report of 64 bytes [Oct 1 13:02:43] DEBUG[419]: rtp.c:923 ast_rtcp_read: Got RTCP report of 64 bytes [Oct 1 13:02:43] DEBUG[32730]: rtp.c:923 ast_rtcp_read: Got RTCP report of 64 bytes [Oct 1 13:02:44] DEBUG[21537]: chan_sip.c:2881 do_setnat: Setting NAT on RTP to Off [Oct 1 13:02:44] DEBUG[21537]: chan_sip.c:2886 do_setnat: Setting NAT on VRTP to Off [Oct 1 13:02:44] DEBUG[21537]: chan_sip.c:4761 sip_alloc: Allocating new SIP dialog for 34634a7b60ca8d5c2df875be518d4dd2@192.168.30.254 - INVITE (With RTP) [Oct 1 13:02:44] DEBUG[21537]: chan_sip.c:2881 do_setnat: Setting NAT on RTP to Off [Oct 1 13:02:44] DEBUG[21537]: chan_sip.c:2886 do_setnat: Setting NAT on VRTP to Off [Oct 1 13:02:44] DEBUG[21537]: chan_sip.c:2258 __sip_ack: Stopping retransmission on '34634a7b60ca8d5c2df875be518d4dd2@192.168.30.254' of Response 102: Match Found [Oct 1 13:02:44] DEBUG[21537]: chan_sip.c:2881 do_setnat: Setting NAT on RTP to Off [Oct 1 13:02:44] DEBUG[21537]: chan_sip.c:2886 do_setnat: Setting NAT on VRTP to Off [Oct 1 13:02:44] DEBUG[21537]: chan_sip.c:5778 process_sdp: T38 state changed to 0 on channel [Oct 1 13:02:44] DEBUG[21537]: chan_sip.c:5858 process_sdp: We're settling with these formats: 0x4 (ulaw) [Oct 1 13:02:44] DEBUG[21537]: chan_sip.c:14930 handle_request_invite: Checking SIP call limits for device siptrunk [Oct 1 13:02:44] DEBUG[21537]: chan_sip.c:3366 update_call_counter: Updating call counter for incoming call [Oct 1 13:02:44] DEBUG[21537]: chan_sip.c:4228 sip_new: *** Our native formats are 0x4 (ulaw) [Oct 1 13:02:44] DEBUG[21537]: chan_sip.c:4229 sip_new: *** Joint capabilities are 0x4 (ulaw) [Oct 1 13:02:44] DEBUG[21537]: chan_sip.c:4230 sip_new: *** Our capabilities are 0x6 (gsm|ulaw) [Oct 1 13:02:44] DEBUG[21537]: chan_sip.c:4231 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Oct 1 13:02:44] DEBUG[21537]: chan_sip.c:4254 sip_new: This channel will not be able to handle video. [Oct 1 13:02:44] DEBUG[21537]: chan_sip.c:8785 build_route: build_route: Contact hop: [Oct 1 13:02:44] DEBUG[21537]: chan_sip.c:15029 handle_request_invite: SIP/siptrunk-b516fa18: New call is still down.... Trying... [Oct 1 13:02:44] DEBUG[21537]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/siptrunk [Oct 1 13:02:44] DEBUG[21436]: chan_sip.c:17064 sip_devicestate: Checking device state for peer siptrunk [Oct 1 13:02:44] DEBUG[21436]: devicestate.c:287 do_state_change: Changing state for SIP/siptrunk - state 1 (Not in use) [Oct 1 13:02:44] DEBUG[21525]: app_queue.c:675 handle_statechange: Device 'SIP/siptrunk' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Oct 1 13:02:44] DEBUG[1118]: pbx.c:1843 pbx_extension_helper: Launching 'Answer' -- Executing [5000@customer-siptrunk-incoming:1] Answer("SIP/siptrunk-b516fa18", "") in new stack [Oct 1 13:02:44] DEBUG[1118]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/siptrunk [Oct 1 13:02:44] DEBUG[21436]: chan_sip.c:17064 sip_devicestate: Checking device state for peer siptrunk [Oct 1 13:02:44] DEBUG[21436]: devicestate.c:287 do_state_change: Changing state for SIP/siptrunk - state 1 (Not in use) [Oct 1 13:02:44] DEBUG[21525]: app_queue.c:675 handle_statechange: Device 'SIP/siptrunk' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Oct 1 13:02:44] DEBUG[1118]: chan_sip.c:3856 sip_answer: SIP answering channel: SIP/siptrunk-b516fa18 [Oct 1 13:02:44] DEBUG[1118]: chan_sip.c:7112 transmit_response_with_sdp: Setting framing from config on incoming call [Oct 1 13:02:44] DEBUG[1118]: chan_sip.c:6827 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True [Oct 1 13:02:44] DEBUG[1118]: chan_sip.c:6828 add_sdp: ** Our prefcodec: 0x0 (nothing) [Oct 1 13:02:44] DEBUG[1118]: chan_sip.c:6945 add_sdp: -- Done with adding codecs to SDP [Oct 1 13:02:44] DEBUG[1118]: chan_sip.c:7054 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw) [Oct 1 13:02:44] DEBUG[1118]: pbx.c:1843 pbx_extension_helper: Launching 'Set' [Oct 1 13:02:44] DEBUG[21537]: chan_sip.c:2258 __sip_ack: Stopping retransmission on '34634a7b60ca8d5c2df875be518d4dd2@192.168.30.254' of Response 103: Match Found -- Executing [5000@customer-siptrunk-incoming:2] Set("SIP/siptrunk-b516fa18", "CHANNEL(musicclass)=default") in new stack [Oct 1 13:02:44] DEBUG[1118]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '1041' [Oct 1 13:02:44] DEBUG[1118]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '1041' [Oct 1 13:02:44] DEBUG[1118]: pbx.c:1843 pbx_extension_helper: Launching 'NoOp' -- Executing [5000@customer-siptrunk-incoming:3] NoOp("SIP/siptrunk-b516fa18", ""INCOMING CALL FROM CALLER ID: 1041 (1041)"") in new stack [Oct 1 13:02:44] DEBUG[1118]: pbx.c:1843 pbx_extension_helper: Launching 'Set' -- Executing [5000@customer-siptrunk-incoming:4] Set("SIP/siptrunk-b516fa18", "__INCOMING_DNIS=5000") in new stack [Oct 1 13:02:44] DEBUG[1118]: pbx.c:1843 pbx_extension_helper: Launching 'Set' -- Executing [5000@customer-siptrunk-incoming:5] Set("SIP/siptrunk-b516fa18", "CALLERID(dnid)=5000") in new stack [Oct 1 13:02:44] DEBUG[1118]: pbx.c:1843 pbx_extension_helper: Launching 'Set' -- Executing [5000@customer-siptrunk-incoming:6] Set("SIP/siptrunk-b516fa18", "CDR(userfield)=5000") in new stack [Oct 1 13:02:44] DEBUG[1118]: pbx.c:1843 pbx_extension_helper: Launching 'Goto' -- Executing [5000@customer-siptrunk-incoming:7] Goto("SIP/siptrunk-b516fa18", "10") in new stack -- Goto (customer-siptrunk-incoming,5000,10) [Oct 1 13:02:44] DEBUG[1118]: pbx.c:1843 pbx_extension_helper: Launching 'AGI' -- Executing [5000@customer-siptrunk-incoming:10] AGI("SIP/siptrunk-b516fa18", "/var/www/scopserv/telephony/scripts/agi/fixcidname.php") in new stack -- Launched AGI Script /var/www/scopserv/telephony/scripts/agi/fixcidname.php [Oct 1 13:02:44] DEBUG[621]: rtp.c:923 ast_rtcp_read: Got RTCP report of 64 bytes [Oct 1 13:02:44] DEBUG[425]: rtp.c:923 ast_rtcp_read: Got RTCP report of 64 bytes [Oct 1 13:02:44] DEBUG[579]: rtp.c:923 ast_rtcp_read: Got RTCP report of 64 bytes -- AGI Script /var/www/scopserv/telephony/scripts/agi/fixcidname.php completed, returning 0 [Oct 1 13:02:44] DEBUG[1118]: pbx.c:1843 pbx_extension_helper: Launching 'Set' -- Executing [5000@customer-siptrunk-incoming:11] Set("SIP/siptrunk-b516fa18", "GROUP(siptrunk)=INCOMING") in new stack [Oct 1 13:02:44] DEBUG[1118]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '14' [Oct 1 13:02:44] DEBUG[1118]: pbx.c:1759 pbx_substitute_variables_helper_full: Expression result is '0' [Oct 1 13:02:44] DEBUG[1118]: pbx.c:1843 pbx_extension_helper: Launching 'GotoIf' -- Executing [5000@customer-siptrunk-incoming:12] GotoIf("SIP/siptrunk-b516fa18", "0?500") in new stack [Oct 1 13:02:44] DEBUG[1118]: pbx.c:6067 pbx_builtin_gotoif: Not taking any branch [Oct 1 13:02:44] DEBUG[1118]: pbx.c:1843 pbx_extension_helper: Launching 'Set' -- Executing [5000@customer-siptrunk-incoming:13] Set("SIP/siptrunk-b516fa18", "FAXNUMBER=5000") in new stack [Oct 1 13:02:44] DEBUG[1118]: pbx.c:1843 pbx_extension_helper: Launching 'Set' -- Executing [5000@customer-siptrunk-incoming:14] Set("SIP/siptrunk-b516fa18", "__INCOMINGLINE=1") in new stack [Oct 1 13:02:44] DEBUG[1118]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '1041' [Oct 1 13:02:44] DEBUG[1118]: pbx.c:1759 pbx_substitute_variables_helper_full: Expression result is '0' [Oct 1 13:02:44] DEBUG[1118]: pbx.c:1843 pbx_extension_helper: Launching 'GotoIf' -- Executing [5000@customer-siptrunk-incoming:15] GotoIf("SIP/siptrunk-b516fa18", "0?16:17") in new stack -- Goto (customer-siptrunk-incoming,5000,17) [Oct 1 13:02:44] DEBUG[1118]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '1041' [Oct 1 13:02:44] DEBUG[1118]: pbx.c:1759 pbx_substitute_variables_helper_full: Expression result is '0' [Oct 1 13:02:44] DEBUG[1118]: pbx.c:1843 pbx_extension_helper: Launching 'GotoIf' -- Executing [5000@customer-siptrunk-incoming:17] GotoIf("SIP/siptrunk-b516fa18", "0?18:19") in new stack -- Goto (customer-siptrunk-incoming,5000,19) [Oct 1 13:02:44] DEBUG[1118]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '1041' [Oct 1 13:02:44] DEBUG[1118]: pbx.c:1759 pbx_substitute_variables_helper_full: Expression result is '0' [Oct 1 13:02:44] DEBUG[1118]: pbx.c:1843 pbx_extension_helper: Launching 'GotoIf' -- Executing [5000@customer-siptrunk-incoming:19] GotoIf("SIP/siptrunk-b516fa18", "0?20:21") in new stack -- Goto (customer-siptrunk-incoming,5000,21) [Oct 1 13:02:44] DEBUG[1118]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '1041' [Oct 1 13:02:44] DEBUG[1118]: pbx.c:1759 pbx_substitute_variables_helper_full: Expression result is '0' [Oct 1 13:02:44] DEBUG[1118]: pbx.c:1843 pbx_extension_helper: Launching 'GotoIf' -- Executing [5000@customer-siptrunk-incoming:21] GotoIf("SIP/siptrunk-b516fa18", "0?22:23") in new stack -- Goto (customer-siptrunk-incoming,5000,23) [Oct 1 13:02:44] DEBUG[1118]: pbx.c:1843 pbx_extension_helper: Launching 'Set' -- Executing [5000@customer-siptrunk-incoming:23] Set("SIP/siptrunk-b516fa18", "CHANNEL(language)=en") in new stack [Oct 1 13:02:44] DEBUG[1118]: pbx.c:1843 pbx_extension_helper: Launching 'Set' -- Executing [5000@customer-siptrunk-incoming:24] Set("SIP/siptrunk-b516fa18", "QUEUE_PRIO=0") in new stack [Oct 1 13:02:44] DEBUG[1118]: pbx.c:1843 pbx_extension_helper: Launching 'Gosub' -- Executing [5000@customer-siptrunk-incoming:25] Gosub("SIP/siptrunk-b516fa18", "default-application-acd-queue-new-english|s|1") in new stack [Oct 1 13:02:44] DEBUG[1118]: pbx.c:1843 pbx_extension_helper: Launching 'NoOp' -- Executing [s@default-application-acd-queue-new-english:1] NoOp("SIP/siptrunk-b516fa18", ""=== START QUEUE (default-queue-new-english) ==="") in new stack [Oct 1 13:02:44] DEBUG[1118]: pbx.c:1843 pbx_extension_helper: Launching 'Set' -- Executing [s@default-application-acd-queue-new-english:2] Set("SIP/siptrunk-b516fa18", "__QUEUENAME=default-queue-new-english") in new stack [Oct 1 13:02:44] DEBUG[1118]: pbx.c:1759 pbx_substitute_variables_helper_full: Expression result is '0' [Oct 1 13:02:44] DEBUG[1118]: pbx.c:1759 pbx_substitute_variables_helper_full: Expression result is '6' [Oct 1 13:02:44] DEBUG[1118]: pbx.c:1843 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@default-application-acd-queue-new-english:3] GotoIf("SIP/siptrunk-b516fa18", "0?6") in new stack [Oct 1 13:02:44] DEBUG[1118]: pbx.c:6067 pbx_builtin_gotoif: Not taking any branch [Oct 1 13:02:44] DEBUG[1118]: pbx.c:1843 pbx_extension_helper: Launching 'Set' -- Executing [s@default-application-acd-queue-new-english:4] Set("SIP/siptrunk-b516fa18", "MONITOR_FILENAME=1254416564.32832") in new stack [Oct 1 13:02:44] DEBUG[1118]: pbx.c:1759 pbx_substitute_variables_helper_full: Expression result is '7' [Oct 1 13:02:44] DEBUG[1118]: pbx.c:1843 pbx_extension_helper: Launching 'Goto' -- Executing [s@default-application-acd-queue-new-english:5] Goto("SIP/siptrunk-b516fa18", "7") in new stack -- Goto (default-application-acd-queue-new-english,s,7) [Oct 1 13:02:44] DEBUG[1118]: pbx.c:1843 pbx_extension_helper: Launching 'Set' -- Executing [s@default-application-acd-queue-new-english:7] Set("SIP/siptrunk-b516fa18", "TIMEOUT(digit)=1") in new stack -- Digit timeout set to 1 [Oct 1 13:02:44] DEBUG[1118]: pbx.c:1843 pbx_extension_helper: Launching 'Set' -- Executing [s@default-application-acd-queue-new-english:8] Set("SIP/siptrunk-b516fa18", "TIMEOUT(response)=1") in new stack -- Response timeout set to 1 [Oct 1 13:02:44] DEBUG[1118]: pbx.c:1843 pbx_extension_helper: Launching 'Set' -- Executing [s@default-application-acd-queue-new-english:9] Set("SIP/siptrunk-b516fa18", "__ACD_TO_OUTGOING=1") in new stack [Oct 1 13:02:44] DEBUG[1118]: pbx.c:1843 pbx_extension_helper: Launching 'Set' -- Executing [s@default-application-acd-queue-new-english:10] Set("SIP/siptrunk-b516fa18", "CHANNEL(musicclass)=default") in new stack [Oct 1 13:02:44] DEBUG[1118]: pbx.c:1843 pbx_extension_helper: Launching 'Set' -- Executing [s@default-application-acd-queue-new-english:11] Set("SIP/siptrunk-b516fa18", "__ALLOW_TRANSFER=twk") in new stack [Oct 1 13:02:44] DEBUG[1118]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '1041' [Oct 1 13:02:44] DEBUG[1118]: pbx.c:1843 pbx_extension_helper: Launching 'Set' -- Executing [s@default-application-acd-queue-new-english:12] Set("SIP/siptrunk-b516fa18", "CALLERID(name)=queue-E:1041") in new stack [Oct 1 13:02:44] DEBUG[1118]: pbx.c:1843 pbx_extension_helper: Launching 'Queue' -- Executing [s@default-application-acd-queue-new-english:13] Queue("SIP/siptrunk-b516fa18", "default-queue-new-english|tH|||60|") in new stack [Oct 1 13:02:44] DEBUG[1118]: app_queue.c:3985 queue_exec: SIP/siptrunk-b516fa18: Got priority 0 from ${QUEUE_PRIO}. [Oct 1 13:02:44] DEBUG[1118]: app_queue.c:4017 queue_exec: queue: default-queue-new-english, options: tH, url: , announce: , expires: 1254416624, priority: 0 [Oct 1 13:02:44] DEBUG[1118]: app_queue.c:1352 update_realtime_members: Queue default-queue-new-english has no realtime members defined. No need for update [Oct 1 13:02:44] DEBUG[1118]: app_queue.c:1497 join_queue: Queue 'default-queue-new-english' Join, Channel 'SIP/siptrunk-b516fa18', Position '1' -- Started music on hold, class 'default', on SIP/siptrunk-b516fa18 [Oct 1 13:02:44] DEBUG[1118]: app_queue.c:2465 is_our_turn: There are 5 available members. [Oct 1 13:02:44] DEBUG[1118]: app_queue.c:2479 is_our_turn: It's our turn (SIP/siptrunk-b516fa18). [Oct 1 13:02:44] DEBUG[1118]: app_queue.c:2862 try_calling: SIP/siptrunk-b516fa18 is trying to call a queue member. [Oct 1 13:02:44] DEBUG[1118]: app_queue.c:2070 ring_one: Trying 'Local/1620@default-agent/n' with metric 3 [Oct 1 13:02:44] DEBUG[1118]: channel.c:3729 ast_channel_inherit_variables: Copying hard-transferable variable ALLOW_TRANSFER. [Oct 1 13:02:44] DEBUG[1118]: channel.c:3729 ast_channel_inherit_variables: Copying hard-transferable variable ACD_TO_OUTGOING. [Oct 1 13:02:44] DEBUG[1118]: channel.c:3734 ast_channel_inherit_variables: Not copying variable MONITOR_FILENAME. [Oct 1 13:02:44] DEBUG[1118]: channel.c:3729 ast_channel_inherit_variables: Copying hard-transferable variable QUEUENAME. [Oct 1 13:02:44] DEBUG[1118]: channel.c:3734 ast_channel_inherit_variables: Not copying variable ~GOSUB~STACK~. [Oct 1 13:02:44] DEBUG[1118]: channel.c:3734 ast_channel_inherit_variables: Not copying variable QUEUE_PRIO. [Oct 1 13:02:44] DEBUG[1118]: channel.c:3729 ast_channel_inherit_variables: Copying hard-transferable variable INCOMINGLINE. [Oct 1 13:02:44] DEBUG[1118]: channel.c:3734 ast_channel_inherit_variables: Not copying variable FAXNUMBER. [Oct 1 13:02:44] DEBUG[1118]: channel.c:3734 ast_channel_inherit_variables: Not copying variable AGISTATUS. [Oct 1 13:02:44] DEBUG[1118]: channel.c:3729 ast_channel_inherit_variables: Copying hard-transferable variable INCOMING_DNIS. [Oct 1 13:02:44] DEBUG[1118]: channel.c:3734 ast_channel_inherit_variables: Not copying variable SIPCALLID. [Oct 1 13:02:44] DEBUG[1118]: channel.c:3734 ast_channel_inherit_variables: Not copying variable SIPUSERAGENT. [Oct 1 13:02:44] DEBUG[1118]: channel.c:3734 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [Oct 1 13:02:44] DEBUG[1118]: channel.c:3734 ast_channel_inherit_variables: Not copying variable SIPURI. -- Called Local/1620@default-agent/n [Oct 1 13:02:44] DEBUG[1118]: chan_sip.c:17064 sip_devicestate: Checking device state for peer 1620 [Oct 1 13:02:44] DEBUG[1118]: res_musiconhold.c:261 ast_moh_files_next: SIP/siptrunk-b516fa18 Opened file 7 '/var/lib/asterisk/moh//reno_project-system' [Oct 1 13:02:44] DEBUG[1118]: rtp.c:2885 ast_rtp_write: Ooh, format changed from unknown to ulaw [Oct 1 13:02:44] DEBUG[1118]: rtp.c:2902 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160 [Oct 1 13:02:44] DEBUG[1120]: pbx.c:1843 pbx_extension_helper: Launching 'NoCDR' -- Executing [1620@default-agent:1] NoCDR("Local/1620@default-agent-39ce,2", "") in new stack [Oct 1 13:02:44] DEBUG[1120]: db.c:196 ast_db_get: Unable to find key '1620/DoNotDisturb' in family 'default' [Oct 1 13:02:44] DEBUG[1120]: func_db.c:70 function_db_read: DB: default/1620/DoNotDisturb not found in database. [Oct 1 13:02:44] DEBUG[1120]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '' [Oct 1 13:02:44] DEBUG[1120]: pbx.c:1843 pbx_extension_helper: Launching 'Set' -- Executing [1620@default-agent:2] Set("Local/1620@default-agent-39ce,2", "DND=") in new stack [Oct 1 13:02:44] DEBUG[1120]: pbx.c:1759 pbx_substitute_variables_helper_full: Expression result is '0' [Oct 1 13:02:44] DEBUG[1120]: pbx.c:1843 pbx_extension_helper: Launching 'GotoIf' -- Executing [1620@default-agent:3] GotoIf("Local/1620@default-agent-39ce,2", "0?30") in new stack [Oct 1 13:02:44] DEBUG[1120]: pbx.c:6067 pbx_builtin_gotoif: Not taking any branch [Oct 1 13:02:44] DEBUG[1120]: db.c:196 ast_db_get: Unable to find key '1620/OutOffice' in family 'default' [Oct 1 13:02:44] DEBUG[1120]: func_db.c:70 function_db_read: DB: default/1620/OutOffice not found in database. [Oct 1 13:02:44] DEBUG[1120]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '' [Oct 1 13:02:44] DEBUG[1120]: pbx.c:1843 pbx_extension_helper: Launching 'Set' -- Executing [1620@default-agent:4] Set("Local/1620@default-agent-39ce,2", "OutOffice=") in new stack [Oct 1 13:02:44] DEBUG[1120]: pbx.c:1759 pbx_substitute_variables_helper_full: Expression result is '0' [Oct 1 13:02:44] DEBUG[1120]: pbx.c:1843 pbx_extension_helper: Launching 'GotoIf' -- Executing [1620@default-agent:5] GotoIf("Local/1620@default-agent-39ce,2", "0?30") in new stack [Oct 1 13:02:44] DEBUG[1120]: pbx.c:6067 pbx_builtin_gotoif: Not taking any branch [Oct 1 13:02:44] DEBUG[1120]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '0' [Oct 1 13:02:44] DEBUG[1120]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '0' [Oct 1 13:02:44] DEBUG[1120]: pbx.c:1759 pbx_substitute_variables_helper_full: Expression result is '0' [Oct 1 13:02:44] DEBUG[1120]: pbx.c:1843 pbx_extension_helper: Launching 'Set' -- Executing [1620@default-agent:6] Set("Local/1620@default-agent-39ce,2", "GROUPCOUNT=0") in new stack [Oct 1 13:02:44] DEBUG[1120]: db.c:196 ast_db_get: Unable to find key 'agent//maxcalls' in family 'default' [Oct 1 13:02:44] DEBUG[1120]: func_db.c:70 function_db_read: DB: default/agent//maxcalls not found in database. [Oct 1 13:02:44] DEBUG[1120]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '' [Oct 1 13:02:44] DEBUG[1120]: pbx.c:1843 pbx_extension_helper: Launching 'Set' -- Executing [1620@default-agent:7] Set("Local/1620@default-agent-39ce,2", "AGENTMAXCALL=") in new stack [Oct 1 13:02:44] DEBUG[1120]: pbx.c:1759 pbx_substitute_variables_helper_full: Expression result is '1' [Oct 1 13:02:44] DEBUG[1120]: pbx.c:1759 pbx_substitute_variables_helper_full: Expression result is '9' [Oct 1 13:02:44] DEBUG[1120]: pbx.c:1759 pbx_substitute_variables_helper_full: Expression result is '12' [Oct 1 13:02:44] DEBUG[1120]: pbx.c:1843 pbx_extension_helper: Launching 'GotoIf' -- Executing [1620@default-agent:8] GotoIf("Local/1620@default-agent-39ce,2", "1?9:12") in new stack -- Goto (default-agent,1620,9) [Oct 1 13:02:44] DEBUG[1120]: pbx.c:1843 pbx_extension_helper: Launching 'Set' -- Executing [1620@default-agent:9] Set("Local/1620@default-agent-39ce,2", "AGENTMAXCALL=") in new stack [Oct 1 13:02:44] DEBUG[1120]: pbx.c:1759 pbx_substitute_variables_helper_full: Expression result is '1' [Oct 1 13:02:44] DEBUG[1120]: pbx.c:1759 pbx_substitute_variables_helper_full: Expression result is '11' [Oct 1 13:02:44] DEBUG[1120]: pbx.c:1759 pbx_substitute_variables_helper_full: Expression result is '12' [Oct 1 13:02:44] DEBUG[1120]: pbx.c:1843 pbx_extension_helper: Launching 'GotoIf' -- Executing [1620@default-agent:10] GotoIf("Local/1620@default-agent-39ce,2", "1?11:12") in new stack -- Goto (default-agent,1620,11) [Oct 1 13:02:44] DEBUG[1120]: pbx.c:1843 pbx_extension_helper: Launching 'Set' -- Executing [1620@default-agent:11] Set("Local/1620@default-agent-39ce,2", "AGENTMAXCALL=1") in new stack [Oct 1 13:02:44] DEBUG[1120]: pbx.c:1759 pbx_substitute_variables_helper_full: Expression result is '0' [Oct 1 13:02:44] DEBUG[1120]: pbx.c:1843 pbx_extension_helper: Launching 'GotoIf' -- Executing [1620@default-agent:12] GotoIf("Local/1620@default-agent-39ce,2", "0?30") in new stack [Oct 1 13:02:44] DEBUG[1120]: pbx.c:6067 pbx_builtin_gotoif: Not taking any branch [Oct 1 13:02:44] DEBUG[1120]: pbx.c:1759 pbx_substitute_variables_helper_full: Expression result is '1' [Oct 1 13:02:44] DEBUG[1120]: pbx.c:1759 pbx_substitute_variables_helper_full: Expression result is '16' [Oct 1 13:02:44] DEBUG[1120]: pbx.c:1843 pbx_extension_helper: Launching 'GotoIf' -- Executing [1620@default-agent:13] GotoIf("Local/1620@default-agent-39ce,2", "1?16") in new stack -- Goto (default-agent,1620,16) [Oct 1 13:02:44] DEBUG[1120]: pbx.c:1843 pbx_extension_helper: Launching 'Set' -- Executing [1620@default-agent:16] Set("Local/1620@default-agent-39ce,2", "OUTBOUND_GROUP_ONCE=1620@INCOMING") in new stack [Oct 1 13:02:44] DEBUG[1120]: pbx.c:1843 pbx_extension_helper: Launching 'Set' -- Executing [1620@default-agent:17] Set("Local/1620@default-agent-39ce,2", "DB(default/wrapup/1620/lastcall)=1254416564.32834") in new stack [Oct 1 13:02:44] DEBUG[1120]: db.c:196 ast_db_get: Unable to find key 'agent//monitor' in family 'default' [Oct 1 13:02:44] DEBUG[1120]: func_db.c:70 function_db_read: DB: default/agent//monitor not found in database. [Oct 1 13:02:44] DEBUG[1120]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '' [Oct 1 13:02:44] DEBUG[1120]: pbx.c:1843 pbx_extension_helper: Launching 'Set' -- Executing [1620@default-agent:18] Set("Local/1620@default-agent-39ce,2", "AGENTMONITOR=") in new stack [Oct 1 13:02:44] DEBUG[1120]: pbx.c:1759 pbx_substitute_variables_helper_full: Expression result is '1' [Oct 1 13:02:44] DEBUG[1120]: pbx.c:1759 pbx_substitute_variables_helper_full: Expression result is '23' [Oct 1 13:02:44] DEBUG[1120]: pbx.c:1843 pbx_extension_helper: Launching 'GotoIf' -- Executing [1620@default-agent:19] GotoIf("Local/1620@default-agent-39ce,2", "1?23") in new stack -- Goto (default-agent,1620,23) [Oct 1 13:02:44] DEBUG[1120]: pbx.c:1843 pbx_extension_helper: Launching 'Goto' -- Executing [1620@default-agent:23] Goto("Local/1620@default-agent-39ce,2", "default-local-devices|1620|1") in new stack -- Goto (default-local-devices,1620,1) [Oct 1 13:02:44] DEBUG[1120]: pbx.c:1843 pbx_extension_helper: Launching 'Set' -- Executing [1620@default-local-devices:1] Set("Local/1620@default-agent-39ce,2", "__PICKUPMARK=1620") in new stack [Oct 1 13:02:44] DEBUG[1120]: pbx.c:1843 pbx_extension_helper: Launching 'Set' -- Executing [1620@default-local-devices:2] Set("Local/1620@default-agent-39ce,2", "DB(default/wrapup/1620/lastcall)=1254416564.32834") in new stack [Oct 1 13:02:44] DEBUG[1120]: pbx.c:1843 pbx_extension_helper: Launching 'Dial' -- Executing [1620@default-local-devices:3] Dial("Local/1620@default-agent-39ce,2", "SIP/1620||twk") in new stack [Oct 1 13:02:44] DEBUG[1120]: chan_sip.c:17140 sip_request_call: Asked to create a SIP channel with formats: 0x4 (ulaw) [Oct 1 13:02:44] DEBUG[1120]: chan_sip.c:4761 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Oct 1 13:02:44] DEBUG[1120]: chan_sip.c:2881 do_setnat: Setting NAT on RTP to Off [Oct 1 13:02:44] DEBUG[1120]: chan_sip.c:4228 sip_new: *** Our native formats are 0x4 (ulaw) [Oct 1 13:02:44] DEBUG[1120]: chan_sip.c:4229 sip_new: *** Joint capabilities are 0x0 (nothing) [Oct 1 13:02:44] DEBUG[1120]: chan_sip.c:4230 sip_new: *** Our capabilities are 0x4 (ulaw) [Oct 1 13:02:44] DEBUG[1120]: chan_sip.c:4231 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Oct 1 13:02:44] DEBUG[1120]: chan_sip.c:4233 sip_new: *** Our preferred formats from the incoming channel are 0x4 (ulaw) [Oct 1 13:02:44] DEBUG[1120]: chan_sip.c:4254 sip_new: This channel will not be able to handle video. [Oct 1 13:02:44] DEBUG[1120]: rtp.c:1648 ast_rtp_make_compatible: Channel 'Local/1620@default-agent-39ce,2' has no RTP, not doing anything [Oct 1 13:02:44] DEBUG[1120]: channel.c:3734 ast_channel_inherit_variables: Not copying variable DIALEDTIME. [Oct 1 13:02:44] DEBUG[1120]: channel.c:3734 ast_channel_inherit_variables: Not copying variable ANSWEREDTIME. [Oct 1 13:02:44] DEBUG[1120]: channel.c:3734 ast_channel_inherit_variables: Not copying variable DIALEDPEERNAME. [Oct 1 13:02:44] DEBUG[1120]: channel.c:3734 ast_channel_inherit_variables: Not copying variable DIALEDPEERNUMBER. [Oct 1 13:02:44] DEBUG[1120]: channel.c:3734 ast_channel_inherit_variables: Not copying variable DIALSTATUS. [Oct 1 13:02:44] DEBUG[1120]: channel.c:3729 ast_channel_inherit_variables: Copying hard-transferable variable PICKUPMARK. [Oct 1 13:02:44] DEBUG[1120]: channel.c:3734 ast_channel_inherit_variables: Not copying variable AGENTMONITOR. [Oct 1 13:02:44] DEBUG[1120]: channel.c:3734 ast_channel_inherit_variables: Not copying variable AGENTMAXCALL. [Oct 1 13:02:44] DEBUG[1120]: channel.c:3734 ast_channel_inherit_variables: Not copying variable GROUPCOUNT. [Oct 1 13:02:44] DEBUG[1120]: channel.c:3734 ast_channel_inherit_variables: Not copying variable OutOffice. [Oct 1 13:02:44] DEBUG[1120]: channel.c:3734 ast_channel_inherit_variables: Not copying variable DND. [Oct 1 13:02:44] DEBUG[1120]: channel.c:3729 ast_channel_inherit_variables: Copying hard-transferable variable ALLOW_TRANSFER. [Oct 1 13:02:44] DEBUG[1120]: channel.c:3729 ast_channel_inherit_variables: Copying hard-transferable variable ACD_TO_OUTGOING. [Oct 1 13:02:44] DEBUG[1120]: channel.c:3729 ast_channel_inherit_variables: Copying hard-transferable variable QUEUENAME. [Oct 1 13:02:44] DEBUG[1120]: channel.c:3729 ast_channel_inherit_variables: Copying hard-transferable variable INCOMINGLINE. [Oct 1 13:02:44] DEBUG[1120]: channel.c:3729 ast_channel_inherit_variables: Copying hard-transferable variable INCOMING_DNIS. [Oct 1 13:02:44] DEBUG[1120]: chan_sip.c:3159 sip_call: Outgoing Call for 1620 [Oct 1 13:02:44] DEBUG[1120]: chan_sip.c:3366 update_call_counter: Updating call counter for outgoing call [Oct 1 13:02:44] DEBUG[1120]: chan_sip.c:3443 update_call_counter: Call to peer '1620' is 1 out of 16 [Oct 1 13:02:44] DEBUG[1120]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/1620 [Oct 1 13:02:44] DEBUG[21436]: chan_sip.c:17064 sip_devicestate: Checking device state for peer 1620 [Oct 1 13:02:44] DEBUG[21436]: devicestate.c:287 do_state_change: Changing state for SIP/1620 - state 6 (Ringing) [Oct 1 13:02:44] DEBUG[21436]: chan_sip.c:17064 sip_devicestate: Checking device state for peer 1620 [Oct 1 13:02:44] DEBUG[21525]: app_queue.c:680 handle_statechange: Device 'SIP/1620' changed to state '6' (Ringing) [Oct 1 13:02:44] DEBUG[1120]: chan_sip.c:3174 sip_call: Our T38 capability (0), joint T38 capability (0) [Oct 1 13:02:44] DEBUG[1120]: chan_sip.c:6827 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: False [Oct 1 13:02:44] DEBUG[1120]: chan_sip.c:6828 add_sdp: ** Our prefcodec: 0x4 (ulaw) [Oct 1 13:02:44] DEBUG[1120]: chan_sip.c:6945 add_sdp: -- Done with adding codecs to SDP [Oct 1 13:02:44] DEBUG[1120]: chan_sip.c:7054 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw) [Oct 1 13:02:44] DEBUG[21537]: chan_sip.c:2300 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '6dad607106961d9f14810f864cbadf19@192.168.30.165' Request 102: Found -- Called 1620 [Oct 1 13:02:44] DEBUG[21537]: chan_sip.c:2226 __sip_ack: Acked pending invite 102 [Oct 1 13:02:44] DEBUG[21537]: chan_sip.c:2258 __sip_ack: Stopping retransmission on '6dad607106961d9f14810f864cbadf19@192.168.30.165' of Request 102: Match Found [Oct 1 13:02:44] DEBUG[21537]: chan_sip.c:5778 process_sdp: T38 state changed to 0 on channel SIP/1620-0983e4e0 [Oct 1 13:02:44] DEBUG[21537]: chan_sip.c:5858 process_sdp: We're settling with these formats: 0x4 (ulaw) [Oct 1 13:02:44] DEBUG[21537]: chan_sip.c:3366 update_call_counter: Updating call counter for outgoing call [Oct 1 13:02:44] DEBUG[21537]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/1620 [Oct 1 13:02:44] DEBUG[21537]: chan_sip.c:8785 build_route: build_route: Contact hop: [Oct 1 13:02:44] DEBUG[21436]: chan_sip.c:17064 sip_devicestate: Checking device state for peer 1620 [Oct 1 13:02:44] DEBUG[1120]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/1620 [Oct 1 13:02:44] DEBUG[21436]: devicestate.c:287 do_state_change: Changing state for SIP/1620 - state 2 (In use) [Oct 1 13:02:44] DEBUG[21525]: app_queue.c:680 handle_statechange: Device 'SIP/1620' changed to state '2' (In use) -- SIP/1620-0983e4e0 answered Local/1620@default-agent-39ce,2 [Oct 1 13:02:44] DEBUG[1120]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel Local/1620@default-agent [Oct 1 13:02:44] DEBUG[1118]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel Local/1620@default-agent -- Local/1620@default-agent-39ce,1 answered SIP/siptrunk-b516fa18 [Oct 1 13:02:44] DEBUG[1118]: app_queue.c:2085 store_next: Next is 'Local/1644@default-agent/n' with metric 4 -- Stopped music on hold on SIP/siptrunk-b516fa18 [Oct 1 13:02:44] DEBUG[1118]: app_queue.c:1701 leave_queue: Queue 'default-queue-new-english' Leave, Channel 'SIP/siptrunk-b516fa18' [Oct 1 13:02:44] DEBUG[21436]: chan_sip.c:17064 sip_devicestate: Checking device state for peer 1620 [Oct 1 13:02:44] DEBUG[1118]: channel.c:4297 ast_generic_bridge: Got a FRAME_CONTROL (-1) frame on channel Local/1620@default-agent-39ce,1 [Oct 1 13:02:44] DEBUG[1118]: channel.c:4637 ast_channel_bridge: Bridge stops bridging channels SIP/siptrunk-b516fa18 and Local/1620@default-agent-39ce,1 [Oct 1 13:02:44] DEBUG[21436]: chan_sip.c:17064 sip_devicestate: Checking device state for peer 1620 [Oct 1 13:02:44] DEBUG[21436]: devicestate.c:287 do_state_change: Changing state for SIP/1620 - state 2 (In use) [Oct 1 13:02:44] DEBUG[21436]: chan_sip.c:17064 sip_devicestate: Checking device state for peer 1620 [Oct 1 13:02:44] DEBUG[21436]: chan_local.c:145 local_devicestate: Checking if extension 1620@default-agent exists (devicestate) [Oct 1 13:02:44] DEBUG[21436]: devicestate.c:287 do_state_change: Changing state for Local/1620@default-agent - state 2 (In use) [Oct 1 13:02:44] DEBUG[21436]: chan_local.c:145 local_devicestate: Checking if extension 1620@default-agent exists (devicestate) [Oct 1 13:02:44] DEBUG[21436]: devicestate.c:287 do_state_change: Changing state for Local/1620@default-agent - state 2 (In use) [Oct 1 13:02:44] DEBUG[21525]: app_queue.c:680 handle_statechange: Device 'SIP/1620' changed to state '2' (In use) [Oct 1 13:02:44] DEBUG[21525]: app_queue.c:675 handle_statechange: Device 'Local/1620@default-agent' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Oct 1 13:02:44] DEBUG[21525]: app_queue.c:675 handle_statechange: Device 'Local/1620@default-agent' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Oct 1 13:02:44] DEBUG[1120]: rtp.c:2885 ast_rtp_write: Ooh, format changed from unknown to ulaw [Oct 1 13:02:44] DEBUG[1120]: rtp.c:2902 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160 [Oct 1 13:02:45] DEBUG[32628]: rtp.c:923 ast_rtcp_read: Got RTCP report of 64 bytes [Oct 1 13:02:45] DEBUG[634]: rtp.c:923 ast_rtcp_read: Got RTCP report of 64 bytes [Oct 1 13:02:45] DEBUG[655]: rtp.c:923 ast_rtcp_read: Got RTCP report of 64 bytes [Oct 1 13:02:45] DEBUG[21537]: chan_sip.c:1706 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 455533282313449738eb349b6f8775f3@192.168.30.254 [Oct 1 13:02:45] DEBUG[21537]: chan_sip.c:15825 handle_request_bye: Received bye, issuing owner hangup [Oct 1 13:02:45] DEBUG[32716]: channel.c:4270 ast_generic_bridge: Didn't get a frame from channel: SIP/siptrunk-b4c4ed78 [Oct 1 13:02:45] DEBUG[32716]: channel.c:4637 ast_channel_bridge: Bridge stops bridging channels SIP/siptrunk-b4c4ed78 and Local/1649@default-agent-8ea1,1 [Oct 1 13:02:45] DEBUG[32716]: pbx.c:1843 pbx_extension_helper: Launching 'Goto' -- Executing [h@default-application-acd-queue-new-english:1] Goto("SIP/siptrunk-b4c4ed78", "all-hangup|s|1") in new stack -- Goto (all-hangup,s,1) [Oct 1 13:02:45] DEBUG[32716]: pbx.c:1759 pbx_substitute_variables_helper_full: Expression result is '0' [Oct 1 13:02:45] DEBUG[32716]: pbx.c:1759 pbx_substitute_variables_helper_full: Expression result is '2' [Oct 1 13:02:45] DEBUG[32716]: pbx.c:1843 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@all-hangup:1] GotoIf("SIP/siptrunk-b4c4ed78", "0?all-faxnotify|s|1:2") in new stack -- Goto (all-hangup,s,2) [Oct 1 13:02:45] DEBUG[32716]: pbx.c:1843 pbx_extension_helper: Launching 'ResetCDR' -- Executing [s@all-hangup:2] ResetCDR("SIP/siptrunk-b4c4ed78", "w") in new stack [Oct 1 13:02:45] DEBUG[32716]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '"queue-E:1039" <1039>' [Oct 1 13:02:45] DEBUG[32716]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '1039' [Oct 1 13:02:45] DEBUG[32716]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is 's' [Oct 1 13:02:45] DEBUG[32716]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is 'default-application-acd-queue-new-english' [Oct 1 13:02:45] DEBUG[32716]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is 'SIP/siptrunk-b4c4ed78' [Oct 1 13:02:45] DEBUG[32716]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is 'Local/1649@default-agent-8ea1,1' [Oct 1 13:02:45] DEBUG[32716]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is 'Queue' [Oct 1 13:02:45] DEBUG[32716]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is 'default-queue-new-english|tH|||60|' [Oct 1 13:02:45] DEBUG[32716]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '2009-10-01 13:00:46' [Oct 1 13:02:45] DEBUG[32716]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '2009-10-01 13:00:46' [Oct 1 13:02:45] DEBUG[32716]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '2009-10-01 13:02:45' [Oct 1 13:02:45] DEBUG[32716]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '119' [Oct 1 13:02:45] DEBUG[32716]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '119' [Oct 1 13:02:45] DEBUG[32716]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is 'ANSWERED' [Oct 1 13:02:45] DEBUG[32716]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' [Oct 1 13:02:45] DEBUG[32716]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is 'siptrunk' [Oct 1 13:02:45] DEBUG[32716]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '1254416446.32784' [Oct 1 13:02:45] DEBUG[32716]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '5000' [Oct 1 13:02:45] DEBUG[32716]: pbx.c:1843 pbx_extension_helper: Launching 'NoCDR' -- Executing [s@all-hangup:3] NoCDR("SIP/siptrunk-b4c4ed78", "") in new stack [Oct 1 13:02:45] DEBUG[32716]: pbx.c:1843 pbx_extension_helper: Launching 'System' -- Executing [s@all-hangup:4] System("SIP/siptrunk-b4c4ed78", "/var/www/scopserv/telephony/scripts/billing/cdr.sh 1254416446.32784") in new stack [Oct 1 13:02:45] DEBUG[32630]: rtp.c:923 ast_rtcp_read: Got RTCP report of 64 bytes [Oct 1 13:02:46] DEBUG[21537]: chan_sip.c:4761 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Oct 1 13:02:46] DEBUG[21537]: chan_sip.c:2258 __sip_ack: Stopping retransmission on '142cdadc1da879851084403900a79c6f@192.168.30.165' of Request 102: Match Found Really destroying SIP dialog '142cdadc1da879851084403900a79c6f@192.168.30.165' Method: OPTIONS [Oct 1 13:02:46] DEBUG[21537]: chan_sip.c:4761 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Oct 1 13:02:46] DEBUG[21537]: chan_sip.c:2258 __sip_ack: Stopping retransmission on '52ddad3e3a6633187d98a24055fd05d2@192.168.30.165' of Request 102: Match Found [Oct 1 13:02:46] DEBUG[21537]: chan_sip.c:4761 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Oct 1 13:02:46] DEBUG[21537]: chan_sip.c:4761 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Oct 1 13:02:46] DEBUG[21537]: chan_sip.c:2258 __sip_ack: Stopping retransmission on '5e23175a34518f365b9e9c2a2e953722@192.168.30.165' of Request 102: Match Found [Oct 1 13:02:46] DEBUG[21537]: chan_sip.c:2258 __sip_ack: Stopping retransmission on '11afc6a17c4f446b2e33693518ba5631@192.168.30.165' of Request 102: Match Found Really destroying SIP dialog '11afc6a17c4f446b2e33693518ba5631@192.168.30.165' Method: OPTIONS Really destroying SIP dialog '5e23175a34518f365b9e9c2a2e953722@192.168.30.165' Method: OPTIONS Really destroying SIP dialog '52ddad3e3a6633187d98a24055fd05d2@192.168.30.165' Method: OPTIONS [Oct 1 13:02:46] DEBUG[21537]: chan_sip.c:4761 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Oct 1 13:02:46] DEBUG[21537]: chan_sip.c:4761 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Oct 1 13:02:46] DEBUG[21537]: chan_sip.c:2258 __sip_ack: Stopping retransmission on '5edaab99131bf79b66defd8f548c5e00@192.168.30.165' of Request 102: Match Found [Oct 1 13:02:46] DEBUG[21537]: chan_sip.c:4761 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Oct 1 13:02:46] DEBUG[21537]: chan_sip.c:2258 __sip_ack: Stopping retransmission on '45c1fbf345d589e8180aeb75787cf2ff@192.168.30.165' of Request 102: Match Found [Oct 1 13:02:46] DEBUG[21537]: chan_sip.c:2258 __sip_ack: Stopping retransmission on '7d384ed45b10d897656073ab33711d6f@192.168.30.165' of Request 102: Match Found [Oct 1 13:02:46] DEBUG[21537]: chan_sip.c:4761 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Oct 1 13:02:46] DEBUG[21537]: chan_sip.c:2258 __sip_ack: Stopping retransmission on '0380977c5e815be62041c9df472ab75b@192.168.30.165' of Request 102: Match Found Really destroying SIP dialog '0380977c5e815be62041c9df472ab75b@192.168.30.165' Method: OPTIONS Really destroying SIP dialog '7d384ed45b10d897656073ab33711d6f@192.168.30.165' Method: OPTIONS Really destroying SIP dialog '45c1fbf345d589e8180aeb75787cf2ff@192.168.30.165' Method: OPTIONS Really destroying SIP dialog '5edaab99131bf79b66defd8f548c5e00@192.168.30.165' Method: OPTIONS [Oct 1 13:02:46] DEBUG[21537]: chan_sip.c:4761 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Oct 1 13:02:46] DEBUG[21537]: chan_sip.c:4761 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Oct 1 13:02:46] DEBUG[21537]: chan_sip.c:2258 __sip_ack: Stopping retransmission on '67b99a3c465aaa8a698ee70e41cb1989@192.168.30.165' of Request 102: Match Found [Oct 1 13:02:46] DEBUG[21537]: chan_sip.c:2258 __sip_ack: Stopping retransmission on '2fd5146f11d8c1502a8d83a03337acae@192.168.30.165' of Request 102: Match Found Really destroying SIP dialog '2fd5146f11d8c1502a8d83a03337acae@192.168.30.165' Method: OPTIONS Really destroying SIP dialog '67b99a3c465aaa8a698ee70e41cb1989@192.168.30.165' Method: OPTIONS [Oct 1 13:02:46] DEBUG[1033]: rtp.c:923 ast_rtcp_read: Got RTCP report of 64 bytes [Oct 1 13:02:46] DEBUG[21537]: chan_sip.c:4761 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Oct 1 13:02:46] DEBUG[21537]: chan_sip.c:2258 __sip_ack: Stopping retransmission on '06571fc861799b67511d268d0d7b90cc@192.168.30.165' of Request 102: Match Found Really destroying SIP dialog '06571fc861799b67511d268d0d7b90cc@192.168.30.165' Method: OPTIONS [Oct 1 13:02:46] DEBUG[21537]: chan_sip.c:4761 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Oct 1 13:02:46] DEBUG[21537]: chan_sip.c:2258 __sip_ack: Stopping retransmission on '2472bac823aeed685057dd96419b5815@192.168.30.165' of Request 102: Match Found [Oct 1 13:02:46] DEBUG[21537]: chan_sip.c:4761 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Oct 1 13:02:46] DEBUG[21537]: chan_sip.c:2258 __sip_ack: Stopping retransmission on '23ee4b9b379e1ba93a44f0de6f61ed65@192.168.30.165' of Request 102: Match Found Really destroying SIP dialog '23ee4b9b379e1ba93a44f0de6f61ed65@192.168.30.165' Method: OPTIONS Really destroying SIP dialog '2472bac823aeed685057dd96419b5815@192.168.30.165' Method: OPTIONS [Oct 1 13:02:46] DEBUG[657]: rtp.c:923 ast_rtcp_read: Got RTCP report of 64 bytes [Oct 1 13:02:46] DEBUG[21537]: chan_sip.c:4761 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Oct 1 13:02:46] DEBUG[21537]: chan_sip.c:4761 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Oct 1 13:02:46] DEBUG[21537]: chan_sip.c:2258 __sip_ack: Stopping retransmission on '2e6aae7a044a32ea25077e123ffd389e@192.168.30.165' of Request 102: Match Found [Oct 1 13:02:46] DEBUG[21537]: chan_sip.c:2258 __sip_ack: Stopping retransmission on '245b001d791c070461f8194b2b39d674@192.168.30.165' of Request 102: Match Found Really destroying SIP dialog '245b001d791c070461f8194b2b39d674@192.168.30.165' Method: OPTIONS Really destroying SIP dialog '2e6aae7a044a32ea25077e123ffd389e@192.168.30.165' Method: OPTIONS [Oct 1 13:02:46] DEBUG[686]: rtp.c:923 ast_rtcp_read: Got RTCP report of 64 bytes [Oct 1 13:02:46] DEBUG[32728]: rtp.c:923 ast_rtcp_read: Got RTCP report of 64 bytes [Oct 1 13:02:46] DEBUG[1036]: rtp.c:923 ast_rtcp_read: Got RTCP report of 64 bytes [Oct 1 13:02:47] DEBUG[32718]: rtp.c:923 ast_rtcp_read: Got RTCP report of 64 bytes [Oct 1 13:02:47] DEBUG[21537]: chan_sip.c:1706 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 305d8347565dadbc4e4143ae6a67eace@192.168.30.254 [Oct 1 13:02:47] DEBUG[21537]: chan_sip.c:15825 handle_request_bye: Received bye, issuing owner hangup [Oct 1 13:02:47] DEBUG[575]: channel.c:4270 ast_generic_bridge: Didn't get a frame from channel: SIP/siptrunk-b484b4e8 [Oct 1 13:02:47] DEBUG[575]: channel.c:4637 ast_channel_bridge: Bridge stops bridging channels SIP/siptrunk-b484b4e8 and Local/1636@default-agent-734c,1 [Oct 1 13:02:47] DEBUG[575]: pbx.c:1843 pbx_extension_helper: Launching 'Goto' -- Executing [h@default-application-acd-queue-new-english:1] Goto("SIP/siptrunk-b484b4e8", "all-hangup|s|1") in new stack -- Goto (all-hangup,s,1) [Oct 1 13:02:47] DEBUG[575]: pbx.c:1759 pbx_substitute_variables_helper_full: Expression result is '0' [Oct 1 13:02:47] DEBUG[575]: pbx.c:1759 pbx_substitute_variables_helper_full: Expression result is '2' [Oct 1 13:02:47] DEBUG[575]: pbx.c:1843 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@all-hangup:1] GotoIf("SIP/siptrunk-b484b4e8", "0?all-faxnotify|s|1:2") in new stack -- Goto (all-hangup,s,2) [Oct 1 13:02:47] DEBUG[575]: pbx.c:1843 pbx_extension_helper: Launching 'ResetCDR' -- Executing [s@all-hangup:2] ResetCDR("SIP/siptrunk-b484b4e8", "w") in new stack [Oct 1 13:02:47] DEBUG[575]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '"queue-E:1030" <1030>' [Oct 1 13:02:47] DEBUG[575]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '1030' [Oct 1 13:02:47] DEBUG[575]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is 's' [Oct 1 13:02:47] DEBUG[575]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is 'default-application-acd-queue-new-english' [Oct 1 13:02:47] DEBUG[575]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is 'SIP/siptrunk-b484b4e8' [Oct 1 13:02:47] DEBUG[575]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is 'Local/1636@default-agent-734c,1' [Oct 1 13:02:47] DEBUG[575]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is 'Queue' [Oct 1 13:02:47] DEBUG[575]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is 'default-queue-new-english|tH|||60|' [Oct 1 13:02:47] DEBUG[575]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '2009-10-01 13:01:18' [Oct 1 13:02:47] DEBUG[575]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '2009-10-01 13:01:18' [Oct 1 13:02:47] DEBUG[575]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '2009-10-01 13:02:47' [Oct 1 13:02:47] DEBUG[575]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '89' [Oct 1 13:02:47] DEBUG[575]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '89' [Oct 1 13:02:47] DEBUG[575]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is 'ANSWERED' [Oct 1 13:02:47] DEBUG[575]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' [Oct 1 13:02:47] DEBUG[575]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is 'siptrunk' [Oct 1 13:02:47] DEBUG[575]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '1254416478.32796' [Oct 1 13:02:47] DEBUG[575]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '5000' [Oct 1 13:02:47] DEBUG[575]: pbx.c:1843 pbx_extension_helper: Launching 'NoCDR' -- Executing [s@all-hangup:3] NoCDR("SIP/siptrunk-b484b4e8", "") in new stack [Oct 1 13:02:47] DEBUG[575]: pbx.c:1843 pbx_extension_helper: Launching 'System' -- Executing [s@all-hangup:4] System("SIP/siptrunk-b484b4e8", "/var/www/scopserv/telephony/scripts/billing/cdr.sh 1254416478.32796") in new stack [Oct 1 13:02:47] DEBUG[836]: rtp.c:923 ast_rtcp_read: Got RTCP report of 64 bytes [Oct 1 13:02:47] DEBUG[688]: rtp.c:923 ast_rtcp_read: Got RTCP report of 64 bytes [Oct 1 13:02:47] WARNING[32718]: channel.c:953 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/1649@default-agent-8ea1,1 [Oct 1 13:02:47] WARNING[32718]: channel.c:953 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/1649@default-agent-8ea1,1 [Oct 1 13:02:47] DEBUG[1055]: rtp.c:923 ast_rtcp_read: Got RTCP report of 64 bytes [Oct 1 13:02:47] WARNING[32718]: channel.c:953 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/1649@default-agent-8ea1,1 [Oct 1 13:02:47] DEBUG[891]: rtp.c:923 ast_rtcp_read: Got RTCP report of 64 bytes [Oct 1 13:02:47] WARNING[32718]: channel.c:953 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/1649@default-agent-8ea1,1 [Oct 1 13:02:47] WARNING[32718]: channel.c:953 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/1649@default-agent-8ea1,1 [Oct 1 13:02:47] DEBUG[1090]: rtp.c:923 ast_rtcp_read: Got RTCP report of 64 bytes [Oct 1 13:02:47] WARNING[32718]: channel.c:953 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/1649@default-agent-8ea1,1 [Oct 1 13:02:47] WARNING[32718]: channel.c:953 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/1649@default-agent-8ea1,1 [Oct 1 13:02:47] WARNING[32718]: channel.c:953 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/1649@default-agent-8ea1,1 [Oct 1 13:02:47] WARNING[32718]: channel.c:953 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/1649@default-agent-8ea1,1 [Oct 1 13:02:47] WARNING[32718]: channel.c:953 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/1649@default-agent-8ea1,1 [Oct 1 13:02:47] WARNING[32718]: channel.c:953 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/1649@default-agent-8ea1,1 [Oct 1 13:02:47] WARNING[32718]: channel.c:953 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/1649@default-agent-8ea1,1 [Oct 1 13:02:47] WARNING[32718]: channel.c:953 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/1649@default-agent-8ea1,1 [Oct 1 13:02:47] WARNING[32718]: channel.c:953 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/1649@default-agent-8ea1,1 [Oct 1 13:02:47] DEBUG[32716]: channel.c:1564 ast_hangup: Hanging up channel 'Local/1649@default-agent-8ea1,1' [Oct 1 13:02:47] DEBUG[32718]: channel.c:4270 ast_generic_bridge: Didn't get a frame from channel: Local/1649@default-agent-8ea1,2 [Oct 1 13:02:47] DEBUG[32718]: channel.c:4637 ast_channel_bridge: Bridge stops bridging channels Local/1649@default-agent-8ea1,2 and SIP/1649-098a1c88 [Oct 1 13:02:47] DEBUG[32716]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel Local/1649@default-agent [Oct 1 13:02:47] DEBUG[32716]: pbx.c:2392 __ast_pbx_run: Spawn extension (all-hangup,s,13) exited non-zero on 'SIP/siptrunk-b4c4ed78' == Spawn extension (all-hangup, s, 13) exited non-zero on 'SIP/siptrunk-b4c4ed78' [Oct 1 13:02:47] DEBUG[32716]: channel.c:1461 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/siptrunk-b4c4ed78' [Oct 1 13:02:47] DEBUG[32718]: channel.c:1564 ast_hangup: Hanging up channel 'SIP/1649-098a1c88' [Oct 1 13:02:47] DEBUG[32718]: chan_sip.c:3683 sip_hangup: Hangup call SIP/1649-098a1c88, SIP callid 3f3a52b113233b2204061feb22e91275@192.168.30.165) [Oct 1 13:02:47] DEBUG[32718]: chan_sip.c:3366 update_call_counter: Updating call counter for outgoing call [Oct 1 13:02:47] DEBUG[32716]: channel.c:1564 ast_hangup: Hanging up channel 'SIP/siptrunk-b4c4ed78' [Oct 1 13:02:47] DEBUG[32716]: chan_sip.c:3683 sip_hangup: Hangup call SIP/siptrunk-b4c4ed78, SIP callid 455533282313449738eb349b6f8775f3@192.168.30.254) [Oct 1 13:02:47] DEBUG[21436]: chan_local.c:145 local_devicestate: Checking if extension 1649@default-agent exists (devicestate) [Oct 1 13:02:47] DEBUG[21436]: devicestate.c:287 do_state_change: Changing state for Local/1649@default-agent - state 2 (In use) [Oct 1 13:02:47] DEBUG[32716]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/siptrunk [Oct 1 13:02:47] DEBUG[21436]: chan_sip.c:17064 sip_devicestate: Checking device state for peer siptrunk [Oct 1 13:02:47] DEBUG[21436]: devicestate.c:287 do_state_change: Changing state for SIP/siptrunk - state 1 (Not in use) [Oct 1 13:02:47] DEBUG[21525]: app_queue.c:675 handle_statechange: Device 'Local/1649@default-agent' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Oct 1 13:02:47] DEBUG[21525]: app_queue.c:675 handle_statechange: Device 'SIP/siptrunk' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Oct 1 13:02:47] DEBUG[32718]: chan_sip.c:3417 update_call_counter: Call to peer '1649' removed from call limit 16 [Oct 1 13:02:47] DEBUG[32718]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/1649 [Oct 1 13:02:47] DEBUG[32718]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/1649 [Oct 1 13:02:47] DEBUG[32718]: rtp.c:1559 ast_rtp_early_bridge: Channel 'Local/1649@default-agent-8ea1,2' has no RTP, not doing anything [Oct 1 13:02:47] DEBUG[32718]: app_dial.c:1824 dial_exec_full: Exiting with DIALSTATUS=ANSWER. [Oct 1 13:02:47] DEBUG[32718]: pbx.c:2392 __ast_pbx_run: Spawn extension (default-local-devices,1649,3) exited non-zero on 'Local/1649@default-agent-8ea1,2' == Spawn extension (default-local-devices, 1649, 3) exited non-zero on 'Local/1649@default-agent-8ea1,2' [Oct 1 13:02:47] DEBUG[32718]: channel.c:1461 ast_softhangup_nolock: Soft-Hanging up channel 'Local/1649@default-agent-8ea1,2' [Oct 1 13:02:47] DEBUG[32718]: channel.c:1564 ast_hangup: Hanging up channel 'Local/1649@default-agent-8ea1,2' [Oct 1 13:02:47] DEBUG[32718]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel Local/1649@default-agent [Oct 1 13:02:47] DEBUG[21436]: chan_sip.c:17064 sip_devicestate: Checking device state for peer 1649 [Oct 1 13:02:47] DEBUG[21436]: devicestate.c:287 do_state_change: Changing state for SIP/1649 - state 1 (Not in use) [Oct 1 13:02:47] DEBUG[21436]: chan_sip.c:17064 sip_devicestate: Checking device state for peer 1649 [Oct 1 13:02:47] DEBUG[21436]: chan_sip.c:17064 sip_devicestate: Checking device state for peer 1649 [Oct 1 13:02:47] DEBUG[21436]: devicestate.c:287 do_state_change: Changing state for SIP/1649 - state 1 (Not in use) [Oct 1 13:02:47] DEBUG[21436]: chan_sip.c:17064 sip_devicestate: Checking device state for peer 1649 [Oct 1 13:02:47] DEBUG[21436]: chan_local.c:145 local_devicestate: Checking if extension 1649@default-agent exists (devicestate) [Oct 1 13:02:47] DEBUG[21436]: devicestate.c:287 do_state_change: Changing state for Local/1649@default-agent - state 1 (Not in use) [Oct 1 13:02:47] DEBUG[21537]: chan_sip.c:2258 __sip_ack: Stopping retransmission on '3f3a52b113233b2204061feb22e91275@192.168.30.165' of Request 103: Match Found [Oct 1 13:02:47] DEBUG[21525]: app_queue.c:680 handle_statechange: Device 'SIP/1649' changed to state '1' (Not in use) [Oct 1 13:02:47] DEBUG[21525]: app_queue.c:680 handle_statechange: Device 'SIP/1649' changed to state '1' (Not in use) [Oct 1 13:02:47] DEBUG[21525]: app_queue.c:675 handle_statechange: Device 'Local/1649@default-agent' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. Really destroying SIP dialog '3f3a52b113233b2204061feb22e91275@192.168.30.165' Method: INVITE Really destroying SIP dialog '455533282313449738eb349b6f8775f3@192.168.30.254' Method: BYE [Oct 1 13:02:47] DEBUG[1057]: rtp.c:923 ast_rtcp_read: Got RTCP report of 64 bytes [Oct 1 13:02:47] DEBUG[21537]: chan_sip.c:4761 sip_alloc: Allocating new SIP dialog for 46bb75636cb1464f1be500845642bde3@192.168.30.165 - REGISTER (No RTP) [Oct 1 13:02:47] DEBUG[21537]: chan_sip.c:8038 transmit_register: Scheduled a registration timeout for 192.168.30.254 id #1106439 [Oct 1 13:02:47] DEBUG[21537]: chan_sip.c:2300 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '46bb75636cb1464f1be500845642bde3@192.168.30.165' Request 1955: Found [Oct 1 13:02:47] DEBUG[21537]: chan_sip.c:2258 __sip_ack: Stopping retransmission on '46bb75636cb1464f1be500845642bde3@192.168.30.165' of Request 1955: Match Found [Oct 1 13:02:47] DEBUG[21537]: chan_sip.c:1694 initialize_initreq: Initializing already initialized SIP dialog 46bb75636cb1464f1be500845642bde3@192.168.30.165 (presumably reinvite) [Oct 1 13:02:47] DEBUG[21537]: chan_sip.c:2300 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '46bb75636cb1464f1be500845642bde3@192.168.30.165' Request 1956: Found [Oct 1 13:02:48] DEBUG[21537]: chan_sip.c:2258 __sip_ack: Stopping retransmission on '46bb75636cb1464f1be500845642bde3@192.168.30.165' of Request 1956: Match Found [Oct 1 13:02:48] DEBUG[21537]: chan_sip.c:13138 handle_response_register: Registration successful [Oct 1 13:02:48] DEBUG[21537]: chan_sip.c:13141 handle_response_register: Cancelling timeout 1106439 [Oct 1 13:02:48] DEBUG[896]: rtp.c:923 ast_rtcp_read: Got RTCP report of 64 bytes [Oct 1 13:02:48] DEBUG[841]: rtp.c:923 ast_rtcp_read: Got RTCP report of 64 bytes [Oct 1 13:02:48] DEBUG[1093]: rtp.c:923 ast_rtcp_read: Got RTCP report of 64 bytes [Oct 1 13:02:48] DEBUG[32730]: rtp.c:923 ast_rtcp_read: Got RTCP report of 64 bytes [Oct 1 13:02:48] DEBUG[419]: rtp.c:923 ast_rtcp_read: Got RTCP report of 64 bytes [Oct 1 13:02:49] DEBUG[1118]: rtp.c:923 ast_rtcp_read: Got RTCP report of 64 bytes [Oct 1 13:02:49] DEBUG[621]: rtp.c:923 ast_rtcp_read: Got RTCP report of 64 bytes [Oct 1 13:02:49] WARNING[579]: channel.c:953 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/1636@default-agent-734c,1 [Oct 1 13:02:49] WARNING[579]: channel.c:953 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/1636@default-agent-734c,1 [Oct 1 13:02:49] WARNING[579]: channel.c:953 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/1636@default-agent-734c,1 [Oct 1 13:02:49] WARNING[579]: channel.c:953 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/1636@default-agent-734c,1 [Oct 1 13:02:49] WARNING[579]: channel.c:953 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/1636@default-agent-734c,1 [Oct 1 13:02:49] WARNING[579]: channel.c:953 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/1636@default-agent-734c,1 [Oct 1 13:02:49] WARNING[579]: channel.c:953 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/1636@default-agent-734c,1 [Oct 1 13:02:49] WARNING[579]: channel.c:953 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/1636@default-agent-734c,1 [Oct 1 13:02:49] DEBUG[425]: rtp.c:923 ast_rtcp_read: Got RTCP report of 64 bytes [Oct 1 13:02:49] DEBUG[579]: rtp.c:923 ast_rtcp_read: Got RTCP report of 64 bytes [Oct 1 13:02:49] WARNING[579]: channel.c:953 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/1636@default-agent-734c,1 [Oct 1 13:02:49] WARNING[579]: channel.c:953 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/1636@default-agent-734c,1 [Oct 1 13:02:49] WARNING[579]: channel.c:953 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/1636@default-agent-734c,1 [Oct 1 13:02:49] WARNING[579]: channel.c:953 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/1636@default-agent-734c,1 [Oct 1 13:02:49] WARNING[579]: channel.c:953 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/1636@default-agent-734c,1 [Oct 1 13:02:49] DEBUG[21537]: chan_sip.c:4761 sip_alloc: Allocating new SIP dialog for 1da3918c6cf08c710ca4cdbb1432e4b5@127.0.0.1 - REGISTER (No RTP) [Oct 1 13:02:49] WARNING[579]: channel.c:953 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/1636@default-agent-734c,1 [Oct 1 13:02:49] WARNING[579]: channel.c:953 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/1636@default-agent-734c,1 [Oct 1 13:02:49] WARNING[579]: channel.c:953 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/1636@default-agent-734c,1 [Oct 1 13:02:49] WARNING[579]: channel.c:953 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/1636@default-agent-734c,1 [Oct 1 13:02:49] WARNING[579]: channel.c:953 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/1636@default-agent-734c,1 [Oct 1 13:02:49] DEBUG[21537]: chan_sip.c:4761 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Oct 1 13:02:49] DEBUG[21537]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/1625 [Oct 1 13:02:49] DEBUG[21436]: chan_sip.c:17064 sip_devicestate: Checking device state for peer 1625 [Oct 1 13:02:49] DEBUG[21436]: devicestate.c:287 do_state_change: Changing state for SIP/1625 - state 1 (Not in use) [Oct 1 13:02:49] DEBUG[21436]: chan_sip.c:17064 sip_devicestate: Checking device state for peer 1625 [Oct 1 13:02:49] DEBUG[21537]: chan_sip.c:4761 sip_alloc: Allocating new SIP dialog for 00be15f61dd17fc8116f53f557469211@127.0.0.1 - REGISTER (No RTP) [Oct 1 13:02:49] DEBUG[21525]: app_queue.c:680 handle_statechange: Device 'SIP/1625' changed to state '1' (Not in use) [Oct 1 13:02:49] WARNING[579]: channel.c:953 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/1636@default-agent-734c,1 [Oct 1 13:02:49] DEBUG[21537]: chan_sip.c:4761 sip_alloc: Allocating new SIP dialog for 18392b4920870ea05e7cbae45a5376b7@127.0.0.1 - REGISTER (No RTP) [Oct 1 13:02:49] DEBUG[21537]: chan_sip.c:4761 sip_alloc: Allocating new SIP dialog for 7271945954d256c95c3f3806527d4d0c@127.0.0.1 - REGISTER (No RTP) [Oct 1 13:02:49] DEBUG[21537]: chan_sip.c:2258 __sip_ack: Stopping retransmission on '2b941f172a5c5f9c02d7bca60cb0fef3@192.168.30.165' of Request 102: Match Found [Oct 1 13:02:49] WARNING[579]: channel.c:953 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/1636@default-agent-734c,1 [Oct 1 13:02:49] DEBUG[21537]: chan_sip.c:4761 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Oct 1 13:02:49] DEBUG[21537]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/1675 [Oct 1 13:02:49] DEBUG[21436]: chan_sip.c:17064 sip_devicestate: Checking device state for peer 1675 [Oct 1 13:02:49] DEBUG[21436]: devicestate.c:287 do_state_change: Changing state for SIP/1675 - state 1 (Not in use) [Oct 1 13:02:49] DEBUG[21525]: app_queue.c:675 handle_statechange: Device 'SIP/1675' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Oct 1 13:02:49] DEBUG[21436]: chan_sip.c:17064 sip_devicestate: Checking device state for peer 1675 [Oct 1 13:02:49] DEBUG[21537]: chan_sip.c:4761 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Oct 1 13:02:49] DEBUG[21537]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/1687 [Oct 1 13:02:49] DEBUG[21436]: chan_sip.c:17064 sip_devicestate: Checking device state for peer 1687 [Oct 1 13:02:49] DEBUG[21436]: devicestate.c:287 do_state_change: Changing state for SIP/1687 - state 1 (Not in use) [Oct 1 13:02:49] DEBUG[21436]: chan_sip.c:17064 sip_devicestate: Checking device state for peer 1687 [Oct 1 13:02:49] DEBUG[21525]: app_queue.c:675 handle_statechange: Device 'SIP/1687' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Oct 1 13:02:49] WARNING[579]: channel.c:953 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/1636@default-agent-734c,1 [Oct 1 13:02:49] DEBUG[21537]: chan_sip.c:4761 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Oct 1 13:02:49] DEBUG[21537]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/1677 [Oct 1 13:02:49] DEBUG[21436]: chan_sip.c:17064 sip_devicestate: Checking device state for peer 1677 [Oct 1 13:02:49] DEBUG[21436]: devicestate.c:287 do_state_change: Changing state for SIP/1677 - state 1 (Not in use) [Oct 1 13:02:49] DEBUG[21436]: chan_sip.c:17064 sip_devicestate: Checking device state for peer 1677 [Oct 1 13:02:49] DEBUG[21525]: app_queue.c:675 handle_statechange: Device 'SIP/1677' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Oct 1 13:02:49] DEBUG[21537]: chan_sip.c:2258 __sip_ack: Stopping retransmission on '3360b3d46da5a4b25d0792186f108e91@192.168.30.165' of Request 102: Match Found [Oct 1 13:02:49] DEBUG[21537]: chan_sip.c:2258 __sip_ack: Stopping retransmission on '5c830089018a7e9b4187b7394c961036@192.168.30.165' of Request 102: Match Found [Oct 1 13:02:49] DEBUG[21537]: chan_sip.c:2258 __sip_ack: Stopping retransmission on '093bf5886b340ed3166de5481c9005b9@192.168.30.165' of Request 102: Match Found [Oct 1 13:02:49] WARNING[579]: channel.c:953 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/1636@default-agent-734c,1 [Oct 1 13:02:49] WARNING[579]: channel.c:953 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/1636@default-agent-734c,1 Really destroying SIP dialog '093bf5886b340ed3166de5481c9005b9@192.168.30.165' Method: OPTIONS Really destroying SIP dialog '5c830089018a7e9b4187b7394c961036@192.168.30.165' Method: OPTIONS Really destroying SIP dialog '3360b3d46da5a4b25d0792186f108e91@192.168.30.165' Method: OPTIONS Really destroying SIP dialog '2b941f172a5c5f9c02d7bca60cb0fef3@192.168.30.165' Method: OPTIONS [Oct 1 13:02:49] WARNING[579]: channel.c:953 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/1636@default-agent-734c,1 [Oct 1 13:02:49] WARNING[579]: channel.c:953 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/1636@default-agent-734c,1 [Oct 1 13:02:49] WARNING[579]: channel.c:953 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/1636@default-agent-734c,1 [Oct 1 13:02:49] WARNING[579]: channel.c:953 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/1636@default-agent-734c,1 [Oct 1 13:02:49] WARNING[579]: channel.c:953 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/1636@default-agent-734c,1 [Oct 1 13:02:49] WARNING[579]: channel.c:953 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/1636@default-agent-734c,1 [Oct 1 13:02:49] WARNING[579]: channel.c:953 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/1636@default-agent-734c,1 [Oct 1 13:02:49] DEBUG[1120]: rtp.c:923 ast_rtcp_read: Got RTCP report of 64 bytes [Oct 1 13:02:49] WARNING[579]: channel.c:953 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/1636@default-agent-734c,1 [Oct 1 13:02:49] WARNING[579]: channel.c:953 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/1636@default-agent-734c,1 [Oct 1 13:02:49] WARNING[579]: channel.c:953 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/1636@default-agent-734c,1 [Oct 1 13:02:49] WARNING[579]: channel.c:953 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/1636@default-agent-734c,1 [Oct 1 13:02:49] WARNING[579]: channel.c:953 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/1636@default-agent-734c,1 [Oct 1 13:02:50] WARNING[579]: channel.c:953 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/1636@default-agent-734c,1 [Oct 1 13:02:50] WARNING[579]: channel.c:953 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/1636@default-agent-734c,1 [Oct 1 13:02:50] WARNING[579]: channel.c:953 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/1636@default-agent-734c,1 [Oct 1 13:02:50] WARNING[579]: channel.c:953 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/1636@default-agent-734c,1 [Oct 1 13:02:50] WARNING[579]: channel.c:953 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/1636@default-agent-734c,1 [Oct 1 13:02:50] WARNING[579]: channel.c:953 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/1636@default-agent-734c,1 [Oct 1 13:02:50] DEBUG[32628]: rtp.c:923 ast_rtcp_read: Got RTCP report of 64 bytes [Oct 1 13:02:50] WARNING[579]: channel.c:953 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/1636@default-agent-734c,1 [Oct 1 13:02:50] WARNING[579]: channel.c:953 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/1636@default-agent-734c,1 [Oct 1 13:02:50] WARNING[579]: channel.c:953 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/1636@default-agent-734c,1 [Oct 1 13:02:50] DEBUG[634]: rtp.c:923 ast_rtcp_read: Got RTCP report of 64 bytes [Oct 1 13:02:50] WARNING[579]: channel.c:953 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/1636@default-agent-734c,1 [Oct 1 13:02:50] WARNING[579]: channel.c:953 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/1636@default-agent-734c,1 [Oct 1 13:02:50] WARNING[579]: channel.c:953 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/1636@default-agent-734c,1 [Oct 1 13:02:50] WARNING[579]: channel.c:953 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/1636@default-agent-734c,1 [Oct 1 13:02:50] WARNING[579]: channel.c:953 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/1636@default-agent-734c,1 [Oct 1 13:02:50] WARNING[579]: channel.c:953 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/1636@default-agent-734c,1 [Oct 1 13:02:50] WARNING[579]: channel.c:953 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/1636@default-agent-734c,1