=~=~=~=~=~=~=~=~=~=~=~= PuTTY log 2006.11.14 18:30:56 =~=~=~=~=~=~=~=~=~=~=~=

[Nov 15 02:31:00] DEBUG[13971]: chan_sip.c:4224 sip_alloc: Allocating new SIP dialog for 4913c2bb2a60923a7ba420612468c766@127.0.0.1 - REGISTER (No RTP)

stealth*CLI> 
[Nov 15 02:31:00] DEBUG[13971]: chan_sip.c:7157 transmit_register: Scheduled a registration timeout for fwd.pulver.com id  #374 

stealth*CLI> 
[Nov 15 02:31:00] DEBUG[13971]: chan_sip.c:2089 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '4913c2bb2a60923a7ba420612468c766@127.0.0.1' Request 105: Found

stealth*CLI> 
[Nov 15 02:31:00] DEBUG[13971]: chan_sip.c:2047 __sip_ack: Stopping retransmission on '4913c2bb2a60923a7ba420612468c766@127.0.0.1' of Request 105: Match Not Found
[Nov 15 02:31:00] DEBUG[13971]: chan_sip.c:11798 handle_response_register: Registration successful
[Nov 15 02:31:00] DEBUG[13971]: chan_sip.c:11801 handle_response_register: Cancelling timeout 374

stealth*CLI> 
[Nov 15 02:31:09] DEBUG[13971]: chan_sip.c:14522 sipsock_read: Invalid SIP message - rejected , no callid, len 334

stealth*CLI> 
[Nov 15 02:31:09] DEBUG[13971]: chan_sip.c:14522 sipsock_read: Invalid SIP message - rejected , no callid, len 331

stealth*CLI> 
[Nov 15 02:31:24] DEBUG[13971]: chan_sip.c:14522 sipsock_read: Invalid SIP message - rejected , no callid, len 334

stealth*CLI> 
[Nov 15 02:31:24] DEBUG[13971]: chan_sip.c:14522 sipsock_read: Invalid SIP message - rejected , no callid, len 331

stealth*CLI> 
[Nov 15 02:31:32] DEBUG[13971]: chan_sip.c:1969 __sip_autodestruct: Auto destroying SIP dialog '4913c2bb2a60923a7ba420612468c766@127.0.0.1'
[Nov 15 02:31:32] 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:31:35] DEBUG[13984]: chan_zap.c:6890 do_monitor: Monitor doohicky got event Ring Begin on channel 4

stealth*CLI> 
[Nov 15 02:31:36] DEBUG[13984]: chan_zap.c:6890 do_monitor: Monitor doohicky got event Ring/Answered on channel 4
[Nov 15 02:31:36] DEBUG[13984]: dsp.c:1658 ast_dsp_set_busy_pattern: dsp busy pattern set to 0,0

stealth*CLI> 
    -- Starting simple switch on 'Zap/4-1'

stealth*CLI> 
[Nov 15 02:31:39] NOTICE[14516]: chan_zap.c:6350 ss_thread: Got event 18 (Ring Begin)...

stealth*CLI> 
[Nov 15 02:31:39] DEBUG[13971]: chan_sip.c:14522 sipsock_read: Invalid SIP message - rejected , no callid, len 334

stealth*CLI> 
[Nov 15 02:31:39] DEBUG[13971]: chan_sip.c:14522 sipsock_read: Invalid SIP message - rejected , no callid, len 331

stealth*CLI> 
[Nov 15 02:31:40] NOTICE[14516]: chan_zap.c:6350 ss_thread: Got event 2 (Ring/Answered)...
[Nov 15 02:31:40] DEBUG[14516]: pbx.c:1767 pbx_extension_helper: Launching 'Answer'
    -- Executing [s@from-zaptel:1] Answer("Zap/4-1", "") in new stack
[Nov 15 02:31:40] DEBUG[14516]: devicestate.c:314 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Zap/4-1
[Nov 15 02:31:40] DEBUG[14516]: chan_zap.c:2796 zt_answer: Took Zap/4-1 off hook
[Nov 15 02:31:40] DEBUG[14516]: chan_zap.c:1461 zt_enable_ec: Enabled echo cancellation on channel 4
[Nov 15 02:31:40] DEBUG[14516]: chan_zap.c:1477 zt_train_ec: Engaged echo training on channel 4
[Nov 15 02:31:40] DEBUG[14516]: pbx.c:1767 pbx_extension_helper: Launching 'Ringing'
    -- Executing [s@from-zaptel:2] Ringing("Zap/4-1", "") in new stack
[Nov 15 02:31:40] DEBUG[14516]: chan_zap.c:5001 zt_indicate: Requested indication 3 on channel Zap/4-1
[Nov 15 02:31:40] DEBUG[14516]: pbx.c:1767 pbx_extension_helper: Launching 'Wait'
    -- Executing [s@from-zaptel:3] Wait("Zap/4-1", "1") in new stack

stealth*CLI> 
[Nov 15 02:31:40] DEBUG[13966]: devicestate.c:298 do_state_change: Changing state for Zap/4 - state 2 (In use)

stealth*CLI> 
[Nov 15 02:31:40] DEBUG[14519]: 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:31:41] DEBUG[14516]: pbx.c:1767 pbx_extension_helper: Launching 'Set'
    -- Executing [s@from-zaptel:4] Set("Zap/4-1", "MONITOR_FILENAME="/var/spool/asterisk/monitor/"INCOMING-CALL/-1163529096.5") in new stack
[Nov 15 02:31:41] DEBUG[14516]: pbx.c:1767 pbx_extension_helper: Launching 'Set'
    -- Executing [s@from-zaptel:5] Set("Zap/4-1", "DYNAMIC_FEATURES=datetime") in new stack
[Nov 15 02:31:41] DEBUG[14516]: pbx.c:1767 pbx_extension_helper: Launching 'Queue'
    -- Executing [s@from-zaptel:6] Queue("Zap/4-1", "operator|tWw|||120") in new stack
