=~=~=~=~=~=~=~=~=~=~=~= PuTTY log 2006.11.14 18:36:21 =~=~=~=~=~=~=~=~=~=~=~= [Nov 15 02:36:25] DEBUG[13971]: chan_sip.c:14522 sipsock_read: Invalid SIP message - rejected , no callid, len 334 stealth*CLI> [Nov 15 02:36:25] DEBUG[13971]: chan_sip.c:14522 sipsock_read: Invalid SIP message - rejected , no callid, len 331 stealth*CLI> [Nov 15 02:36:28] DEBUG[13971]: chan_sip.c:2534 do_setnat: Setting NAT on RTP to Off [Nov 15 02:36:28] DEBUG[13971]: chan_sip.c:2544 do_setnat: Setting NAT on UDPTL to Off [Nov 15 02:36:28] DEBUG[13971]: chan_sip.c:4224 sip_alloc: Allocating new SIP dialog for 446bfa32-6c0a0418@192.168.4.196 - INVITE (With RTP) [Nov 15 02:36:28] DEBUG[13971]: chan_sip.c:2534 do_setnat: Setting NAT on RTP to On [Nov 15 02:36:28] DEBUG[13971]: chan_sip.c:2544 do_setnat: Setting NAT on UDPTL to On stealth*CLI> [Nov 15 02:36:29] DEBUG[13971]: chan_sip.c:2047 __sip_ack: Stopping retransmission on '446bfa32-6c0a0418@192.168.4.196' of Response 101: Match Not Found stealth*CLI> [Nov 15 02:36:29] DEBUG[13971]: chan_sip.c:2534 do_setnat: Setting NAT on RTP to On [Nov 15 02:36:29] DEBUG[13971]: chan_sip.c:2544 do_setnat: Setting NAT on UDPTL to On [Nov 15 02:36:29] DEBUG[13971]: chan_sip.c:5015 process_sdp: T38 state changed to 0 on channel [Nov 15 02:36:29] DEBUG[13971]: chan_sip.c:5092 process_sdp: We're settling with these formats: 0xc (ulaw|alaw) [Nov 15 02:36:29] DEBUG[13971]: chan_sip.c:13136 handle_request_invite: Checking SIP call limits for device 201 [Nov 15 02:36:29] DEBUG[13971]: chan_sip.c:2950 update_call_counter: Updating call counter for incoming call [Nov 15 02:36:29] DEBUG[13971]: chan_sip.c:3022 update_call_counter: Call from peer '201' is 1 out of 0 [Nov 15 02:36:29] DEBUG[13971]: devicestate.c:314 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/201 [Nov 15 02:36:29] DEBUG[13971]: chan_sip.c:3731 sip_new: *** Our native formats are 0x4 (ulaw) [Nov 15 02:36:29] DEBUG[13971]: chan_sip.c:3732 sip_new: *** Joint capabilities are 0xc (ulaw|alaw) [Nov 15 02:36:29] DEBUG[13971]: chan_sip.c:3733 sip_new: *** Our capabilities are 0xe (gsm|ulaw|alaw) [Nov 15 02:36:29] DEBUG[13971]: chan_sip.c:3734 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Nov 15 02:36:29] DEBUG[13971]: chan_sip.c:3757 sip_new: This channel will not be able to handle video. [Nov 15 02:36:29] DEBUG[13971]: chan_sip.c:7828 build_route: build_route: Contact hop: Ronald Chan [Nov 15 02:36:29] DEBUG[13971]: chan_sip.c:13209 handle_request_invite: SIP/201-09e2d830: New call is still down.... Trying... stealth*CLI> [Nov 15 02:36:29] DEBUG[13971]: devicestate.c:314 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/201-09e2d830 stealth*CLI> [Nov 15 02:36:29] DEBUG[13966]: chan_sip.c:14932 sip_devicestate: Checking device state for peer 201 [Nov 15 02:36:29] NOTICE[13966]: chan_sip.c:14972 sip_devicestate: sip_devicestate(201) returning In use call-lim=0, inuse=1, onHold=0, inRinging=0, maxms=0, lastms=0 [Nov 15 02:36:29] DEBUG[13966]: devicestate.c:298 do_state_change: Changing state for SIP/201 - state 2 (In use) [Nov 15 02:36:29] DEBUG[13966]: chan_sip.c:14932 sip_devicestate: Checking device state for peer 201 [Nov 15 02:36:29] NOTICE[13966]: chan_sip.c:14972 sip_devicestate: sip_devicestate(201) returning In use call-lim=0, inuse=1, onHold=0, inRinging=0, maxms=0, lastms=0 [Nov 15 02:36:29] DEBUG[13966]: devicestate.c:298 do_state_change: Changing state for SIP/201 - state 2 (In use) stealth*CLI> [Nov 15 02:36:29] DEBUG[14666]: pbx.c:1767 pbx_extension_helper: Launching 'Macro' stealth*CLI> -- Executing [97533707@internal:1] Macro("SIP/201-09e2d830", "extensions|Zap/g1|7533707") in new stack stealth*CLI> [Nov 15 02:36:29] DEBUG[14666]: pbx.c:1688 pbx_substitute_variables_helper_full: Expression result is '0' stealth*CLI> [Nov 15 02:36:29] DEBUG[14666]: pbx.c:1767 pbx_extension_helper: Launching 'GotoIf' stealth*CLI> -- Executing [s@macro-extensions:1] GotoIf("SIP/201-09e2d830", "0?s|intercom") in new stack stealth*CLI> [Nov 15 02:36:29] DEBUG[14666]: pbx.c:5932 pbx_builtin_gotoif: Not taking any branch stealth*CLI> [Nov 15 02:36:29] DEBUG[14666]: pbx.c:1688 pbx_substitute_variables_helper_full: Expression result is '0' stealth*CLI> [Nov 15 02:36:29] DEBUG[14666]: pbx.c:1767 pbx_extension_helper: Launching 'GotoIf' stealth*CLI> -- Executing [s@macro-extensions:2] GotoIf("SIP/201-09e2d830", "0?s|intercom:s|outgoing") in new stack stealth*CLI> -- Goto (macro-extensions,s,3) stealth*CLI> [Nov 15 02:36:29] DEBUG[14666]: pbx.c:1767 pbx_extension_helper: Launching 'Set' stealth*CLI> -- Executing [s@macro-extensions:3] Set("SIP/201-09e2d830", "CALLFILE=OUTGOING-CALL/7533707--1163529389.12.wav") in new stack stealth*CLI> [Nov 15 02:36:29] DEBUG[14666]: pbx.c:1767 pbx_extension_helper: Launching 'Goto' stealth*CLI> -- Executing [s@macro-extensions:4] Goto("SIP/201-09e2d830", "s|mixnow") in new stack stealth*CLI> -- Goto (macro-extensions,s,6) stealth*CLI> [Nov 15 02:36:29] DEBUG[14666]: pbx.c:1767 pbx_extension_helper: Launching 'MixMonitor' stealth*CLI> -- Executing [s@macro-extensions:6] MixMonitor("SIP/201-09e2d830", "OUTGOING-CALL/7533707--1163529389.12.wav|bW(1)") in new stack stealth*CLI> [Nov 15 02:36:29] DEBUG[14666]: channel.c:1263 ast_channel_spy_add: Spy MixMonitor added to channel SIP/201-09e2d830 stealth*CLI> [Nov 15 02:36:29] DEBUG[14666]: pbx.c:1767 pbx_extension_helper: Launching 'Playback' stealth*CLI> -- Executing [s@macro-extensions:7] Playback("SIP/201-09e2d830", "pls-wait-connect-call") in new stack stealth*CLI> [Nov 15 02:36:29] DEBUG[14666]: devicestate.c:314 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/201-09e2d830 stealth*CLI> [Nov 15 02:36:29] DEBUG[13966]: chan_sip.c:14932 sip_devicestate: Checking device state for peer 201 [Nov 15 02:36:29] NOTICE[13966]: chan_sip.c:14972 sip_devicestate: sip_devicestate(201) returning In use call-lim=0, inuse=1, onHold=0, inRinging=0, maxms=0, lastms=0 [Nov 15 02:36:29] DEBUG[13966]: devicestate.c:298 do_state_change: Changing state for SIP/201 - state 2 (In use) stealth*CLI> [Nov 15 02:36:29] DEBUG[14666]: chan_sip.c:3400 sip_answer: SIP answering channel: SIP/201-09e2d830 stealth*CLI> [Nov 15 02:36:29] DEBUG[14666]: chan_sip.c:6297 transmit_response_with_sdp: Setting framing from config on incoming call stealth*CLI> [Nov 15 02:36:29] DEBUG[14666]: chan_sip.c:6065 add_sdp: ** Our capability: 0xc (ulaw|alaw) Video flag: True stealth*CLI> [Nov 15 02:36:29] DEBUG[14666]: chan_sip.c:6066 add_sdp: ** Our prefcodec: 0x0 (nothing) stealth*CLI> [Nov 15 02:36:29] DEBUG[14666]: chan_sip.c:6197 add_sdp: -- Done with adding codecs to SDP stealth*CLI> [Nov 15 02:36:29] DEBUG[14666]: chan_sip.c:6242 add_sdp: Done building SDP. Settling with this capability: 0xc (ulaw|alaw) stealth*CLI> [Nov 15 02:36:29] DEBUG[14666]: channel.c:2731 set_format: Set channel SIP/201-09e2d830 to write format slin stealth*CLI> [Nov 15 02:36:29] DEBUG[14666]: channel.c:1444 queue_frame_to_spies: Building translator from ulaw to SLINEAR for spies on channel SIP/201-09e2d830 stealth*CLI> [Nov 15 02:36:29] DEBUG[14666]: rtp.c:2559 ast_rtp_write: Ooh, format changed from unknown to ulaw stealth*CLI> [Nov 15 02:36:29] DEBUG[14666]: rtp.c:2576 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160 stealth*CLI> [Nov 15 02:36:29] DEBUG[14666]: channel.c:1908 ast_settimeout: Scheduling timer at 160 sample intervals stealth*CLI> -- Playing 'pls-wait-connect-call' (language 'en') stealth*CLI> [Nov 15 02:36:29] DEBUG[14667]: app_queue.c:552 changethread: Device 'SIP/201' changed to state '2' (In use) stealth*CLI> [Nov 15 02:36:29] DEBUG[14668]: app_queue.c:552 changethread: Device 'SIP/201' changed to state '2' (In use) stealth*CLI> [Nov 15 02:36:29] DEBUG[14670]: app_queue.c:552 changethread: Device 'SIP/201' changed to state '2' (In use) stealth*CLI> == Begin MixMonitor Recording SIP/201-09e2d830 stealth*CLI> [Nov 15 02:36:29] DEBUG[13971]: chan_sip.c:2047 __sip_ack: Stopping retransmission on '446bfa32-6c0a0418@192.168.4.196' of Response 102: Match Not Found stealth*CLI> [Nov 15 02:36:29] DEBUG[14666]: channel.c:1444 queue_frame_to_spies: Building translator from ulaw to SLINEAR for spies on channel SIP/201-09e2d830 stealth*CLI> [Nov 15 02:36:31] DEBUG[14666]: channel.c:1908 ast_settimeout: Scheduling timer at 140 sample intervals stealth*CLI> [Nov 15 02:36:31] DEBUG[14666]: channel.c:1908 ast_settimeout: Scheduling timer at 0 sample intervals [Nov 15 02:36:31] DEBUG[14666]: channel.c:1908 ast_settimeout: Scheduling timer at 0 sample intervals [Nov 15 02:36:31] DEBUG[14666]: channel.c:2731 set_format: Set channel SIP/201-09e2d830 to write format ulaw [Nov 15 02:36:31] DEBUG[14666]: pbx.c:1767 pbx_extension_helper: Launching 'Dial' -- Executing [s@macro-extensions:8] Dial("SIP/201-09e2d830", "Zap/g1/7533707|120|tH") in new stack [Nov 15 02:36:31] DEBUG[14666]: chan_zap.c:7794 zt_request: Using channel 4 [Nov 15 02:36:31] DEBUG[14666]: dsp.c:1658 ast_dsp_set_busy_pattern: dsp busy pattern set to 0,0 [Nov 15 02:36:31] DEBUG[14666]: rtp.c:1479 ast_rtp_make_compatible: Channel 'Zap/4-1' has no RTP, not doing anything [Nov 15 02:36:31] DEBUG[14666]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-macro-extensions-s-8. [Nov 15 02:36:31] DEBUG[14666]: channel.c:3185 ast_channel_inherit_variables: Not copying variable MACRO_DEPTH. [Nov 15 02:36:31] DEBUG[14666]: channel.c:3185 ast_channel_inherit_variables: Not copying variable PLAYBACKSTATUS. [Nov 15 02:36:31] DEBUG[14666]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-macro-extensions-s-7. [Nov 15 02:36:31] DEBUG[14666]: channel.c:3185 ast_channel_inherit_variables: Not copying variable MIXMONITOR_FILENAME. [Nov 15 02:36:31] DEBUG[14666]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-macro-extensions-s-6. [Nov 15 02:36:31] DEBUG[14666]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-macro-extensions-s-4. [Nov 15 02:36:31] DEBUG[14666]: channel.c:3185 ast_channel_inherit_variables: Not copying variable CALLFILE. [Nov 15 02:36:31] DEBUG[14666]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-macro-extensions-s-3. [Nov 15 02:36:31] DEBUG[14666]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-macro-extensions-s-2. [Nov 15 02:36:31] DEBUG[14666]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-macro-extensions-s-1. [Nov 15 02:36:31] DEBUG[14666]: channel.c:3185 ast_channel_inherit_variables: Not copying variable ARG2. [Nov 15 02:36:31] DEBUG[14666]: channel.c:3185 ast_channel_inherit_variables: Not copying variable ARG1. [Nov 15 02:36:31] DEBUG[14666]: channel.c:3185 ast_channel_inherit_variables: Not copying variable MACRO_PRIORITY. [Nov 15 02:36:31] DEBUG[14666]: channel.c:3185 ast_channel_inherit_variables: Not copying variable MACRO_CONTEXT. [Nov 15 02:36:31] DEBUG[14666]: channel.c:3185 ast_channel_inherit_variables: Not copying variable MACRO_EXTEN. [Nov 15 02:36:31] DEBUG[14666]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-internal-97533707-1. [Nov 15 02:36:31] DEBUG[14666]: channel.c:3185 ast_channel_inherit_variables: Not copying variable SIPCALLID. [Nov 15 02:36:31] DEBUG[14666]: channel.c:3185 ast_channel_inherit_variables: Not copying variable SIPUSERAGENT. [Nov 15 02:36:31] DEBUG[14666]: channel.c:3185 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [Nov 15 02:36:31] DEBUG[14666]: channel.c:3185 ast_channel_inherit_variables: Not copying variable SIPURI. [Nov 15 02:36:31] DEBUG[14666]: chan_zap.c:1970 zt_call: Dialing '7533707' [Nov 15 02:36:31] DEBUG[14666]: chan_zap.c:2046 zt_call: Deferring dialing... [Nov 15 02:36:31] DEBUG[14666]: devicestate.c:314 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Zap/4-1 -- Called g1/7533707 [Nov 15 02:36:31] DEBUG[13966]: devicestate.c:298 do_state_change: Changing state for Zap/4 - state 2 (In use) stealth*CLI> [Nov 15 02:36:31] DEBUG[14671]: app_queue.c:546 changethread: Device 'Zap/4' changed to state '2' (In use) but we don't care because they're not a member of any queue. stealth*CLI> [Nov 15 02:36:31] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:31] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:31] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:31] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:31] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:31] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:31] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:31] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:31] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:31] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:31] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:31] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:31] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:31] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:31] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:31] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:31] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:31] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:31] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:31] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:31] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:31] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:31] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:31] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:31] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:31] DEBUG[14666]: channel.c:1499 queue_frame_to_spies: Triggering queue flush for spy 'MixMonitor' on 'SIP/201-09e2d830' [Nov 15 02:36:31] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:31] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:31] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:31] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:31] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:31] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:31] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:31] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:31] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:31] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:31] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:31] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:31] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:31] DEBUG[14666]: chan_zap.c:4515 __zt_exception: Exception on 15, channel 4 [Nov 15 02:36:31] DEBUG[14666]: chan_zap.c:3639 zt_handle_event: Got event Hook Transition Complete(12) on channel 4 (index 0) stealth*CLI> [Nov 15 02:36:31] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:31] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:31] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:31] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:31] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:31] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:31] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:32] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:32] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:32] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:32] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:32] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:32] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:32] DEBUG[14666]: channel.c:1499 queue_frame_to_spies: Triggering queue flush for spy 'MixMonitor' on 'SIP/201-09e2d830' [Nov 15 02:36:32] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:32] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:32] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:32] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:32] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:32] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:32] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:32] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:32] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:32] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:32] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:32] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:32] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:32] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:32] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:32] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:32] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:32] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:32] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:32] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:32] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:32] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:32] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:32] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:32] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:32] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:32] DEBUG[14666]: channel.c:1499 queue_frame_to_spies: Triggering queue flush for spy 'MixMonitor' on 'SIP/201-09e2d830' [Nov 15 02:36:32] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:32] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:32] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:32] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:32] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:32] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:32] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:32] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:32] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:32] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:32] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:32] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:32] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:32] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:32] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:32] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:32] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:32] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:33] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:33] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:33] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:33] DEBUG[14666]: chan_zap.c:4515 __zt_exception: Exception on 15, channel 4 [Nov 15 02:36:33] DEBUG[14666]: chan_zap.c:3639 zt_handle_event: Got event Dial Complete(9) on channel 4 (index 0) [Nov 15 02:36:33] DEBUG[14666]: chan_zap.c:1461 zt_enable_ec: Enabled echo cancellation on channel 4 [Nov 15 02:36:33] DEBUG[14666]: chan_zap.c:1477 zt_train_ec: Engaged echo training on channel 4 stealth*CLI> [Nov 15 02:36:33] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:33] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:33] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:33] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:33] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:33] DEBUG[14666]: channel.c:1499 queue_frame_to_spies: Triggering queue flush for spy 'MixMonitor' on 'SIP/201-09e2d830' [Nov 15 02:36:33] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:33] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:33] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:33] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:33] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:33] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:33] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:33] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:33] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:33] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:33] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:33] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:33] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:33] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:33] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:33] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:33] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:33] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:33] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:33] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:33] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:33] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:33] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:33] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:33] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:33] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:33] DEBUG[14666]: channel.c:1499 queue_frame_to_spies: Triggering queue flush for spy 'MixMonitor' on 'SIP/201-09e2d830' [Nov 15 02:36:33] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:33] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:33] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:33] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:33] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:33] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:33] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:33] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:33] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:33] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:33] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:33] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:33] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:33] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:33] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:33] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:34] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:34] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:34] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:34] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:34] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:34] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:34] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:34] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:34] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:34] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:34] DEBUG[14666]: channel.c:1499 queue_frame_to_spies: Triggering queue flush for spy 'MixMonitor' on 'SIP/201-09e2d830' [Nov 15 02:36:34] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:34] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:34] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:34] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:34] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:34] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:34] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:34] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:34] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:34] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:34] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:34] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:34] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:34] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:34] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:34] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:34] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:34] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:34] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:34] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:34] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:34] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:34] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:34] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:34] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:34] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:34] DEBUG[14666]: channel.c:1499 queue_frame_to_spies: Triggering queue flush for spy 'MixMonitor' on 'SIP/201-09e2d830' [Nov 15 02:36:34] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:34] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:34] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:34] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:34] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:34] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:34] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:34] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:34] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:34] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:34] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:34] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:34] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:34] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:35] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:35] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:35] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:35] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:35] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:35] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:35] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:35] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:35] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:35] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:35] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:35] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:35] DEBUG[14666]: channel.c:1499 queue_frame_to_spies: Triggering queue flush for spy 'MixMonitor' on 'SIP/201-09e2d830' [Nov 15 02:36:35] DEBUG[14666]: chan_zap.c:4947 zt_write: Dropping frame since I'm still dialing on Zap/4-1... stealth*CLI> [Nov 15 02:36:35] DEBUG[14666]: chan_zap.c:4515 __zt_exception: Exception on 15, channel 4 stealth*CLI> [Nov 15 02:36:35] DEBUG[14666]: chan_zap.c:3639 zt_handle_event: Got event Dial Complete(9) on channel 4 (index 0) [Nov 15 02:36:35] DEBUG[14666]: chan_zap.c:1441 zt_enable_ec: Echo cancellation already on [Nov 15 02:36:35] DEBUG[14666]: devicestate.c:314 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Zap/4-1 -- Zap/4-1 answered SIP/201-09e2d830 [Nov 15 02:36:35] DEBUG[14666]: rtp.c:1418 ast_rtp_early_bridge: Channel 'Zap/4-1' has no RTP, not doing anything stealth*CLI> [Nov 15 02:36:35] DEBUG[13966]: devicestate.c:298 do_state_change: Changing state for Zap/4 - state 2 (In use) stealth*CLI> [Nov 15 02:36:35] DEBUG[14674]: app_queue.c:546 changethread: Device 'Zap/4' changed to state '2' (In use) but we don't care because they're not a member of any queue. stealth*CLI> [Nov 15 02:36:35] DEBUG[14666]: rtp.c:2429 ast_rtp_raw_write: Difference is 33480, ms is 4205 stealth*CLI> show queues stealth*CLI> operator has 0 calls (max unlimited) in 'ringall' strategy (0s holdtime), W:0, C:3, A:0, SL:0.0% within 0s stealth*CLI> Members: stealth*CLI> Agent/202 (Unavailable) has taken no calls yet stealth*CLI> Sip/203 (Not in use) has taken 1 calls (last was 6882 secs ago) stealth*CLI> Sip/201 (In use) has taken 2 calls (last was 270 secs ago) stealth*CLI> No Callers stealth*CLI> stealth*CLI> show queues stealth*CLI> operator has 0 calls (max unlimited) in 'ringall' strategy (0s holdtime), W:0, C:3, A:0, SL:0.0% within 0s stealth*CLI> Members: stealth*CLI> Agent/202 (Unavailable) has taken no calls yet stealth*CLI> Sip/203 (Not in use) has taken 1 calls (last was 6883 secs ago) stealth*CLI> Sip/201 (In use) has taken 2 calls (last was 271 secs ago) stealth*CLI> No Callers stealth*CLI> stealth*CLI> show queues stealth*CLI> operator has 0 calls (max unlimited) in 'ringall' strategy (0s holdtime), W:0, C:3, A:0, SL:0.0% within 0s Members: Agent/202 (Unavailable) has taken no calls yet Sip/203 (Not in use) has taken 1 calls (last was 6883 secs ago) Sip/201 (In use) has taken 2 calls (last was 271 secs ago) No Callers stealth*CLI> show queues stealth*CLI> operator has 0 calls (max unlimited) in 'ringall' strategy (0s holdtime), W:0, C:3, A:0, SL:0.0% within 0s stealth*CLI> Members: stealth*CLI> Agent/202 (Unavailable) has taken no calls yet stealth*CLI> Sip/203 (Not in use) has taken 1 calls (last was 6885 secs ago) stealth*CLI> Sip/201 (In use) has taken 2 calls (last was 273 secs ago) stealth*CLI> No Callers stealth*CLI> stealth*CLI> [Nov 15 02:36:40] DEBUG[13971]: chan_sip.c:14522 sipsock_read: Invalid SIP message - rejected , no callid, len 334 stealth*CLI> [Nov 15 02:36:40] DEBUG[13971]: chan_sip.c:14522 sipsock_read: Invalid SIP message - rejected , no callid, len 331 stealth*CLI> [Nov 15 02:36:41] DEBUG[13971]: chan_sip.c:5015 process_sdp: T38 state changed to 0 on channel SIP/201-09e2d830 [Nov 15 02:36:41] DEBUG[13971]: chan_sip.c:5092 process_sdp: We're settling with these formats: 0xc (ulaw|alaw) [Nov 15 02:36:41] NOTICE[13971]: chan_sip.c:8037 sip_peer_hold: onHold now: 1; hold arg was: 1 [Nov 15 02:36:41] DEBUG[13971]: devicestate.c:314 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/201 [Nov 15 02:36:41] DEBUG[13971]: chan_sip.c:13276 handle_request_invite: SIP/201-09e2d830: This call is UP.... [Nov 15 02:36:41] DEBUG[13971]: chan_sip.c:6297 transmit_response_with_sdp: Setting framing from config on incoming call [Nov 15 02:36:41] DEBUG[13971]: chan_sip.c:6065 add_sdp: ** Our capability: 0xc (ulaw|alaw) Video flag: True [Nov 15 02:36:41] DEBUG[13971]: chan_sip.c:6066 add_sdp: ** Our prefcodec: 0x0 (nothing) [Nov 15 02:36:41] DEBUG[13971]: chan_sip.c:6197 add_sdp: -- Done with adding codecs to SDP [Nov 15 02:36:41] DEBUG[13971]: chan_sip.c:6242 add_sdp: Done building SDP. Settling with this capability: 0xc (ulaw|alaw) [Nov 15 02:36:41] DEBUG[14666]: chan_zap.c:5001 zt_indicate: Requested indication 16 on channel Zap/4-1 -- Started music on hold, class 'default', on Zap/4-1 [Nov 15 02:36:41] DEBUG[14666]: channel.c:1908 ast_settimeout: Scheduling timer at 160 sample intervals stealth*CLI> [Nov 15 02:36:41] DEBUG[13966]: chan_sip.c:14932 sip_devicestate: Checking device state for peer 201 [Nov 15 02:36:41] NOTICE[13966]: chan_sip.c:14960 sip_devicestate: sip_devicestate(201) returning On Hold call-lim=0, inuse=1, onHold=1, inRinging=0, maxms=0, lastms=0 [Nov 15 02:36:41] DEBUG[13966]: devicestate.c:298 do_state_change: Changing state for SIP/201 - state 8 (On Hold) stealth*CLI> [Nov 15 02:36:41] DEBUG[14677]: app_queue.c:552 changethread: Device 'SIP/201' changed to state '8' (On Hold) stealth*CLI> [Nov 15 02:36:41] DEBUG[14666]: channel.c:2225 __ast_read: Generator got voice, switching to phase locked mode [Nov 15 02:36:41] DEBUG[14666]: channel.c:1908 ast_settimeout: Scheduling timer at 0 sample intervals [Nov 15 02:36:41] DEBUG[14666]: res_musiconhold.c:252 ast_moh_files_next: Zap/4-1 Opened file 0 '/var/lib/asterisk/moh/breathless' stealth*CLI> [Nov 15 02:36:41] DEBUG[13971]: chan_sip.c:2047 __sip_ack: Stopping retransmission on '446bfa32-6c0a0418@192.168.4.196' of Response 103: Match Not Found stealth*CLI> show queues [Nov 15 02:36:41] DEBUG[14666]: channel.c:1484 queue_frame_to_spies: Switching spy 'MixMonitor' on 'SIP/201-09e2d830' to write-trigger mode [Nov 15 02:36:41] DEBUG[14666]: channel.c:1499 queue_frame_to_spies: Triggering queue flush for spy 'MixMonitor' on 'SIP/201-09e2d830' stealth*CLI> show queues stealth*CLI> operator has 0 calls (max unlimited) in 'ringall' strategy (0s holdtime), W:0, C:3, A:0, SL:0.0% within 0s Members: Agent/202 (Unavailable) has taken no calls yet Sip/203 (Not in use) has taken 1 calls (last was 6887 secs ago) Sip/201 (On Hold) has taken 2 calls (last was 275 secs ago) No Callers stealth*CLI> [Nov 15 02:36:42] DEBUG[14666]: channel.c:1499 queue_frame_to_spies: Triggering queue flush for spy 'MixMonitor' on 'SIP/201-09e2d830' stealth*CLI> show queues stealth*CLI> operator has 0 calls (max unlimited) in 'ringall' strategy (0s holdtime), W:0, C:3, A:0, SL:0.0% within 0s Members: Agent/202 (Unavailable) has taken no calls yet Sip/203 (Not in use) has taken 1 calls (last was 6888 secs ago) Sip/201 (On Hold) has taken 2 calls (last was 276 secs ago) No Callers stealth*CLI> [Nov 15 02:36:42] DEBUG[14666]: channel.c:1499 queue_frame_to_spies: Triggering queue flush for spy 'MixMonitor' on 'SIP/201-09e2d830' stealth*CLI> [Nov 15 02:36:43] DEBUG[14666]: channel.c:1499 queue_frame_to_spies: Triggering queue flush for spy 'MixMonitor' on 'SIP/201-09e2d830' stealth*CLI> [Nov 15 02:36:43] DEBUG[14666]: channel.c:1499 queue_frame_to_spies: Triggering queue flush for spy 'MixMonitor' on 'SIP/201-09e2d830' stealth*CLI> [Nov 15 02:36:43] DEBUG[13971]: chan_sip.c:5015 process_sdp: T38 state changed to 0 on channel SIP/201-09e2d830 [Nov 15 02:36:43] DEBUG[13971]: chan_sip.c:5092 process_sdp: We're settling with these formats: 0xc (ulaw|alaw) [Nov 15 02:36:43] NOTICE[13971]: chan_sip.c:8037 sip_peer_hold: onHold now: 0; hold arg was: 0 [Nov 15 02:36:43] DEBUG[13971]: devicestate.c:314 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/201 [Nov 15 02:36:43] DEBUG[13971]: chan_sip.c:13276 handle_request_invite: SIP/201-09e2d830: This call is UP.... stealth*CLI> [Nov 15 02:36:43] DEBUG[13971]: chan_sip.c:6297 transmit_response_with_sdp: Setting framing from config on incoming call [Nov 15 02:36:43] DEBUG[13971]: chan_sip.c:6065 add_sdp: ** Our capability: 0xc (ulaw|alaw) Video flag: True [Nov 15 02:36:43] DEBUG[13971]: chan_sip.c:6066 add_sdp: ** Our prefcodec: 0x0 (nothing) [Nov 15 02:36:43] DEBUG[13971]: chan_sip.c:6197 add_sdp: -- Done with adding codecs to SDP [Nov 15 02:36:43] DEBUG[13971]: chan_sip.c:6242 add_sdp: Done building SDP. Settling with this capability: 0xc (ulaw|alaw) stealth*CLI> [Nov 15 02:36:43] DEBUG[14666]: chan_zap.c:5001 zt_indicate: Requested indication 17 on channel Zap/4-1 -- Stopped music on hold on Zap/4-1 [Nov 15 02:36:43] DEBUG[14666]: channel.c:1908 ast_settimeout: Scheduling timer at 0 sample intervals stealth*CLI> [Nov 15 02:36:43] DEBUG[13966]: chan_sip.c:14932 sip_devicestate: Checking device state for peer 201 stealth*CLI> [Nov 15 02:36:43] NOTICE[13966]: chan_sip.c:14972 sip_devicestate: sip_devicestate(201) returning In use call-lim=0, inuse=1, onHold=0, inRinging=0, maxms=0, lastms=0 stealth*CLI> [Nov 15 02:36:43] DEBUG[13966]: devicestate.c:298 do_state_change: Changing state for SIP/201 - state 2 (In use) stealth*CLI> [Nov 15 02:36:43] DEBUG[14666]: rtp.c:2576 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160 [Nov 15 02:36:43] DEBUG[14666]: rtp.c:2429 ast_rtp_raw_write: Difference is 20488, ms is 2581 stealth*CLI> [Nov 15 02:36:43] DEBUG[14678]: app_queue.c:552 changethread: Device 'SIP/201' changed to state '2' (In use) stealth*CLI> [Nov 15 02:36:43] DEBUG[13971]: chan_sip.c:2047 __sip_ack: Stopping retransmission on '446bfa32-6c0a0418@192.168.4.196' of Response 104: Match Not Found stealth*CLI> show queues stealth*CLI> operator has 0 calls (max unlimited) in 'ringall' strategy (0s holdtime), W:0, C:3, A:0, SL:0.0% within 0s Members: Agent/202 (Unavailable) has taken no calls yet Sip/203 (Not in use) has taken 1 calls (last was 6890 secs ago) Sip/201 (In use) has taken 2 calls (last was 278 secs ago) No Callers stealth*CLI> show queues stealth*CLI> operator has 0 calls (max unlimited) in 'ringall' strategy (0s holdtime), W:0, C:3, A:0, SL:0.0% within 0s stealth*CLI> Members: stealth*CLI> Agent/202 (Unavailable) has taken no calls yet stealth*CLI> Sip/203 (Not in use) has taken 1 calls (last was 6891 secs ago) stealth*CLI> Sip/201 (In use) has taken 2 calls (last was 279 secs ago) stealth*CLI> No Callers stealth*CLI> stealth*CLI> show queues stealth*CLI> operator has 0 calls (max unlimited) in 'ringall' strategy (0s holdtime), W:0, C:3, A:0, SL:0.0% within 0s stealth*CLI> Members: stealth*CLI> Agent/202 (Unavailable) has taken no calls yet stealth*CLI> Sip/203 (Not in use) has taken 1 calls (last was 6892 secs ago) stealth*CLI> Sip/201 (In use) has taken 2 calls (last was 280 secs ago) stealth*CLI> No Callers stealth*CLI> stealth*CLI> [Nov 15 02:36:48] DEBUG[13971]: chan_sip.c:1969 __sip_autodestruct: Auto destroying SIP dialog '4913c2bb2a60923a7ba420612468c766@127.0.0.1' [Nov 15 02:36:48] DEBUG[13971]: chan_sip.c:3054 sip_destroy: Destroying SIP dialog 4913c2bb2a60923a7ba420612468c766@127.0.0.1 Really destroying SIP dialog '4913c2bb2a60923a7ba420612468c766@127.0.0.1' Method: REGISTER stealth*CLI> [Nov 15 02:36:49] DEBUG[13971]: chan_sip.c:13918 handle_request_bye: Received bye, issuing owner hangup .[Nov 15 02:36:49] DEBUG[14666]: channel.c:3679 ast_generic_bridge: Didn't get a frame from channel: SIP/201-09e2d830 [Nov 15 02:36:49] DEBUG[14666]: channel.c:3984 ast_channel_bridge: Bridge stops bridging channels SIP/201-09e2d830 and Zap/4-1 [Nov 15 02:36:49] DEBUG[14666]: channel.c:1606 ast_hangup: Hanging up channel 'Zap/4-1' [Nov 15 02:36:49] DEBUG[14666]: chan_zap.c:2438 zt_hangup: zt_hangup(Zap/4-1) [Nov 15 02:36:49] DEBUG[14666]: chan_zap.c:2471 zt_hangup: Hangup: channel: 4 index = 0, normal = 15, callwait = -1, thirdcall = -1 [Nov 15 02:36:49] DEBUG[14666]: chan_zap.c:1493 zt_disable_ec: disabled echo cancellation on channel 4 stealth*CLI> [Nov 15 02:36:49] DEBUG[14666]: chan_zap.c:2899 zt_setoption: Set option TDD MODE, value: OFF(0) on Zap/4-1 [Nov 15 02:36:49] DEBUG[14666]: chan_zap.c:1430 update_conf: Updated conferencing on 4, with 0 conference users -- Hungup 'Zap/4-1' [Nov 15 02:36:49] DEBUG[14666]: devicestate.c:314 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Zap/4-1 [Nov 15 02:36:49] DEBUG[14666]: rtp.c:1418 ast_rtp_early_bridge: Channel '' has no RTP, not doing anything [Nov 15 02:36:49] DEBUG[14666]: app_dial.c:1639 dial_exec_full: Exiting with DIALSTATUS=ANSWER. [Nov 15 02:36:49] DEBUG[14666]: app_macro.c:253 _macro_exec: Spawn extension (macro-extensions,s,8) exited non-zero on 'SIP/201-09e2d830' in macro 'extensions' [Nov 15 02:36:49] DEBUG[14666]: pbx.c:2363 __ast_pbx_run: Spawn extension (macro-extensions,s,8) exited non-zero on 'SIP/201-09e2d830' == Spawn extension (macro-extensions, s, 8) exited non-zero on 'SIP/201-09e2d830' [Nov 15 02:36:49] DEBUG[14666]: channel.c:1299 spy_detach: Spy MixMonitor removed from channel SIP/201-09e2d830 [Nov 15 02:36:49] DEBUG[14666]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '"Ronald Chan" <201>' [Nov 15 02:36:49] DEBUG[14666]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '201' [Nov 15 02:36:49] DEBUG[14666]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '97533707' [Nov 15 02:36:49] DEBUG[14666]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'internal' [Nov 15 02:36:49] DEBUG[14666]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'SIP/201-09e2d830' [Nov 15 02:36:49] DEBUG[14666]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'Zap/4-1' [Nov 15 02:36:49] DEBUG[14666]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'Dial' [Nov 15 02:36:49] DEBUG[14666]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'Zap/g1/7533707|120|tH' [Nov 15 02:36:49] DEBUG[14666]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '2006-11-15 02:36:29' [Nov 15 02:36:49] DEBUG[14666]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '2006-11-15 02:36:29' [Nov 15 02:36:49] DEBUG[14666]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '2006-11-15 02:36:49' [Nov 15 02:36:49] DEBUG[14666]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '20' [Nov 15 02:36:49] DEBUG[14666]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '20' [Nov 15 02:36:49] DEBUG[14666]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'ANSWERED' [Nov 15 02:36:49] DEBUG[14666]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' [Nov 15 02:36:49] DEBUG[14666]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '' [Nov 15 02:36:49] DEBUG[14666]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '1163529389.12' [Nov 15 02:36:49] DEBUG[14666]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '' [Nov 15 02:36:49] DEBUG[14666]: channel.c:1606 ast_hangup: Hanging up channel 'SIP/201-09e2d830' [Nov 15 02:36:49] DEBUG[14666]: chan_sip.c:3252 sip_hangup: Hangup call SIP/201-09e2d830, SIP callid 446bfa32-6c0a0418@192.168.4.196) [Nov 15 02:36:49] DEBUG[14666]: chan_sip.c:2950 update_call_counter: Updating call counter for incoming call [Nov 15 02:36:49] DEBUG[14666]: chan_sip.c:2996 update_call_counter: == End MixMonitor Recording SIP/201-09e2d830 Call from peer '201' removed from call limit 0 [Nov 15 02:36:49] DEBUG[14666]: devicestate.c:314 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/201 [Nov 15 02:36:49] DEBUG[14666]: devicestate.c:314 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/201-09e2d830 [Nov 15 02:36:49] DEBUG[13966]: devicestate.c:298 do_state_change: Changing state for Zap/4 - state 0 (Unknown) stealth*CLI> [Nov 15 02:36:49] DEBUG[13966]: chan_sip.c:14932 sip_devicestate: Checking device state for peer 201 stealth*CLI> [Nov 15 02:36:49] NOTICE[13966]: chan_sip.c:14976 sip_devicestate: sip_devicestate(201) returning Not in use call-lim=0, inuse=0, onHold=0, inRinging=0, maxms=0, lastms=0 stealth*CLI> [Nov 15 02:36:49] NOTICE[13966]: chan_sip.c:14979 sip_devicestate: sip_devicestate(201) USER: call_limit=0, inUse=0 stealth*CLI> [Nov 15 02:36:49] DEBUG[13966]: devicestate.c:298 do_state_change: Changing state for SIP/201 - state 1 (Not in use) stealth*CLI> [Nov 15 02:36:49] DEBUG[14681]: app_queue.c:546 changethread: Device 'Zap/4' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. stealth*CLI> [Nov 15 02:36:49] DEBUG[13966]: chan_sip.c:14932 sip_devicestate: Checking device state for peer 201 stealth*CLI> [Nov 15 02:36:49] NOTICE[13966]: chan_sip.c:14976 sip_devicestate: sip_devicestate(201) returning Not in use call-lim=0, inuse=0, onHold=0, inRinging=0, maxms=0, lastms=0 stealth*CLI> [Nov 15 02:36:49] NOTICE[13966]: chan_sip.c:14979 sip_devicestate: sip_devicestate(201) USER: call_limit=0, inUse=0 stealth*CLI> [Nov 15 02:36:49] DEBUG[13966]: devicestate.c:298 do_state_change: Changing state for SIP/201 - state 1 (Not in use) stealth*CLI> [Nov 15 02:36:49] DEBUG[14682]: app_queue.c:552 changethread: Device 'SIP/201' changed to state '1' (Not in use) stealth*CLI> [Nov 15 02:36:49] DEBUG[14683]: app_queue.c:552 changethread: Device 'SIP/201' changed to state '1' (Not in use) stealth*CLI> show queues stealth*CLI> operator has 0 calls (max unlimited) in 'ringall' strategy (0s holdtime), W:0, C:3, A:0, SL:0.0% within 0s stealth*CLI> Members: stealth*CLI> Agent/202 (Unavailable) has taken no calls yet stealth*CLI> Sip/203 (Not in use) has taken 1 calls (last was 6896 secs ago) stealth*CLI> Sip/201 (Not in use) has taken 2 calls (last was 284 secs ago) stealth*CLI> No Callers stealth*CLI> stealth*CLI> Really destroying SIP dialog '446bfa32-6c0a0418@192.168.4.196' Method: BYE stealth*CLI> [Nov 15 02:36:55] DEBUG[13971]: chan_sip.c:14522 sipsock_read: Invalid SIP message - rejected , no callid, len 334 stealth*CLI> [Nov 15 02:36:55] DEBUG[13971]: chan_sip.c:14522 sipsock_read: Invalid SIP message - rejected , no callid, len 331 stealth*CLI>