=~=~=~=~=~=~=~=~=~=~=~= 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 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>