[Nov 15 02:31:41] DEBUG[14516]: app_queue.c:3325 queue_exec: NO QUEUE_PRIO variable found. Using default.
[Nov 15 02:31:41] DEBUG[14516]: app_queue.c:3348 queue_exec: queue: operator, options: tWw, url: , announce: , expires: 1163529221, priority: 0
[Nov 15 02:31:41] DEBUG[14516]: app_queue.c:1207 join_queue: Queue 'operator' Join, Channel 'Zap/4-1', Position '1'
    -- Started music on hold, class 'default', on Zap/4-1
[Nov 15 02:31:41] DEBUG[14516]: channel.c:1908 ast_settimeout: Scheduling timer at 160 sample intervals
[Nov 15 02:31:41] DEBUG[14516]: app_queue.c:2115 is_our_turn: Even though there are 0 available members, the strategy is ringall so only the head call is allowed in
[Nov 15 02:31:41] DEBUG[14516]: app_queue.c:2129 is_our_turn: There are 1 available members.
[Nov 15 02:31:41] DEBUG[14516]: app_queue.c:2139 is_our_turn: It's our turn (Zap/4-1).
[Nov 15 02:31:41] DEBUG[14516]: app_queue.c:2357 try_calling: Zap/4-1 is trying to call a queue member.
[Nov 15 02:31:41] DEBUG[14516]: app_queue.c:1717 ring_one: (Parallel) Trying 'Sip/201' with metric 0
[Nov 15 02:31:41] DEBUG[14516]: chan_sip.c:15021 sip_request_call: Asked to create a SIP channel with formats: 0x4 (ulaw)
[Nov 15 02:31:41] DEBUG[14516]: chan_sip.c:4224 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP)
[Nov 15 02:31:41] DEBUG[14516]: chan_sip.c:2580 create_addr_from_peer: Our T38 capability (3856)
[Nov 15 02:31:41] DEBUG[14516]: chan_sip.c:2534 do_setnat: Setting NAT on RTP to On
[Nov 15 02:31:41] DEBUG[14516]: chan_sip.c:2544 do_setnat: Setting NAT on UDPTL to On
[Nov 15 02:31:41] DEBUG[14516]: chan_sip.c:3731 sip_new: *** Our native formats are 0x4 (ulaw) 
[Nov 15 02:31:41] DEBUG[14516]: chan_sip.c:3732 sip_new: *** Joint capabilities are 0x0 (nothing) 
[Nov 15 02:31:41] DEBUG[14516]: chan_sip.c:3733 sip_new: *** Our capabilities are 0xe (gsm|ulaw|alaw) 
[Nov 15 02:31:41] DEBUG[14516]: chan_sip.c:3734 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) 
[Nov 15 02:31:41] DEBUG[14516]: chan_sip.c:3736 sip_new: *** Our preferred formats from the incoming channel are 0x4 (ulaw) 
[Nov 15 02:31:41] DEBUG[14516]: chan_sip.c:3757 sip_new: This channel will not be able to handle video.
[Nov 15 02:31:41] DEBUG[14516]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-from-zaptel-s-6.
[Nov 15 02:31:41] DEBUG[14516]: channel.c:3185 ast_channel_inherit_variables: Not copying variable DYNAMIC_FEATURES.
[Nov 15 02:31:41] DEBUG[14516]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-from-zaptel-s-5.
[Nov 15 02:31:41] DEBUG[14516]: channel.c:3185 ast_channel_inherit_variables: Not copying variable MONITOR_FILENAME.
[Nov 15 02:31:41] DEBUG[14516]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-from-zaptel-s-4.
[Nov 15 02:31:41] DEBUG[14516]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-from-zaptel-s-3.
[Nov 15 02:31:41] DEBUG[14516]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-from-zaptel-s-2.
[Nov 15 02:31:41] DEBUG[14516]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-from-zaptel-s-1.
[Nov 15 02:31:41] DEBUG[14516]: channel.c:3185 ast_channel_inherit_variables: Not copying variable TRANSFERCAPABILITY.
[Nov 15 02:31:41] DEBUG[14516]: chan_sip.c:2785 sip_call: Outgoing Call for 201
[Nov 15 02:31:41] DEBUG[14516]: chan_sip.c:2950 update_call_counter: Updating call counter for outgoing call
[Nov 15 02:31:41] DEBUG[14516]: chan_sip.c:3022 update_call_counter: Call to peer '201' is 1 out of 0
[Nov 15 02:31:41] DEBUG[14516]: devicestate.c:314 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/201
[Nov 15 02:31:41] DEBUG[14516]: chan_sip.c:2799 sip_call: Our T38 capability (3856), joint T38 capability (3856)
[Nov 15 02:31:41] DEBUG[14516]: chan_sip.c:6065 add_sdp: ** Our capability: 0xe (gsm|ulaw|alaw) Video flag: False
[Nov 15 02:31:41] DEBUG[14516]: chan_sip.c:6066 add_sdp: ** Our prefcodec: 0x4 (ulaw) 
[Nov 15 02:31:41] DEBUG[14516]: chan_sip.c:6197 add_sdp: -- Done with adding codecs to SDP
[Nov 15 02:31:41] DEBUG[14516]: chan_sip.c:6242 add_sdp: Done building SDP. Settling with this capability: 0xe (gsm|ulaw|alaw)
[Nov 15 02:31:41] DEBUG[14516]: app_queue.c:1717 ring_one: (Parallel) Trying 'Sip/203' with metric 0
[Nov 15 02:31:41] DEBUG[14516]: chan_sip.c:15021 sip_request_call: Asked to create a SIP channel with formats: 0x4 (ulaw)
[Nov 15 02:31:41] DEBUG[14516]: chan_sip.c:4224 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP)
[Nov 15 02:31:41] DEBUG[14516]: chan_sip.c:2580 create_addr_from_peer: Our T38 capability (3856)
[Nov 15 02:31:41] DEBUG[14516]: chan_sip.c:2534 do_setnat: Setting NAT on RTP to On
[Nov 15 02:31:41] DEBUG[14516]: chan_sip.c:2544 do_setnat: Setting NAT on UDPTL to On
[Nov 15 02:31:41] DEBUG[14516]: chan_sip.c:3731 sip_new: *** Our native formats are 0x4 (ulaw) 
[Nov 15 02:31:41] DEBUG[14516]: chan_sip.c:3732 sip_new: *** Joint capabilities are 0x0 (nothing) 
[Nov 15 02:31:41] DEBUG[14516]: chan_sip.c:3733 sip_new: *** Our capabilities are 0xc (ulaw|alaw) 
[Nov 15 02:31:41] DEBUG[14516]: chan_sip.c:3734 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) 
[Nov 15 02:31:41] DEBUG[14516]: chan_sip.c:3736 sip_new: *** Our preferred formats from the incoming channel are 0x4 (ulaw) 
[Nov 15 02:31:41] DEBUG[14516]: chan_sip.c:3757 sip_new: This channel will not be able to handle video.
[Nov 15 02:31:41] DEBUG[14516]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-from-zaptel-s-6.
[Nov 15 02:31:41] DEBUG[14516]: channel.c:3185 ast_channel_inherit_variables: Not copying variable DYNAMIC_FEATURES.
[Nov 15 02:31:41] DEBUG[14516]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-from-zaptel-s-5.
[Nov 15 02:31:41] DEBUG[14516]: channel.c:3185 ast_channel_inherit_variables: Not copying variable MONITOR_FILENAME.
[Nov 15 02:31:41] DEBUG[14516]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-from-zaptel-s-4.
[Nov 15 02:31:41] DEBUG[14516]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-from-zaptel-s-3.
[Nov 15 02:31:41] DEBUG[14516]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-from-zaptel-s-2.
[Nov 15 02:31:41] DEBUG[14516]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-from-zaptel-s-1.
[Nov 15 02:31:41] DEBUG[14516]: channel.c:3185 ast_channel_inherit_variables: Not copying variable TRANSFERCAPABILITY.
[Nov 15 02:31:41] DEBUG[14516]: chan_sip.c:2785 sip_call: Outgoing Call for 203
[Nov 15 02:31:41] DEBUG[14516]: chan_sip.c:2950 update_call_counter: Updating call counter for outgoing call
[Nov 15 02:31:41] DEBUG[14516]: chan_sip.c:3022 update_call_counter: Call to peer '203' is 2 out of 0
[Nov 15 02:31:41] DEBUG[14516]: devicestate.c:314 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/203
[Nov 15 02:31:41] DEBUG[14516]: chan_sip.c:2799 sip_call: Our T38 capability (3856), joint T38 capability (3856)
[Nov 15 02:31:41] DEBUG[14516]: chan_sip.c:6065 add_sdp: ** Our capability: 0xc (ulaw|alaw) Video flag: False
[Nov 15 02:31:41] DEBUG[14516]: chan_sip.c:6066 add_sdp: ** Our prefcodec: 0x4 (ulaw) 
[Nov 15 02:31:41] DEBUG[14516]: chan_sip.c:6197 add_sdp: -- Done with adding codecs to SDP
[Nov 15 02:31:41] DEBUG[14516]: chan_sip.c:6242 add_sdp: Done building SDP. Settling with this capability: 0xc (ulaw|alaw)
[Nov 15 02:31:41] DEBUG[14516]: app_queue.c:1717 ring_one: (Parallel) Trying 'Agent/202' with metric 0
[Nov 15 02:31:41] DEBUG[14516]: channel.c:2225 __ast_read: Generator got voice, switching to phase locked mode
[Nov 15 02:31:41] DEBUG[14516]: channel.c:1908 ast_settimeout: Scheduling timer at 0 sample intervals
[Nov 15 02:31:41] DEBUG[14516]: res_musiconhold.c:252 ast_moh_files_next: Zap/4-1 Opened file 0 '/var/lib/asterisk/moh/breathless'
[Nov 15 02:31:41] DEBUG[13971]: chan_sip.c:2089 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '7345337644aff43602added52c8818b8@192.168.4.1' Request 102: Found
[Nov 15 02:31:41] DEBUG[13966]: chan_sip.c:14932 sip_devicestate: Checking device state for peer 201
[Nov 15 02:31:41] NOTICE[13966]: chan_sip.c:14964 sip_devicestate: sip_devicestate(201) returning Ringing call-lim=0, inuse=1, onHold=0,  inRinging=1, maxms=0, lastms=0
[Nov 15 02:31:41] DEBUG[13966]: devicestate.c:298 do_state_change: Changing state for SIP/201 - state 6 (Ringing)
[Nov 15 02:31:41] DEBUG[13966]: chan_sip.c:14932 sip_devicestate: Checking device state for peer 203
[Nov 15 02:31:41] NOTICE[13966]: chan_sip.c:14968 sip_devicestate: sip_devicestate(203) returning Ring+Inuse call-lim=0, inuse=2, onHold=0,  inRinging=1, maxms=0, lastms=0
[Nov 15 02:31:41] DEBUG[13966]: devicestate.c:298 do_state_change: Changing state for SIP/203 - state 7 (Ring+Inuse)

stealth*CLI> 
[Nov 15 02:31:41] DEBUG[14520]: app_queue.c:552 changethread: Device 'SIP/201' changed to state '6' (Ringing)

stealth*CLI> 
[Nov 15 02:31:41] DEBUG[14521]: app_queue.c:552 changethread: Device 'SIP/203' changed to state '7' (Ring+Inuse)

stealth*CLI> 
[Nov 15 02:31:41] DEBUG[13971]: chan_sip.c:2089 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '7345337644aff43602added52c8818b8@192.168.4.1' Request 102: Found
[Nov 15 02:31:41] DEBUG[13971]: devicestate.c:314 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/201-09e2b390
    -- SIP/201-09e2b390 is ringing

stealth*CLI> 
[Nov 15 02:31:41] DEBUG[13966]: chan_sip.c:14932 sip_devicestate: Checking device state for peer 201
[Nov 15 02:31:41] NOTICE[13966]: chan_sip.c:14964 sip_devicestate: sip_devicestate(201) returning Ringing call-lim=0, inuse=1, onHold=0,  inRinging=1, maxms=0, lastms=0
[Nov 15 02:31:41] DEBUG[13966]: devicestate.c:298 do_state_change: Changing state for SIP/201 - state 6 (Ringing)

stealth*CLI> 
[Nov 15 02:31:41] DEBUG[14522]: app_queue.c:552 changethread: Device 'SIP/201' changed to state '6' (Ringing)

stealth*CLI> 
[Nov 15 02:31:41] DEBUG[13971]: chan_sip.c:2089 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '29b81581487762405339ce804adfc1b0@192.168.4.1' Request 102: Found
[Nov 15 02:31:41] DEBUG[13971]: devicestate.c:314 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/203-09e3d7f8
    -- SIP/203-09e3d7f8 is ringing

stealth*CLI> 
[Nov 15 02:31:41] DEBUG[13966]: chan_sip.c:14932 sip_devicestate: Checking device state for peer 203
[Nov 15 02:31:41] NOTICE[13966]: chan_sip.c:14968 sip_devicestate: sip_devicestate(203) returning Ring+Inuse call-lim=0, inuse=2, onHold=0,  inRinging=1, maxms=0, lastms=0
[Nov 15 02:31:41] DEBUG[13966]: devicestate.c:298 do_state_change: Changing state for SIP/203 - state 7 (Ring+Inuse)

stealth*CLI> 
[Nov 15 02:31:41] DEBUG[14523]: app_queue.c:552 changethread: Device 'SIP/203' changed to state '7' (Ring+Inuse)

stealth*CLI> 
[Nov 15 02:31:42] DEBUG[13971]: chan_sip.c:2089 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '29b81581487762405339ce804adfc1b0@192.168.4.1' Request 102: Found

stealth*CLI> 
    -- SIP/203-09e3d7f8 is ringing

stealth*CLI> 
[Nov 15 02:31:42] DEBUG[13971]: chan_sip.c:2030 __sip_ack: Acked pending invite 102
[Nov 15 02:31:42] DEBUG[13971]: chan_sip.c:2047 __sip_ack: Stopping retransmission on '7345337644aff43602added52c8818b8@192.168.4.1' of Request 102: Match Not Found
[Nov 15 02:31:42] DEBUG[13971]: chan_sip.c:5015 process_sdp: T38 state changed to 0 on channel SIP/201-09e2b390
[Nov 15 02:31:42] DEBUG[13971]: chan_sip.c:5092 process_sdp: We're settling with these formats: 0x4 (ulaw)
[Nov 15 02:31:42] DEBUG[13971]: chan_sip.c:2950 update_call_counter: Updating call counter for outgoing call
[Nov 15 02:31:42] 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:31:42] DEBUG[13971]: chan_sip.c:7828 build_route: build_route: Contact hop: Ronald Chan <sip:201@192.168.4.196:5060>

stealth*CLI> 
[Nov 15 02:31:42] DEBUG[14516]: devicestate.c:314 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/201-09e2b390
    -- SIP/201-09e2b390 answered Zap/4-1
[Nov 15 02:31:42] DEBUG[14516]: chan_zap.c:2881 zt_setoption: Set option TONE VERIFY, mode: MUTECONF(1) on Zap/4-1
[Nov 15 02:31:42] DEBUG[14516]: channel.c:1606 ast_hangup: Hanging up channel 'SIP/203-09e3d7f8'
[Nov 15 02:31:42] DEBUG[14516]: chan_sip.c:3252 sip_hangup: Hangup call SIP/203-09e3d7f8, SIP callid 29b81581487762405339ce804adfc1b0@192.168.4.1)
[Nov 15 02:31:42] DEBUG[14516]: chan_sip.c:2950 update_call_counter: Updating call counter for outgoing call
[Nov 15 02:31:42] DEBUG[14516]: chan_sip.c:2996 update_call_counter: Call to peer '203' removed from call limit 0
[Nov 15 02:31:42] DEBUG[14516]: devicestate.c:314 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/203
[Nov 15 02:31:42] DEBUG[14516]: chan_sip.c:2030 __sip_ack: Acked pending invite 102
[Nov 15 02:31:42] DEBUG[14516]: chan_sip.c:2047 __sip_ack: Stopping retransmission on '29b81581487762405339ce804adfc1b0@192.168.4.1' of Request 102: Match Not Found
[Nov 15 02:31:42] DEBUG[14516]: devicestate.c:314 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/203-09e3d7f8
    -- Stopped music on hold on Zap/4-1
[Nov 15 02:31:42] DEBUG[14516]: channel.c:1908 ast_settimeout: Scheduling timer at 0 sample intervals
[Nov 15 02:31:42] DEBUG[14516]: app_queue.c:1405 leave_queue: Queue 'operator' Leave, Channel 'Zap/4-1'
[Nov 15 02:31:42] DEBUG[14516]: rtp.c:2559 ast_rtp_write: Ooh, format changed from unknown to ulaw
[Nov 15 02:31:42] DEBUG[14516]: rtp.c:2576 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160

stealth*CLI> 
[Nov 15 02:31:42] DEBUG[13966]: chan_sip.c:14932 sip_devicestate: Checking device state for peer 201

stealth*CLI> 
[Nov 15 02:31:42] 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:31:42] DEBUG[13966]: devicestate.c:298 do_state_change: Changing state for SIP/201 - state 2 (In use)

stealth*CLI> 
[Nov 15 02:31:42] DEBUG[13966]: chan_sip.c:14932 sip_devicestate: Checking device state for peer 201

stealth*CLI> 
[Nov 15 02:31:42] 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:31:42] DEBUG[13971]: chan_sip.c:2047 __sip_ack: Stopping retransmission on '29b81581487762405339ce804adfc1b0@192.168.4.1' of Request 102: Match Not Found

stealth*CLI> 
[Nov 15 02:31:42] DEBUG[13966]: devicestate.c:298 do_state_change: Changing state for SIP/201 - state 2 (In use)

stealth*CLI> 
[Nov 15 02:31:42] DEBUG[13966]: chan_sip.c:14932 sip_devicestate: Checking device state for peer 203

stealth*CLI> 
[Nov 15 02:31:42] NOTICE[13966]: chan_sip.c:14972 sip_devicestate: sip_devicestate(203) returning In use call-lim=0, inuse=1, onHold=0,  inRinging=0, maxms=0, lastms=0

stealth*CLI> 
[Nov 15 02:31:42] DEBUG[13971]: chan_sip.c:2047 __sip_ack: Stopping retransmission on '29b81581487762405339ce804adfc1b0@192.168.4.1' of Request 102: Match Found
[Nov 15 02:31:42] DEBUG[13971]: chan_sip.c:2950 update_call_counter: Updating call counter for outgoing call
[Nov 15 02:31:42] DEBUG[13971]: chan_sip.c:2996 update_call_counter: Call to peer '203' removed from call limit 0
[Nov 15 02:31:42] DEBUG[13971]: devicestate.c:314 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/203
Really destroying SIP dialog '29b81581487762405339ce804adfc1b0@192.168.4.1' Method: INVITE

stealth*CLI> 
[Nov 15 02:31:42] DEBUG[13966]: devicestate.c:298 do_state_change: Changing state for SIP/203 - state 2 (In use)

stealth*CLI> 
[Nov 15 02:31:42] DEBUG[13966]: chan_sip.c:14932 sip_devicestate: Checking device state for peer 203

stealth*CLI> 
[Nov 15 02:31:42] NOTICE[13966]: chan_sip.c:14976 sip_devicestate: sip_devicestate(203) returning Not in use call-lim=0, inuse=0, onHold=0,  inRinging=0, maxms=0, lastms=0

stealth*CLI> 
[Nov 15 02:31:42] NOTICE[13966]: chan_sip.c:14979 sip_devicestate: sip_devicestate(203) USER: call_limit=0, inUse=0

stealth*CLI> 
[Nov 15 02:31:42] DEBUG[13966]: devicestate.c:298 do_state_change: Changing state for SIP/203 - state 1 (Not in use)

stealth*CLI> 
[Nov 15 02:31:42] DEBUG[13966]: chan_sip.c:14932 sip_devicestate: Checking device state for peer 203

stealth*CLI> 
[Nov 15 02:31:42] NOTICE[13966]: chan_sip.c:14976 sip_devicestate: sip_devicestate(203) returning Not in use call-lim=0, inuse=0, onHold=0,  inRinging=0, maxms=0, lastms=0

stealth*CLI> 
[Nov 15 02:31:42] NOTICE[13966]: chan_sip.c:14979 sip_devicestate: sip_devicestate(203) USER: call_limit=0, inUse=0

stealth*CLI> 
[Nov 15 02:31:42] DEBUG[13966]: devicestate.c:298 do_state_change: Changing state for SIP/203 - state 1 (Not in use)

stealth*CLI> 
[Nov 15 02:31:42] DEBUG[14524]: app_queue.c:552 changethread: Device 'SIP/201' changed to state '2' (In use)

stealth*CLI> 
[Nov 15 02:31:42] DEBUG[14525]: app_queue.c:552 changethread: Device 'SIP/201' changed to state '2' (In use)

stealth*CLI> 
[Nov 15 02:31:42] DEBUG[14526]: app_queue.c:552 changethread: Device 'SIP/203' changed to state '2' (In use)

stealth*CLI> 
[Nov 15 02:31:42] DEBUG[14527]: app_queue.c:552 changethread: Device 'SIP/203' changed to state '1' (Not in use)

stealth*CLI> 
[Nov 15 02:31:42] DEBUG[14528]: app_queue.c:552 changethread: Device 'SIP/203' changed to state '1' (Not in use)

stealth*CLI> whow qusohow qu
queues  queue   

stealth*CLI> show queues

stealth*CLI> 
operator     has 0 calls (max unlimited) in 'ringall' strategy (0s holdtime), W:0, C:2, 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 6597 secs ago)

stealth*CLI> 
      Sip/201 (In use) has taken 1 calls (last was 188 secs ago)

stealth*CLI> 
   No Callers

stealth*CLI> 


stealth*CLI> 
[Nov 15 02:31:54] DEBUG[13971]: chan_sip.c:5015 process_sdp: T38 state changed to 0 on channel SIP/201-09e2b390
[Nov 15 02:31:54] DEBUG[13971]: chan_sip.c:5092 process_sdp: We're settling with these formats: 0xc (ulaw|alaw)
[Nov 15 02:31:54] NOTICE[13971]: chan_sip.c:8037 sip_peer_hold: onHold now: 1;  hold arg was: 1
[Nov 15 02:31:54] 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:31:54] DEBUG[13971]: chan_sip.c:13276 handle_request_invite: SIP/201-09e2b390: This call is UP.... 
[Nov 15 02:31:54] DEBUG[13971]: chan_sip.c:6297 transmit_response_with_sdp: Setting framing from config on incoming call
[Nov 15 02:31:54] DEBUG[13971]: chan_sip.c:6065 add_sdp: ** Our capability: 0xc (ulaw|alaw) Video flag: True
[Nov 15 02:31:54] DEBUG[13971]: chan_sip.c:6066 add_sdp: ** Our prefcodec: 0x4 (ulaw) 
[Nov 15 02:31:54] DEBUG[13971]: chan_sip.c:6197 add_sdp: -- Done with adding codecs to SDP
[Nov 15 02:31:54] DEBUG[13971]: chan_sip.c:6242 add_sdp: Done building SDP. Settling with this capability: 0xc (ulaw|alaw)
[Nov 15 02:31:54] DEBUG[14516]: 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:31:54] DEBUG[14516]: channel.c:1908 ast_settimeout: Scheduling timer at 160 sample intervals

stealth*CLI> 
[Nov 15 02:31:54] DEBUG[13966]: chan_sip.c:14932 sip_devicestate: Checking device state for peer 201
[Nov 15 02:31:54] 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:31:54] DEBUG[13966]: devicestate.c:298 do_state_change: Changing state for SIP/201 - state 8 (On Hold)

stealth*CLI> 
[Nov 15 02:31:54] DEBUG[14516]: channel.c:2225 __ast_read: Generator got voice, switching to phase locked mode
[Nov 15 02:31:54] DEBUG[14516]: channel.c:1908 ast_settimeout: Scheduling timer at 0 sample intervals
[Nov 15 02:31:54] DEBUG[14516]: res_musiconhold.c:252 ast_moh_files_next: Zap/4-1 Opened file 0 '/var/lib/asterisk/moh/breathless'

stealth*CLI> 
[Nov 15 02:31:54] DEBUG[14533]: app_queue.c:552 changethread: Device 'SIP/201' changed to state '8' (On Hold)

stealth*CLI> 
[Nov 15 02:31:54] DEBUG[13971]: chan_sip.c:2047 __sip_ack: Stopping retransmission on '7345337644aff43602added52c8818b8@192.168.4.1' of Response 101: Match Not Found

stealth*CLI> 
[Nov 15 02:31:54] DEBUG[13971]: chan_sip.c:14522 sipsock_read: Invalid SIP message - rejected , no callid, len 334

stealth*CLI> 
[Nov 15 02:31:54] DEBUG[13971]: chan_sip.c:14522 sipsock_read: Invalid SIP message - rejected , no callid, len 331

stealth*CLI> show queues

stealth*CLI> 
operator     has 0 calls (max unlimited) in 'ringall' strategy (0s holdtime), W:0, C:2, 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 6601 secs ago)
      Sip/201 (On Hold) has taken 1 calls (last was 192 secs ago)
   No Callers


stealth*CLI> 
[Nov 15 02:31:56] DEBUG[13971]: chan_sip.c:5015 process_sdp: T38 state changed to 0 on channel SIP/201-09e2b390
[Nov 15 02:31:56] DEBUG[13971]: chan_sip.c:5092 process_sdp: We're settling with these formats: 0xc (ulaw|alaw)
[Nov 15 02:31:56] NOTICE[13971]: chan_sip.c:8037 sip_peer_hold: onHold now: 0;  hold arg was: 0
[Nov 15 02:31:56] 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:31:56] DEBUG[13971]: chan_sip.c:13276 handle_request_invite: SIP/201-09e2b390: This call is UP.... 
[Nov 15 02:31:56] DEBUG[13971]: chan_sip.c:6297 transmit_response_with_sdp: Setting framing from config on incoming call
[Nov 15 02:31:56] DEBUG[13971]: chan_sip.c:6065 add_sdp: ** Our capability: 0xc (ulaw|alaw) Video flag: True
[Nov 15 02:31:56] DEBUG[13971]: chan_sip.c:6066 add_sdp: ** Our prefcodec: 0x4 (ulaw) 
[Nov 15 02:31:56] DEBUG[13971]: chan_sip.c:6197 add_sdp: -- Done with adding codecs to SDP
[Nov 15 02:31:56] DEBUG[13971]: chan_sip.c:6242 add_sdp: Done building SDP. Settling with this capability: 0xc (ulaw|alaw)
[Nov 15 02:31:56] DEBUG[14516]: 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:31:56] DEBUG[14516]: channel.c:1908 ast_settimeout: Scheduling timer at 0 sample intervals

stealth*CLI> 
[Nov 15 02:31:56] DEBUG[13966]: chan_sip.c:14932 sip_devicestate: Checking device state for peer 201
[Nov 15 02:31:56] 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:31:56] DEBUG[13966]: devicestate.c:298 do_state_change: Changing state for SIP/201 - state 2 (In use)

stealth*CLI> 
[Nov 15 02:31:56] DEBUG[14534]: app_queue.c:552 changethread: Device 'SIP/201' changed to state '2' (In use)

stealth*CLI> 
[Nov 15 02:31:56] DEBUG[13971]: chan_sip.c:2047 __sip_ack: Stopping retransmission on '7345337644aff43602added52c8818b8@192.168.4.1' of Response 102: Match Not Found

stealth*CLI> 
[Nov 15 02:31:56] DEBUG[14516]: rtp.c:2576 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160
[Nov 15 02:31:56] DEBUG[14516]: rtp.c:2429 ast_rtp_raw_write: Difference is 16480, ms is 2080

stealth*CLI> show queues

stealth*CLI> 
operator     has 0 calls (max unlimited) in 'ringall' strategy (0s holdtime), W:0, C:2, 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 6603 secs ago)

stealth*CLI> 
      Sip/201 (In use) has taken 1 calls (last was 194 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:2, 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 6604 secs ago)

stealth*CLI> 
      Sip/201 (In use) has taken 1 calls (last was 195 secs ago)

stealth*CLI> 
   No Callers

stealth*CLI> 


stealth*CLI> 
[Nov 15 02:31:59] DEBUG[13971]: chan_sip.c:5015 process_sdp: T38 state changed to 0 on channel SIP/201-09e2b390
[Nov 15 02:31:59] DEBUG[13971]: chan_sip.c:5092 process_sdp: We're settling with these formats: 0xc (ulaw|alaw)
[Nov 15 02:31:59] NOTICE[13971]: chan_sip.c:8037 sip_peer_hold: onHold now: 1;  hold arg was: 1
[Nov 15 02:31:59] 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:31:59] DEBUG[13971]: chan_sip.c:13276 handle_request_invite: SIP/201-09e2b390: This call is UP.... 
[Nov 15 02:31:59] DEBUG[13971]: chan_sip.c:6297 transmit_response_with_sdp: Setting framing from config on incoming call
[Nov 15 02:31:59] DEBUG[13971]: chan_sip.c:6065 add_sdp: ** Our capability: 0xc (ulaw|alaw) Video flag: True
[Nov 15 02:31:59] DEBUG[13971]: chan_sip.c:6066 add_sdp: ** Our prefcodec: 0x4 (ulaw) 
[Nov 15 02:31:59] DEBUG[13971]: chan_sip.c:6197 add_sdp: -- Done with adding codecs to SDP
[Nov 15 02:31:59] DEBUG[13971]: chan_sip.c:6242 add_sdp: Done building SDP. Settling with this capability: 0xc (ulaw|alaw)
[Nov 15 02:31:59] DEBUG[14516]: 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:31:59] DEBUG[14516]: channel.c:1908 ast_settimeout: Scheduling timer at 160 sample intervals

stealth*CLI> 
[Nov 15 02:31:59] DEBUG[13966]: chan_sip.c:14932 sip_devicestate: Checking device state for peer 201
[Nov 15 02:31:59] 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:31:59] DEBUG[13966]: devicestate.c:298 do_state_change: Changing state for SIP/201 - state 8 (On Hold)

stealth*CLI> 
[Nov 15 02:31:59] DEBUG[14537]: app_queue.c:552 changethread: Device 'SIP/201' changed to state '8' (On Hold)

stealth*CLI> 
[Nov 15 02:31:59] DEBUG[14516]: channel.c:2225 __ast_read: Generator got voice, switching to phase locked mode
[Nov 15 02:31:59] DEBUG[14516]: channel.c:1908 ast_settimeout: Scheduling timer at 0 sample intervals
[Nov 15 02:31:59] DEBUG[14516]: res_musiconhold.c:252 ast_moh_files_next: Zap/4-1 Opened file 0 '/var/lib/asterisk/moh/breathless'

stealth*CLI> 
[Nov 15 02:31:59] DEBUG[13971]: chan_sip.c:2047 __sip_ack: Stopping retransmission on '7345337644aff43602added52c8818b8@192.168.4.1' of Response 103: Match Not Found

stealth*CLI> show queues

stealth*CLI> 
operator     has 0 calls (max unlimited) in 'ringall' strategy (0s holdtime), W:0, C:2, 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 6606 secs ago)
      Sip/201 (On Hold) has taken 1 calls (last was 197 secs ago)
   No Callers


stealth*CLI> show queues

stealth*CLI> 
operator     has 0 calls (max unlimited) in 'ringall' strategy (0s holdtime), W:0, C:2, A:0, SL:0.0% within 0s

stealth*CLI> 
   Members: 
      Agent/202 (Unavailable) has taken no calls yet
      Sip/203 (Not in use) has taken 1 calls (last was 6607 secs ago)
      Sip/201 (On Hold) has taken 1 calls (last was 198 secs ago)
   No Callers


stealth*CLI> 
[Nov 15 02:32:02] DEBUG[13971]: chan_sip.c:5015 process_sdp: T38 state changed to 0 on channel SIP/201-09e2b390
[Nov 15 02:32:02] DEBUG[13971]: chan_sip.c:5092 process_sdp: We're settling with these formats: 0xc (ulaw|alaw)
[Nov 15 02:32:02] NOTICE[13971]: chan_sip.c:8037 sip_peer_hold: onHold now: 0;  hold arg was: 0
[Nov 15 02:32:02] 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:32:02] DEBUG[13971]: chan_sip.c:13276 handle_request_invite: SIP/201-09e2b390: This call is UP.... 
[Nov 15 02:32:02] DEBUG[13971]: chan_sip.c:6297 transmit_response_with_sdp: Setting framing from config on incoming call

stealth*CLI> 
[Nov 15 02:32:02] DEBUG[13971]: chan_sip.c:6065 add_sdp: ** Our capability: 0xc (ulaw|alaw) Video flag: True
[Nov 15 02:32:02] DEBUG[13971]: chan_sip.c:6066 add_sdp: ** Our prefcodec: 0x4 (ulaw) 
[Nov 15 02:32:02] DEBUG[13971]: chan_sip.c:6197 add_sdp: -- Done with adding codecs to SDP
[Nov 15 02:32:02] DEBUG[13971]: chan_sip.c:6242 add_sdp: Done building SDP. Settling with this capability: 0xc (ulaw|alaw)

stealth*CLI> 
[Nov 15 02:32:02] DEBUG[14516]: 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:32:02] DEBUG[14516]: channel.c:1908 ast_settimeout: Scheduling timer at 0 sample intervals

stealth*CLI> 
[Nov 15 02:32:02] DEBUG[13966]: chan_sip.c:14932 sip_devicestate: Checking device state for peer 201

stealth*CLI> 
[Nov 15 02:32:02] DEBUG[14516]: rtp.c:2576 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160
[Nov 15 02:32:02] DEBUG[14516]: rtp.c:2429 ast_rtp_raw_write: Difference is 20648, ms is 2601

stealth*CLI> 
[Nov 15 02:32:02] 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:32:02] DEBUG[13966]: devicestate.c:298 do_state_change: Changing state for SIP/201 - state 2 (In use)

stealth*CLI> 
[Nov 15 02:32:02] DEBUG[14538]: app_queue.c:552 changethread: Device 'SIP/201' changed to state '2' (In use)

stealth*CLI> 
[Nov 15 02:32:02] DEBUG[13971]: chan_sip.c:2047 __sip_ack: Stopping retransmission on '7345337644aff43602added52c8818b8@192.168.4.1' 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:2, 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 6608 secs ago)
      Sip/201 (In use) has taken 1 calls (last was 199 secs ago)
   No Callers


stealth*CLI> 
[Nov 15 02:32:06] DEBUG[13971]: chan_sip.c:13918 handle_request_bye: Received bye, issuing owner hangup
.[Nov 15 02:32:06] DEBUG[14516]: channel.c:3679 ast_generic_bridge: Didn't get a frame from channel: SIP/201-09e2b390
[Nov 15 02:32:06] DEBUG[14516]: channel.c:3984 ast_channel_bridge: Bridge stops bridging channels Zap/4-1 and SIP/201-09e2b390
[Nov 15 02:32:06] DEBUG[14516]: channel.c:1606 ast_hangup: Hanging up channel 'SIP/201-09e2b390'
[Nov 15 02:32:06] DEBUG[14516]: chan_sip.c:3252 sip_hangup: Hangup call SIP/201-09e2b390, SIP callid 7345337644aff43602added52c8818b8@192.168.4.1)
[Nov 15 02:32:06] DEBUG[14516]: chan_sip.c:2950 update_call_counter: Updating call counter for incoming call
[Nov 15 02:32:06] DEBUG[14516]: chan_sip.c:2996 update_call_counter: Call from peer '201' removed from call limit 0
[Nov 15 02:32:06] DEBUG[14516]: devicestate.c:314 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/201
[Nov 15 02:32:06] DEBUG[14516]: devicestate.c:314 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/201-09e2b390
[Nov 15 02:32:06] DEBUG[14516]: pbx.c:2363 __ast_pbx_run: Spawn extension (from-zaptel,s,6) exited non-zero on 'Zap/4-1'
  == Spawn extension (from-zaptel, s, 6) exited non-zero on 'Zap/4-1'
[Nov 15 02:32:06] DEBUG[14516]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is ''
[Nov 15 02:32:06] DEBUG[14516]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is ''
[Nov 15 02:32:06] DEBUG[14516]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 's'
[Nov 15 02:32:06] DEBUG[14516]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'from-zaptel'
[Nov 15 02:32:06] DEBUG[14516]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'Zap/4-1'
[Nov 15 02:32:06] DEBUG[14516]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'SIP/201-09e2b390'
[Nov 15 02:32:06] DEBUG[14516]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'Queue'
[Nov 15 02:32:06] DEBUG[14516]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'operator|tWw|||120'
[Nov 15 02:32:06] DEBUG[14516]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '2006-11-15 02:31:40'
[Nov 15 02:32:06] DEBUG[14516]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '2006-11-15 02:31:40'
[Nov 15 02:32:06] DEBUG[14516]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '2006-11-15 02:32:06'
[Nov 15 02:32:06] DEBUG[14516]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '26'
[Nov 15 02:32:06] DEBUG[14516]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '26'
[Nov 15 02:32:06] DEBUG[14516]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'ANSWERED'
[Nov 15 02:32:06] DEBUG[14516]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION'
[Nov 15 02:32:06] DEBUG[14516]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is ''
[Nov 15 02:32:06] DEBUG[14516]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '1163529096.5'
[Nov 15 02:32:06] DEBUG[14516]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is ''
[Nov 15 02:32:06] DEBUG[14516]: channel.c:1606 ast_hangup: Hanging up channel 'Zap/4-1'
[Nov 15 02:32:06] DEBUG[14516]: chan_zap.c:2438 zt_hangup: zt_hangup(Zap/4-1)
[Nov 15 02:32:06] DEBUG[14516]: chan_zap.c:2471 zt_hangup: Hangup: channel: 4 index = 0, normal = 15, callwait = -1, thirdcall = -1
[Nov 15 02:32:06] DEBUG[14516]: chan_zap.c:1493 zt_disable_ec: disabled echo cancellation on channel 4
[Nov 15 02:32:06] DEBUG[14516]: chan_zap.c:2899 zt_setoption: Set option TDD MODE, value: OFF(0) on Zap/4-1
[Nov 15 02:32:06] DEBUG[14516]: chan_zap.c:1430 update_conf: Updated conferencing on 4, with 0 conference users
    -- Hungup 'Zap/4-1'
[Nov 15 02:32:06] DEBUG[14516]: devicestate.c:314 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Zap/4-1
[Nov 15 02:32:06] DEBUG[13966]: chan_sip.c:14932 sip_devicestate: Checking device state for peer 201
[Nov 15 02:32:06] 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
[Nov 15 02:32:06] NOTICE[13966]: chan_sip.c:14979 sip_devicestate: sip_devicestate(201) USER: call_limit=0, inUse=0
[Nov 15 02:32:06] DEBUG[13966]: devicestate.c:298 do_state_change: Changing state for SIP/201 - state 1 (Not in use)
[Nov 15 02:32:06] DEBUG[13966]: chan_sip.c:14932 sip_devicestate: Checking device state for peer 201
[Nov 15 02:32:06] 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
[Nov 15 02:32:06] NOTICE[13966]: chan_sip.c:14979 sip_devicestate: sip_devicestate(201) USER: call_limit=0, inUse=0
[Nov 15 02:32:06] DEBUG[13966]: devicestate.c:298 do_state_change: Changing state for SIP/201 - state 1 (Not in use)

stealth*CLI> 
[Nov 15 02:32:06] DEBUG[14541]: app_queue.c:552 changethread: Device 'SIP/201' changed to state '1' (Not in use)

stealth*CLI> 
[Nov 15 02:32:06] DEBUG[13966]: devicestate.c:298 do_state_change: Changing state for Zap/4 - state 0 (Unknown)

stealth*CLI> 
[Nov 15 02:32:06] DEBUG[14542]: app_queue.c:552 changethread: Device 'SIP/201' changed to state '1' (Not in use)

stealth*CLI> 
[Nov 15 02:32:06] DEBUG[14543]: 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> 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 6613 secs ago)

stealth*CLI> 
      Sip/201 (Not in use) has taken 2 calls (last was 1 secs ago)

stealth*CLI> 
   No Callers

stealth*CLI> 


stealth*CLI> 
Really destroying SIP dialog '7345337644aff43602added52c8818b8@192.168.4.1' Method: BYE

stealth*CLI> 
[Nov 15 02:32:09] DEBUG[13971]: chan_sip.c:14522 sipsock_read: Invalid SIP message - rejected , no callid, len 334

stealth*CLI> 
[Nov 15 02:32:09] DEBUG[13971]: chan_sip.c:14522 sipsock_read: Invalid SIP message - rejected , no callid, len 331

stealth*CLI>