ilha1*CLI> core set debug 3
Core debug was 0 and is now 3
[Nov 15 11:07:17] DEBUG[12880]: chan_sip.c:4224 sip_alloc: Allocating new SIP dialog for YTZhNjE3Yjc3ZDg4NzkyZTdkNWMxYjExNmU0MjJkYWQ. - REGISTER (No RTP)
[Nov 15 11:07:17] DEBUG[12880]: chan_sip.c:4224 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
    -- Registered SIP 'xlite' at 192.168.0.254 port 14930 expires 3600
[Nov 15 11:07:17] DEBUG[12880]: devicestate.c:314 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/xlite
[Nov 15 11:07:17] DEBUG[12878]: chan_sip.c:14935 sip_devicestate: Checking device state for peer xlite
[Nov 15 11:07:17] NOTICE[12878]: chan_sip.c:14979 sip_devicestate: sip_devicestate(xlite) returning Not in use call-lim=0, inuse=0, onHold=0,  inRinging=0, maxms=2000, lastms=0
[Nov 15 11:07:17] NOTICE[12878]: chan_sip.c:14982 sip_devicestate: sip_devicestate(xlite) USER: call_limit=0, inUse=0
[Nov 15 11:07:17] DEBUG[12878]: devicestate.c:298 do_state_change: Changing state for SIP/xlite - state 1 (Not in use)
[Nov 15 11:07:17] DEBUG[12878]: chan_sip.c:14935 sip_devicestate: Checking device state for peer xlite
[Nov 15 11:07:17] NOTICE[12878]: chan_sip.c:14979 sip_devicestate: sip_devicestate(xlite) returning Not in use call-lim=0, inuse=0, onHold=0,  inRinging=0, maxms=2000, lastms=0
[Nov 15 11:07:17] NOTICE[12878]: chan_sip.c:14982 sip_devicestate: sip_devicestate(xlite) USER: call_limit=0, inUse=0
[Nov 15 11:07:17] DEBUG[12907]: app_queue.c:552 changethread: Device 'SIP/xlite' changed to state '1' (Not in use)
[Nov 15 11:07:17] DEBUG[12880]: chan_sip.c:2047 __sip_ack: Stopping retransmission on '7fb8ced77c5bea911145525b0c76aab0@192.168.0.252' of Request 102: Match Not Found
[Nov 15 11:07:17] NOTICE[12880]: chan_sip.c:11893 handle_response_peerpoke: Peer 'xlite' is now Reachable. (87ms / 2000ms)
[Nov 15 11:07:17] DEBUG[12880]: devicestate.c:314 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/xlite
Really destroying SIP dialog '7fb8ced77c5bea911145525b0c76aab0@192.168.0.252' Method: OPTIONS
[Nov 15 11:07:17] DEBUG[12878]: chan_sip.c:14935 sip_devicestate: Checking device state for peer xlite
[Nov 15 11:07:17] NOTICE[12878]: chan_sip.c:14979 sip_devicestate: sip_devicestate(xlite) returning Not in use call-lim=0, inuse=0, onHold=0,  inRinging=0, maxms=2000, lastms=87
[Nov 15 11:07:17] NOTICE[12878]: chan_sip.c:14982 sip_devicestate: sip_devicestate(xlite) USER: call_limit=0, inUse=0
[Nov 15 11:07:17] DEBUG[12878]: devicestate.c:298 do_state_change: Changing state for SIP/xlite - state 1 (Not in use)
[Nov 15 11:07:17] DEBUG[12878]: chan_sip.c:14935 sip_devicestate: Checking device state for peer xlite
[Nov 15 11:07:17] NOTICE[12878]: chan_sip.c:14979 sip_devicestate: sip_devicestate(xlite) returning Not in use call-lim=0, inuse=0, onHold=0,  inRinging=0, maxms=2000, lastms=87
[Nov 15 11:07:17] NOTICE[12878]: chan_sip.c:14982 sip_devicestate: sip_devicestate(xlite) USER: call_limit=0, inUse=0
[Nov 15 11:07:17] DEBUG[12908]: app_queue.c:552 changethread: Device 'SIP/xlite' changed to state '1' (Not in use)
[Nov 15 11:07:17] DEBUG[12880]: chan_sip.c:4224 sip_alloc: Allocating new SIP dialog for ZDY4MGY0MTRmOWFkYjhkY2JjOTk5ZTM1ODZhMDllYzY. - SUBSCRIBE (No RTP)
[Nov 15 11:07:17] DEBUG[12880]: chan_sip.c:4224 sip_alloc: Allocating new SIP dialog for YTBjMmRhMjZmYTM1Yjg1NTk5NjUzNDIzODFiOGY2MmM. - SUBSCRIBE (No RTP)
[Nov 15 11:07:17] DEBUG[12880]: chan_sip.c:14522 sipsock_read: Invalid SIP message - rejected , no callid, len 1044
Really destroying SIP dialog 'ZDY4MGY0MTRmOWFkYjhkY2JjOTk5ZTM1ODZhMDllYzY.' Method: SUBSCRIBE
Really destroying SIP dialog 'YTBjMmRhMjZmYTM1Yjg1NTk5NjUzNDIzODFiOGY2MmM.' Method: SUBSCRIBE
[Nov 15 11:07:21] DEBUG[12880]: chan_sip.c:4224 sip_alloc: Allocating new SIP dialog for (No Call-ID) - NOTIFY (No RTP)
[Nov 15 11:07:22] DEBUG[12880]: chan_sip.c:2047 __sip_ack: Stopping retransmission on '35f6975c6f0772766631d9464ad0a838@192.168.0.252' of Request 102: Match Not Found
Really destroying SIP dialog '35f6975c6f0772766631d9464ad0a838@192.168.0.252' Method: NOTIFY
[Nov 15 11:07:26] DEBUG[12880]: chan_sip.c:4224 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Nov 15 11:07:26] DEBUG[12880]: chan_sip.c:2047 __sip_ack: Stopping retransmission on '147262961f48ebab629194e516e65cec@192.168.0.252' of Request 102: Match Not Found
Really destroying SIP dialog '147262961f48ebab629194e516e65cec@192.168.0.252' Method: OPTIONS
[Nov 15 11:07:28] DEBUG[12880]: chan_sip.c:4224 sip_alloc: Allocating new SIP dialog for D2A8EC31-3F05-4986-95E4-08C62D5445BC@192.168.0.254 - REGISTER (No RTP)
[Nov 15 11:07:28] DEBUG[12880]: chan_sip.c:4224 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
    -- Registered SIP 'sjphone' at 192.168.0.254 port 5060 expires 120
[Nov 15 11:07:28] DEBUG[12880]: devicestate.c:314 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/sjphone
[Nov 15 11:07:28] DEBUG[12878]: chan_sip.c:14935 sip_devicestate: Checking device state for peer sjphone
[Nov 15 11:07:28] NOTICE[12878]: chan_sip.c:14979 sip_devicestate: sip_devicestate(sjphone) returning Not in use call-lim=0, inuse=0, onHold=0,  inRinging=0, maxms=2000, lastms=0
[Nov 15 11:07:28] NOTICE[12878]: chan_sip.c:14982 sip_devicestate: sip_devicestate(sjphone) USER: call_limit=0, inUse=0
[Nov 15 11:07:28] DEBUG[12878]: devicestate.c:298 do_state_change: Changing state for SIP/sjphone - state 1 (Not in use)
[Nov 15 11:07:28] DEBUG[12878]: chan_sip.c:14935 sip_devicestate: Checking device state for peer sjphone
[Nov 15 11:07:28] NOTICE[12878]: chan_sip.c:14979 sip_devicestate: sip_devicestate(sjphone) returning Not in use call-lim=0, inuse=0, onHold=0,  inRinging=0, maxms=2000, lastms=0
[Nov 15 11:07:28] NOTICE[12878]: chan_sip.c:14982 sip_devicestate: sip_devicestate(sjphone) USER: call_limit=0, inUse=0
[Nov 15 11:07:28] DEBUG[12910]: app_queue.c:552 changethread: Device 'SIP/sjphone' changed to state '1' (Not in use)
[Nov 15 11:07:31] DEBUG[12880]: chan_sip.c:2047 __sip_ack: Stopping retransmission on '29b25763777cb4592864869e71e81c1d@192.168.0.252' of Request 102: Match Not Found
[Nov 15 11:07:31] NOTICE[12880]: chan_sip.c:11893 handle_response_peerpoke: Peer 'sjphone' is now Lagged. (2889ms / 2000ms)
[Nov 15 11:07:31] DEBUG[12880]: devicestate.c:314 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/sjphone
Really destroying SIP dialog '29b25763777cb4592864869e71e81c1d@192.168.0.252' Method: OPTIONS
[Nov 15 11:07:31] DEBUG[12880]: chan_sip.c:14522 sipsock_read: Invalid SIP message - rejected , no callid, len 411
[Nov 15 11:07:31] DEBUG[12880]: chan_sip.c:14364 handle_request: Ignoring SIP message because of retransmit (REGISTER Seqno 2, ours 2)
[Nov 15 11:07:31] DEBUG[12878]: chan_sip.c:14935 sip_devicestate: Checking device state for peer sjphone
[Nov 15 11:07:31] NOTICE[12878]: chan_sip.c:14952 sip_devicestate: sip_devicestate(sjphone) returning Unavailable call-lim=0, inuse=0, onHold=0,  inRinging=0, maxms=2000, lastms=2889
[Nov 15 11:07:31] DEBUG[12880]: devicestate.c:314 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/sjphone
[Nov 15 11:07:31] DEBUG[12880]: chan_sip.c:14522 sipsock_read: Invalid SIP message - rejected , no callid, len 411
[Nov 15 11:07:31] DEBUG[12878]: devicestate.c:298 do_state_change: Changing state for SIP/sjphone - state 5 (Unavailable)
[Nov 15 11:07:31] DEBUG[12878]: chan_sip.c:14935 sip_devicestate: Checking device state for peer sjphone
[Nov 15 11:07:31] NOTICE[12878]: chan_sip.c:14952 sip_devicestate: sip_devicestate(sjphone) returning Unavailable call-lim=0, inuse=0, onHold=0,  inRinging=0, maxms=2000, lastms=2889
[Nov 15 11:07:31] DEBUG[12878]: chan_sip.c:14935 sip_devicestate: Checking device state for peer sjphone
[Nov 15 11:07:31] NOTICE[12878]: chan_sip.c:14952 sip_devicestate: sip_devicestate(sjphone) returning Unavailable call-lim=0, inuse=0, onHold=0,  inRinging=0, maxms=2000, lastms=2889
[Nov 15 11:07:31] DEBUG[12878]: devicestate.c:298 do_state_change: Changing state for SIP/sjphone - state 5 (Unavailable)
[Nov 15 11:07:31] DEBUG[12878]: chan_sip.c:14935 sip_devicestate: Checking device state for peer sjphone
[Nov 15 11:07:31] NOTICE[12878]: chan_sip.c:14952 sip_devicestate: sip_devicestate(sjphone) returning Unavailable call-lim=0, inuse=0, onHold=0,  inRinging=0, maxms=2000, lastms=2889
[Nov 15 11:07:31] DEBUG[12911]: app_queue.c:552 changethread: Device 'SIP/sjphone' changed to state '5' (Unavailable)
[Nov 15 11:07:31] DEBUG[12912]: app_queue.c:552 changethread: Device 'SIP/sjphone' changed to state '5' (Unavailable)
[Nov 15 11:07:32] DEBUG[12880]: chan_sip.c:4224 sip_alloc: Allocating new SIP dialog for (No Call-ID) - NOTIFY (No RTP)
[Nov 15 11:07:32] DEBUG[12880]: chan_sip.c:3054 sip_destroy: Destroying SIP dialog 239bd5e534c22a8675189b6e26453ff4@127.0.0.1
Really destroying SIP dialog '239bd5e534c22a8675189b6e26453ff4@127.0.0.1' Method: NOTIFY
[Nov 15 11:07:41] DEBUG[12880]: chan_sip.c:4224 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Nov 15 11:07:41] DEBUG[12880]: chan_sip.c:2047 __sip_ack: Stopping retransmission on '172757405732f2d865e2fcaf659bcb87@192.168.0.252' of Request 102: Match Not Found
[Nov 15 11:07:41] NOTICE[12880]: chan_sip.c:11893 handle_response_peerpoke: Peer 'sjphone' is now Reachable. (1ms / 2000ms)
[Nov 15 11:07:41] DEBUG[12880]: devicestate.c:314 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/sjphone
Really destroying SIP dialog '172757405732f2d865e2fcaf659bcb87@192.168.0.252' Method: OPTIONS
[Nov 15 11:07:41] DEBUG[12878]: chan_sip.c:14935 sip_devicestate: Checking device state for peer sjphone
[Nov 15 11:07:41] NOTICE[12878]: chan_sip.c:14979 sip_devicestate: sip_devicestate(sjphone) returning Not in use call-lim=0, inuse=0, onHold=0,  inRinging=0, maxms=2000, lastms=1
[Nov 15 11:07:41] NOTICE[12878]: chan_sip.c:14982 sip_devicestate: sip_devicestate(sjphone) USER: call_limit=0, inUse=0
[Nov 15 11:07:41] DEBUG[12878]: devicestate.c:298 do_state_change: Changing state for SIP/sjphone - state 1 (Not in use)
[Nov 15 11:07:41] DEBUG[12878]: chan_sip.c:14935 sip_devicestate: Checking device state for peer sjphone
[Nov 15 11:07:41] NOTICE[12878]: chan_sip.c:14979 sip_devicestate: sip_devicestate(sjphone) returning Not in use call-lim=0, inuse=0, onHold=0,  inRinging=0, maxms=2000, lastms=1
[Nov 15 11:07:41] NOTICE[12878]: chan_sip.c:14982 sip_devicestate: sip_devicestate(sjphone) USER: call_limit=0, inUse=0
[Nov 15 11:07:41] DEBUG[12914]: app_queue.c:552 changethread: Device 'SIP/sjphone' changed to state '1' (Not in use)
[Nov 15 11:07:49] DEBUG[12880]: chan_sip.c:1969 __sip_autodestruct: Auto destroying SIP dialog 'YTZhNjE3Yjc3ZDg4NzkyZTdkNWMxYjExNmU0MjJkYWQ.'
[Nov 15 11:07:49] DEBUG[12880]: chan_sip.c:3054 sip_destroy: Destroying SIP dialog YTZhNjE3Yjc3ZDg4NzkyZTdkNWMxYjExNmU0MjJkYWQ.
Really destroying SIP dialog 'YTZhNjE3Yjc3ZDg4NzkyZTdkNWMxYjExNmU0MjJkYWQ.' Method: REGISTER
[Nov 15 11:08:03] DEBUG[12880]: chan_sip.c:1969 __sip_autodestruct: Auto destroying SIP dialog 'D2A8EC31-3F05-4986-95E4-08C62D5445BC@192.168.0.254'
[Nov 15 11:08:03] DEBUG[12880]: chan_sip.c:3054 sip_destroy: Destroying SIP dialog D2A8EC31-3F05-4986-95E4-08C62D5445BC@192.168.0.254
Really destroying SIP dialog 'D2A8EC31-3F05-4986-95E4-08C62D5445BC@192.168.0.254' Method: REGISTER
[Nov 15 11:08:17] DEBUG[12880]: chan_sip.c:4224 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Nov 15 11:08:17] DEBUG[12880]: chan_sip.c:2047 __sip_ack: Stopping retransmission on '198e8442694c02d4643acffa1ba69e97@192.168.0.252' of Request 102: Match Not Found
Really destroying SIP dialog '198e8442694c02d4643acffa1ba69e97@192.168.0.252' Method: OPTIONS
[Nov 15 11:08:18] DEBUG[12880]: chan_sip.c:14522 sipsock_read: Invalid SIP message - rejected , no callid, len 1044
[Nov 15 11:08:18] DEBUG[12880]: chan_sip.c:4224 sip_alloc: Allocating new SIP dialog for MTVjYzNkMDc1NjE5ZjVlNTdmMzIyNWE3OTVmNjA5NDQ. - SUBSCRIBE (No RTP)
Really destroying SIP dialog 'MTVjYzNkMDc1NjE5ZjVlNTdmMzIyNWE3OTVmNjA5NDQ.' Method: SUBSCRIBE
[Nov 15 11:08:18] DEBUG[12880]: chan_sip.c:4224 sip_alloc: Allocating new SIP dialog for 3c2670131117-7oegehdqg2da@192-168-0-11 - REGISTER (No RTP)
[Nov 15 11:08:18] DEBUG[12880]: chan_sip.c:4224 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
    -- Registered SIP 'snom' at 192.168.0.11 port 5060 expires 3600
[Nov 15 11:08:18] DEBUG[12880]: devicestate.c:314 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/snom
[Nov 15 11:08:18] DEBUG[12878]: chan_sip.c:14935 sip_devicestate: Checking device state for peer snom
[Nov 15 11:08:18] NOTICE[12878]: chan_sip.c:14979 sip_devicestate: sip_devicestate(snom) returning Not in use call-lim=0, inuse=0, onHold=0,  inRinging=0, maxms=2000, lastms=41
[Nov 15 11:08:18] NOTICE[12878]: chan_sip.c:14982 sip_devicestate: sip_devicestate(snom) USER: call_limit=0, inUse=0
[Nov 15 11:08:18] DEBUG[12878]: devicestate.c:298 do_state_change: Changing state for SIP/snom - state 1 (Not in use)
[Nov 15 11:08:18] DEBUG[12878]: chan_sip.c:14935 sip_devicestate: Checking device state for peer snom
[Nov 15 11:08:18] NOTICE[12878]: chan_sip.c:14979 sip_devicestate: sip_devicestate(snom) returning Not in use call-lim=0, inuse=0, onHold=0,  inRinging=0, maxms=2000, lastms=41
[Nov 15 11:08:18] NOTICE[12878]: chan_sip.c:14982 sip_devicestate: sip_devicestate(snom) USER: call_limit=0, inUse=0
[Nov 15 11:08:18] DEBUG[12917]: app_queue.c:552 changethread: Device 'SIP/snom' changed to state '1' (Not in use)
[Nov 15 11:08:18] DEBUG[12880]: chan_sip.c:2047 __sip_ack: Stopping retransmission on '69d17f275f48bf4473bb21db13040d86@192.168.0.252' of Request 102: Match Not Found
Really destroying SIP dialog '69d17f275f48bf4473bb21db13040d86@192.168.0.252' Method: OPTIONS
[Nov 15 11:08:27] DEBUG[12880]: chan_sip.c:4224 sip_alloc: Allocating new SIP dialog for (No Call-ID) - NOTIFY (No RTP)
[Nov 15 11:08:27] DEBUG[12880]: chan_sip.c:2047 __sip_ack: Stopping retransmission on '197ccb0c19f21e977c575d4f1e0cd08a@192.168.0.252' of Request 102: Match Not Found
Really destroying SIP dialog '197ccb0c19f21e977c575d4f1e0cd08a@192.168.0.252' Method: NOTIFY
[Nov 15 11:08:37] DEBUG[12880]: chan_sip.c:14522 sipsock_read: Invalid SIP message - rejected , no callid, len 1080
[Nov 15 11:08:39] DEBUG[12880]: chan_sip.c:2534 do_setnat: Setting NAT on RTP to Off
[Nov 15 11:08:39] DEBUG[12880]: chan_sip.c:4224 sip_alloc: Allocating new SIP dialog for NjBmMzkxMTUxMjg5ZDY4NDA3MTU4MGI5NjIwNmEwODM. - INVITE (With RTP)
[Nov 15 11:08:39] DEBUG[12880]: chan_sip.c:2534 do_setnat: Setting NAT on RTP to Off
[Nov 15 11:08:39] DEBUG[12880]: chan_sip.c:2047 __sip_ack: Stopping retransmission on 'NjBmMzkxMTUxMjg5ZDY4NDA3MTU4MGI5NjIwNmEwODM.' of Response 1: Match Not Found
[Nov 15 11:08:39] DEBUG[12880]: chan_sip.c:2534 do_setnat: Setting NAT on RTP to Off
[Nov 15 11:08:39] DEBUG[12880]: chan_sip.c:5015 process_sdp: T38 state changed to 0 on channel <none>
[Nov 15 11:08:39] DEBUG[12880]: chan_sip.c:5092 process_sdp: We're settling with these formats: 0xe (gsm|ulaw|alaw)
[Nov 15 11:08:39] DEBUG[12880]: chan_sip.c:13136 handle_request_invite: Checking SIP call limits for device xlite
[Nov 15 11:08:39] DEBUG[12880]: chan_sip.c:2950 update_call_counter: Updating call counter for incoming call
[Nov 15 11:08:39] DEBUG[12880]: chan_sip.c:3022 update_call_counter: Call from user 'xlite' is 1 out of 0
[Nov 15 11:08:39] DEBUG[12880]: chan_sip.c:3731 sip_new: *** Our native formats are 0x8 (alaw)
[Nov 15 11:08:39] DEBUG[12880]: chan_sip.c:3732 sip_new: *** Joint capabilities are 0xe (gsm|ulaw|alaw)
[Nov 15 11:08:39] DEBUG[12880]: chan_sip.c:3733 sip_new: *** Our capabilities are 0xe (gsm|ulaw|alaw)
[Nov 15 11:08:39] DEBUG[12880]: chan_sip.c:3734 sip_new: *** AST_CODEC_CHOOSE formats are 0x8 (alaw)
[Nov 15 11:08:39] DEBUG[12880]: chan_sip.c:3757 sip_new: This channel will not be able to handle video.
[Nov 15 11:08:39] DEBUG[12880]: chan_sip.c:7828 build_route: build_route: Contact hop: <sip:xlite@192.168.0.254:14930>
[Nov 15 11:08:39] DEBUG[12880]: chan_sip.c:13209 handle_request_invite: SIP/xlite-08520d38: New call is still down.... Trying...
[Nov 15 11:08:39] DEBUG[12880]: devicestate.c:314 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/xlite-08520d38
[Nov 15 11:08:39] DEBUG[12878]: chan_sip.c:14935 sip_devicestate: Checking device state for peer xlite
[Nov 15 11:08:39] NOTICE[12878]: chan_sip.c:14979 sip_devicestate: sip_devicestate(xlite) returning Not in use call-lim=0, inuse=0, onHold=0,  inRinging=0, maxms=2000, lastms=101
[Nov 15 11:08:39] NOTICE[12878]: chan_sip.c:14982 sip_devicestate: sip_devicestate(xlite) USER: call_limit=0, inUse=1
[Nov 15 11:08:39] DEBUG[12878]: devicestate.c:298 do_state_change: Changing state for SIP/xlite - state 1 (Not in use)
[Nov 15 11:08:39] DEBUG[12878]: chan_sip.c:14935 sip_devicestate: Checking device state for peer xlite
[Nov 15 11:08:39] NOTICE[12878]: chan_sip.c:14979 sip_devicestate: sip_devicestate(xlite) returning Not in use call-lim=0, inuse=0, onHold=0,  inRinging=0, maxms=2000, lastms=101
[Nov 15 11:08:39] NOTICE[12878]: chan_sip.c:14982 sip_devicestate: sip_devicestate(xlite) USER: call_limit=0, inUse=1
[Nov 15 11:08:39] DEBUG[12920]: pbx.c:1767 pbx_extension_helper: Launching 'Dial'
    -- Executing [5000@default:1] Dial("SIP/xlite-08520d38", "SIP/sjphone") in new stack
[Nov 15 11:08:39] DEBUG[12920]: chan_sip.c:15024 sip_request_call: Asked to create a SIP channel with formats: 0x8 (alaw)
[Nov 15 11:08:39] DEBUG[12920]: chan_sip.c:4224 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP)
[Nov 15 11:08:39] DEBUG[12920]: chan_sip.c:2534 do_setnat: Setting NAT on RTP to Off
[Nov 15 11:08:39] DEBUG[12920]: chan_sip.c:3731 sip_new: *** Our native formats are 0x8 (alaw)
[Nov 15 11:08:39] DEBUG[12920]: chan_sip.c:3732 sip_new: *** Joint capabilities are 0x0 (nothing)
[Nov 15 11:08:39] DEBUG[12920]: chan_sip.c:3733 sip_new: *** Our capabilities are 0xe (gsm|ulaw|alaw)
[Nov 15 11:08:39] DEBUG[12920]: chan_sip.c:3734 sip_new: *** AST_CODEC_CHOOSE formats are 0x8 (alaw)
[Nov 15 11:08:39] DEBUG[12920]: chan_sip.c:3736 sip_new: *** Our preferred formats from the incoming channel are 0x8 (alaw)
[Nov 15 11:08:39] DEBUG[12920]: chan_sip.c:3757 sip_new: This channel will not be able to handle video.
[Nov 15 11:08:39] DEBUG[12920]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-default-5000-1.
[Nov 15 11:08:39] DEBUG[12920]: channel.c:3185 ast_channel_inherit_variables: Not copying variable SIPCALLID.
[Nov 15 11:08:39] DEBUG[12920]: channel.c:3185 ast_channel_inherit_variables: Not copying variable SIPUSERAGENT.
[Nov 15 11:08:39] DEBUG[12920]: channel.c:3185 ast_channel_inherit_variables: Not copying variable SIPDOMAIN.
[Nov 15 11:08:39] DEBUG[12920]: channel.c:3185 ast_channel_inherit_variables: Not copying variable SIPURI.
[Nov 15 11:08:39] DEBUG[12920]: chan_sip.c:2785 sip_call: Outgoing Call for sjphone
[Nov 15 11:08:39] DEBUG[12920]: chan_sip.c:2950 update_call_counter: Updating call counter for outgoing call
[Nov 15 11:08:39] DEBUG[12920]: chan_sip.c:3022 update_call_counter: Call to peer 'sjphone' is 1 out of 0
[Nov 15 11:08:39] DEBUG[12920]: devicestate.c:314 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/sjphone
[Nov 15 11:08:39] DEBUG[12920]: chan_sip.c:2799 sip_call: Our T38 capability (0), joint T38 capability (0)
[Nov 15 11:08:39] DEBUG[12920]: chan_sip.c:6065 add_sdp: ** Our capability: 0xe (gsm|ulaw|alaw) Video flag: False
[Nov 15 11:08:39] DEBUG[12920]: chan_sip.c:6066 add_sdp: ** Our prefcodec: 0x8 (alaw)
[Nov 15 11:08:39] DEBUG[12920]: chan_sip.c:6197 add_sdp: -- Done with adding codecs to SDP
[Nov 15 11:08:39] DEBUG[12920]: chan_sip.c:6242 add_sdp: Done building SDP. Settling with this capability: 0xe (gsm|ulaw|alaw)
    -- Called sjphone
[Nov 15 11:08:39] DEBUG[12878]: chan_sip.c:14935 sip_devicestate: Checking device state for peer sjphone
[Nov 15 11:08:39] NOTICE[12878]: chan_sip.c:14967 sip_devicestate: sip_devicestate(sjphone) returning Ringing call-lim=0, inuse=1, onHold=0,  inRinging=1, maxms=2000, lastms=1
[Nov 15 11:08:39] DEBUG[12878]: devicestate.c:298 do_state_change: Changing state for SIP/sjphone - state 6 (Ringing)
[Nov 15 11:08:39] DEBUG[12878]: chan_sip.c:14935 sip_devicestate: Checking device state for peer sjphone
[Nov 15 11:08:39] NOTICE[12878]: chan_sip.c:14967 sip_devicestate: sip_devicestate(sjphone) returning Ringing call-lim=0, inuse=1, onHold=0,  inRinging=1, maxms=2000, lastms=1
[Nov 15 11:08:39] DEBUG[12921]: app_queue.c:552 changethread: Device 'SIP/xlite' changed to state '1' (Not in use)
[Nov 15 11:08:39] DEBUG[12922]: app_queue.c:552 changethread: Device 'SIP/sjphone' changed to state '6' (Ringing)
[Nov 15 11:08:39] DEBUG[12880]: chan_sip.c:2089 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '4290fd3419c3f00c7fa6ecbc6542b843@192.168.0.252' Request 102: Found
[Nov 15 11:08:40] DEBUG[12880]: chan_sip.c:2089 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '4290fd3419c3f00c7fa6ecbc6542b843@192.168.0.252' Request 102: Found
[Nov 15 11:08:40] DEBUG[12880]: devicestate.c:314 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/sjphone-085222b8
    -- SIP/sjphone-085222b8 is ringing
[Nov 15 11:08:40] DEBUG[12878]: chan_sip.c:14935 sip_devicestate: Checking device state for peer sjphone
[Nov 15 11:08:40] NOTICE[12878]: chan_sip.c:14967 sip_devicestate: sip_devicestate(sjphone) returning Ringing call-lim=0, inuse=1, onHold=0,  inRinging=1, maxms=2000, lastms=1
[Nov 15 11:08:40] DEBUG[12878]: devicestate.c:298 do_state_change: Changing state for SIP/sjphone - state 6 (Ringing)
[Nov 15 11:08:40] DEBUG[12878]: chan_sip.c:14935 sip_devicestate: Checking device state for peer sjphone
[Nov 15 11:08:40] NOTICE[12878]: chan_sip.c:14967 sip_devicestate: sip_devicestate(sjphone) returning Ringing call-lim=0, inuse=1, onHold=0,  inRinging=1, maxms=2000, lastms=1
[Nov 15 11:08:40] DEBUG[12923]: app_queue.c:552 changethread: Device 'SIP/sjphone' changed to state '6' (Ringing)
[Nov 15 11:08:41] DEBUG[12880]: chan_sip.c:4224 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Nov 15 11:08:41] DEBUG[12880]: chan_sip.c:2047 __sip_ack: Stopping retransmission on '4c48cac63594cd9a19cf9d9435763c2b@192.168.0.252' of Request 102: Match Not Found
Really destroying SIP dialog '4c48cac63594cd9a19cf9d9435763c2b@192.168.0.252' Method: OPTIONS
[Nov 15 11:08:50] DEBUG[12880]: chan_sip.c:2030 __sip_ack: Acked pending invite 102
[Nov 15 11:08:50] DEBUG[12880]: chan_sip.c:2047 __sip_ack: Stopping retransmission on '4290fd3419c3f00c7fa6ecbc6542b843@192.168.0.252' of Request 102: Match Not Found
[Nov 15 11:08:50] DEBUG[12880]: chan_sip.c:5015 process_sdp: T38 state changed to 0 on channel SIP/sjphone-085222b8
[Nov 15 11:08:50] DEBUG[12880]: chan_sip.c:5092 process_sdp: We're settling with these formats: 0x8 (alaw)
[Nov 15 11:08:50] DEBUG[12880]: chan_sip.c:2950 update_call_counter: Updating call counter for outgoing call
[Nov 15 11:08:50] DEBUG[12880]: devicestate.c:314 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/sjphone
[Nov 15 11:08:50] DEBUG[12880]: chan_sip.c:7828 build_route: build_route: Contact hop: <sip:sjphone@192.168.0.254>
[Nov 15 11:08:50] DEBUG[12878]: chan_sip.c:14935 sip_devicestate: Checking device state for peer sjphone
[Nov 15 11:08:50] NOTICE[12878]: chan_sip.c:14975 sip_devicestate: sip_devicestate(sjphone) returning In use call-lim=0, inuse=1, onHold=0,  inRinging=0, maxms=2000, lastms=1
[Nov 15 11:08:50] DEBUG[12878]: devicestate.c:298 do_state_change: Changing state for SIP/sjphone - state 2 (In use)
[Nov 15 11:08:50] DEBUG[12878]: chan_sip.c:14935 sip_devicestate: Checking device state for peer sjphone
[Nov 15 11:08:50] NOTICE[12878]: chan_sip.c:14975 sip_devicestate: sip_devicestate(sjphone) returning In use call-lim=0, inuse=1, onHold=0,  inRinging=0, maxms=2000, lastms=1
[Nov 15 11:08:50] DEBUG[12920]: devicestate.c:314 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/sjphone-085222b8
    -- SIP/sjphone-085222b8 answered SIP/xlite-08520d38
[Nov 15 11:08:50] DEBUG[12920]: devicestate.c:314 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/xlite-08520d38
[Nov 15 11:08:50] DEBUG[12920]: chan_sip.c:3400 sip_answer: SIP answering channel: SIP/xlite-08520d38
[Nov 15 11:08:50] DEBUG[12920]: chan_sip.c:6297 transmit_response_with_sdp: Setting framing from config on incoming call
[Nov 15 11:08:50] DEBUG[12920]: chan_sip.c:6065 add_sdp: ** Our capability: 0xe (gsm|ulaw|alaw) Video flag: True
[Nov 15 11:08:50] DEBUG[12920]: chan_sip.c:6066 add_sdp: ** Our prefcodec: 0x0 (nothing)
[Nov 15 11:08:50] DEBUG[12920]: chan_sip.c:6197 add_sdp: -- Done with adding codecs to SDP
[Nov 15 11:08:50] DEBUG[12920]: chan_sip.c:6242 add_sdp: Done building SDP. Settling with this capability: 0xe (gsm|ulaw|alaw)
    -- Packet2Packet bridging SIP/xlite-08520d38 and SIP/sjphone-085222b8
[Nov 15 11:08:50] DEBUG[12878]: chan_sip.c:14935 sip_devicestate: Checking device state for peer sjphone
[Nov 15 11:08:50] NOTICE[12878]: chan_sip.c:14975 sip_devicestate: sip_devicestate(sjphone) returning In use call-lim=0, inuse=1, onHold=0,  inRinging=0, maxms=2000, lastms=1
[Nov 15 11:08:50] DEBUG[12878]: devicestate.c:298 do_state_change: Changing state for SIP/sjphone - state 2 (In use)
[Nov 15 11:08:50] DEBUG[12878]: chan_sip.c:14935 sip_devicestate: Checking device state for peer sjphone
[Nov 15 11:08:50] NOTICE[12878]: chan_sip.c:14975 sip_devicestate: sip_devicestate(sjphone) returning In use call-lim=0, inuse=1, onHold=0,  inRinging=0, maxms=2000, lastms=1
[Nov 15 11:08:50] DEBUG[12878]: chan_sip.c:14935 sip_devicestate: Checking device state for peer xlite
[Nov 15 11:08:50] NOTICE[12878]: chan_sip.c:14979 sip_devicestate: sip_devicestate(xlite) returning Not in use call-lim=0, inuse=0, onHold=0,  inRinging=0, maxms=2000, lastms=101
[Nov 15 11:08:50] NOTICE[12878]: chan_sip.c:14982 sip_devicestate: sip_devicestate(xlite) USER: call_limit=0, inUse=1
[Nov 15 11:08:50] DEBUG[12878]: devicestate.c:298 do_state_change: Changing state for SIP/xlite - state 1 (Not in use)
[Nov 15 11:08:50] DEBUG[12878]: chan_sip.c:14935 sip_devicestate: Checking device state for peer xlite
[Nov 15 11:08:50] NOTICE[12878]: chan_sip.c:14979 sip_devicestate: sip_devicestate(xlite) returning Not in use call-lim=0, inuse=0, onHold=0,  inRinging=0, maxms=2000, lastms=101
[Nov 15 11:08:50] NOTICE[12878]: chan_sip.c:14982 sip_devicestate: sip_devicestate(xlite) USER: call_limit=0, inUse=1
[Nov 15 11:08:50] DEBUG[12924]: app_queue.c:552 changethread: Device 'SIP/sjphone' changed to state '2' (In use)
[Nov 15 11:08:50] DEBUG[12925]: app_queue.c:552 changethread: Device 'SIP/sjphone' changed to state '2' (In use)
[Nov 15 11:08:50] DEBUG[12926]: app_queue.c:552 changethread: Device 'SIP/xlite' changed to state '1' (Not in use)
[Nov 15 11:08:50] DEBUG[12880]: chan_sip.c:2047 __sip_ack: Stopping retransmission on 'NjBmMzkxMTUxMjg5ZDY4NDA3MTU4MGI5NjIwNmEwODM.' of Response 2: Match Not Found
[Nov 15 11:08:50] DEBUG[12880]: chan_sip.c:1969 __sip_autodestruct: Auto destroying SIP dialog '3c2670131117-7oegehdqg2da@192-168-0-11'
[Nov 15 11:08:50] DEBUG[12880]: chan_sip.c:3054 sip_destroy: Destroying SIP dialog 3c2670131117-7oegehdqg2da@192-168-0-11
Really destroying SIP dialog '3c2670131117-7oegehdqg2da@192-168-0-11' Method: REGISTER
ilha1*CLI> show queues
fila         has 0 calls (max unlimited) in 'rrmemory' strategy (0s holdtime), W:0, C:0, A:0, SL:0.0% within 0s
   Members:
      SIP/snom (Not in use) has taken no calls yet
      SIP/sjphone (In use) has taken no calls yet
      SIP/xlite (Not in use) has taken no calls yet
   No Callers

[Nov 15 11:09:17] DEBUG[12880]: chan_sip.c:4224 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Nov 15 11:09:17] DEBUG[12880]: chan_sip.c:2047 __sip_ack: Stopping retransmission on '227a26c56cf5c9c0024214f45e1dc50a@192.168.0.252' of Request 102: Match Not Found
Really destroying SIP dialog '227a26c56cf5c9c0024214f45e1dc50a@192.168.0.252' Method: OPTIONS
[Nov 15 11:09:18] DEBUG[12880]: chan_sip.c:4224 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Nov 15 11:09:18] DEBUG[12880]: chan_sip.c:2047 __sip_ack: Stopping retransmission on '71ec474d7e6846a60729d0d129e5dc9f@192.168.0.252' of Request 102: Match Not Found
Really destroying SIP dialog '71ec474d7e6846a60729d0d129e5dc9f@192.168.0.252' Method: OPTIONS
[Nov 15 11:09:30] DEBUG[12880]: chan_sip.c:13918 handle_request_bye: Received bye, issuing owner hangup
.[Nov 15 11:09:30] DEBUG[12920]: rtp.c:2951 bridge_p2p_loop: Oooh, got a hangup
[Nov 15 11:09:30] DEBUG[12920]: channel.c:3918 ast_channel_bridge: Returning from native bridge, channels: SIP/xlite-08520d38, SIP/sjphone-085222b8
[Nov 15 11:09:30] DEBUG[12920]: channel.c:1606 ast_hangup: Hanging up channel 'SIP/sjphone-085222b8'
[Nov 15 11:09:30] DEBUG[12920]: chan_sip.c:3252 sip_hangup: Hangup call SIP/sjphone-085222b8, SIP callid 4290fd3419c3f00c7fa6ecbc6542b843@192.168.0.252)
[Nov 15 11:09:30] DEBUG[12920]: chan_sip.c:2950 update_call_counter: Updating call counter for outgoing call
[Nov 15 11:09:30] DEBUG[12920]: chan_sip.c:2996 update_call_counter: Call to peer 'sjphone' removed from call limit 0
[Nov 15 11:09:30] DEBUG[12920]: devicestate.c:314 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/sjphone
[Nov 15 11:09:30] DEBUG[12920]: devicestate.c:314 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/sjphone-085222b8
[Nov 15 11:09:30] DEBUG[12920]: rtp.c:1419 ast_rtp_early_bridge: Channel '<unspecified>' has no RTP, not doing anything
[Nov 15 11:09:30] DEBUG[12920]: app_dial.c:1639 dial_exec_full: Exiting with DIALSTATUS=ANSWER.
[Nov 15 11:09:30] DEBUG[12920]: pbx.c:2363 __ast_pbx_run: Spawn extension (default,5000,1) exited non-zero on 'SIP/xlite-08520d38'
  == Spawn extension (default, 5000, 1) exited non-zero on 'SIP/xlite-08520d38'
[Nov 15 11:09:30] DEBUG[12920]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '"Telefone 4000" <4000>'
[Nov 15 11:09:30] DEBUG[12920]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '4000'
[Nov 15 11:09:30] DEBUG[12920]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '5000'
[Nov 15 11:09:30] DEBUG[12920]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'default'
[Nov 15 11:09:30] DEBUG[12920]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'SIP/xlite-08520d38'
[Nov 15 11:09:30] DEBUG[12920]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'SIP/sjphone-085222b8'
[Nov 15 11:09:30] DEBUG[12920]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'Dial'
[Nov 15 11:09:30] DEBUG[12920]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'SIP/sjphone'
[Nov 15 11:09:30] DEBUG[12920]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '2006-11-15 11:08:39'
[Nov 15 11:09:30] DEBUG[12920]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '2006-11-15 11:08:50'
[Nov 15 11:09:30] DEBUG[12920]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '2006-11-15 11:09:30'
[Nov 15 11:09:30] DEBUG[12920]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '51'
[Nov 15 11:09:30] DEBUG[12920]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '40'
[Nov 15 11:09:30] DEBUG[12920]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'ANSWERED'
[Nov 15 11:09:30] DEBUG[12920]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION'
[Nov 15 11:09:30] DEBUG[12920]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is ''
[Nov 15 11:09:30] DEBUG[12920]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '1163599719.0'
[Nov 15 11:09:30] DEBUG[12920]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is ''
[Nov 15 11:09:30] DEBUG[12878]: chan_sip.c:14935 sip_devicestate: Checking device state for peer sjphone
[Nov 15 11:09:30] NOTICE[12878]: chan_sip.c:14979 sip_devicestate: sip_devicestate(sjphone) returning Not in use call-lim=0, inuse=0, onHold=0,  inRinging=0, maxms=2000, lastms=1
[Nov 15 11:09:30] NOTICE[12878]: chan_sip.c:14982 sip_devicestate: sip_devicestate(sjphone) USER: call_limit=0, inUse=0
[Nov 15 11:09:30] DEBUG[12878]: devicestate.c:298 do_state_change: Changing state for SIP/sjphone - state 1 (Not in use)
[Nov 15 11:09:30] DEBUG[12878]: chan_sip.c:14935 sip_devicestate: Checking device state for peer sjphone
[Nov 15 11:09:30] NOTICE[12878]: chan_sip.c:14979 sip_devicestate: sip_devicestate(sjphone) returning Not in use call-lim=0, inuse=0, onHold=0,  inRinging=0, maxms=2000, lastms=1
[Nov 15 11:09:30] NOTICE[12878]: chan_sip.c:14982 sip_devicestate: sip_devicestate(sjphone) USER: call_limit=0, inUse=0
[Nov 15 11:09:30] DEBUG[12878]: chan_sip.c:14935 sip_devicestate: Checking device state for peer sjphone
[Nov 15 11:09:30] NOTICE[12878]: chan_sip.c:14979 sip_devicestate: sip_devicestate(sjphone) returning Not in use call-lim=0, inuse=0, onHold=0,  inRinging=0, maxms=2000, lastms=1
[Nov 15 11:09:30] NOTICE[12878]: chan_sip.c:14982 sip_devicestate: sip_devicestate(sjphone) USER: call_limit=0, inUse=0
[Nov 15 11:09:30] DEBUG[12878]: devicestate.c:298 do_state_change: Changing state for SIP/sjphone - state 1 (Not in use)
[Nov 15 11:09:30] DEBUG[12878]: chan_sip.c:14935 sip_devicestate: Checking device state for peer sjphone
[Nov 15 11:09:30] NOTICE[12878]: chan_sip.c:14979 sip_devicestate: sip_devicestate(sjphone) returning Not in use call-lim=0, inuse=0, onHold=0,  inRinging=0, maxms=2000, lastms=1
[Nov 15 11:09:30] NOTICE[12878]: chan_sip.c:14982 sip_devicestate: sip_devicestate(sjphone) USER: call_limit=0, inUse=0
[Nov 15 11:09:30] DEBUG[12930]: app_queue.c:552 changethread: Device 'SIP/sjphone' changed to state '1' (Not in use)
[Nov 15 11:09:30] DEBUG[12931]: app_queue.c:552 changethread: Device 'SIP/sjphone' changed to state '1' (Not in use)
[Nov 15 11:09:30] DEBUG[12920]: channel.c:1606 ast_hangup: Hanging up channel 'SIP/xlite-08520d38'
[Nov 15 11:09:30] DEBUG[12920]: chan_sip.c:3252 sip_hangup: Hangup call SIP/xlite-08520d38, SIP callid NjBmMzkxMTUxMjg5ZDY4NDA3MTU4MGI5NjIwNmEwODM.)
[Nov 15 11:09:30] DEBUG[12920]: chan_sip.c:2950 update_call_counter: Updating call counter for incoming call
[Nov 15 11:09:30] DEBUG[12920]: chan_sip.c:2996 update_call_counter: Call from user 'xlite' removed from call limit 0
[Nov 15 11:09:30] DEBUG[12920]: devicestate.c:314 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/xlite-08520d38
[Nov 15 11:09:30] DEBUG[12878]: chan_sip.c:14935 sip_devicestate: Checking device state for peer xlite
[Nov 15 11:09:30] NOTICE[12878]: chan_sip.c:14979 sip_devicestate: sip_devicestate(xlite) returning Not in use call-lim=0, inuse=0, onHold=0,  inRinging=0, maxms=2000, lastms=103
[Nov 15 11:09:30] NOTICE[12878]: chan_sip.c:14982 sip_devicestate: sip_devicestate(xlite) USER: call_limit=0, inUse=0
[Nov 15 11:09:30] DEBUG[12878]: devicestate.c:298 do_state_change: Changing state for SIP/xlite - state 1 (Not in use)
[Nov 15 11:09:30] DEBUG[12878]: chan_sip.c:14935 sip_devicestate: Checking device state for peer xlite
[Nov 15 11:09:30] NOTICE[12878]: chan_sip.c:14979 sip_devicestate: sip_devicestate(xlite) returning Not in use call-lim=0, inuse=0, onHold=0,  inRinging=0, maxms=2000, lastms=103
[Nov 15 11:09:30] NOTICE[12878]: chan_sip.c:14982 sip_devicestate: sip_devicestate(xlite) USER: call_limit=0, inUse=0
[Nov 15 11:09:30] DEBUG[12932]: app_queue.c:552 changethread: Device 'SIP/xlite' changed to state '1' (Not in use)
[Nov 15 11:09:30] DEBUG[12880]: chan_sip.c:2047 __sip_ack: Stopping retransmission on '4290fd3419c3f00c7fa6ecbc6542b843@192.168.0.252' of Request 103: Match Not Found
Really destroying SIP dialog '4290fd3419c3f00c7fa6ecbc6542b843@192.168.0.252' Method: INVITE
Really destroying SIP dialog 'NjBmMzkxMTUxMjg5ZDY4NDA3MTU4MGI5NjIwNmEwODM.' Method: BYE
[Nov 15 11:09:30] DEBUG[12880]: chan_sip.c:14522 sipsock_read: Invalid SIP message - rejected , no callid, len 1044
[Nov 15 11:09:31] DEBUG[12880]: chan_sip.c:4224 sip_alloc: Allocating new SIP dialog for D2A8EC31-3F05-4986-95E4-08C62D5445BC@192.168.0.254 - REGISTER (No RTP)
[Nov 15 11:09:31] DEBUG[12880]: devicestate.c:314 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/sjphone
[Nov 15 11:09:31] DEBUG[12878]: chan_sip.c:14935 sip_devicestate: Checking device state for peer sjphone
[Nov 15 11:09:31] NOTICE[12878]: chan_sip.c:14979 sip_devicestate: sip_devicestate(sjphone) returning Not in use call-lim=0, inuse=0, onHold=0,  inRinging=0, maxms=2000, lastms=1
[Nov 15 11:09:31] NOTICE[12878]: chan_sip.c:14982 sip_devicestate: sip_devicestate(sjphone) USER: call_limit=0, inUse=0
[Nov 15 11:09:31] DEBUG[12878]: devicestate.c:298 do_state_change: Changing state for SIP/sjphone - state 1 (Not in use)
[Nov 15 11:09:31] DEBUG[12878]: chan_sip.c:14935 sip_devicestate: Checking device state for peer sjphone
[Nov 15 11:09:31] NOTICE[12878]: chan_sip.c:14979 sip_devicestate: sip_devicestate(sjphone) returning Not in use call-lim=0, inuse=0, onHold=0,  inRinging=0, maxms=2000, lastms=1
[Nov 15 11:09:31] NOTICE[12878]: chan_sip.c:14982 sip_devicestate: sip_devicestate(sjphone) USER: call_limit=0, inUse=0
[Nov 15 11:09:31] DEBUG[12933]: app_queue.c:552 changethread: Device 'SIP/sjphone' changed to state '1' (Not in use)
[Nov 15 11:09:33] DEBUG[12880]: chan_sip.c:4224 sip_alloc: Allocating new SIP dialog for (No Call-ID) - NOTIFY (No RTP)
[Nov 15 11:09:33] DEBUG[12880]: chan_sip.c:2047 __sip_ack: Stopping retransmission on '4d80e7c758d9a76107ce3ce16b84fce7@192.168.0.252' of Request 102: Match Not Found
Really destroying SIP dialog '4d80e7c758d9a76107ce3ce16b84fce7@192.168.0.252' Method: NOTIFY
ilha1*CLI> show queues
fila         has 0 calls (max unlimited) in 'rrmemory' strategy (0s holdtime), W:0, C:0, A:0, SL:0.0% within 0s
   Members:
      SIP/snom (Not in use) has taken no calls yet
      SIP/sjphone (Not in use) has taken no calls yet
      SIP/xlite (Not in use) has taken no calls yet
   No Callers

[Nov 15 11:09:41] DEBUG[12880]: chan_sip.c:4224 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Nov 15 11:09:41] DEBUG[12880]: chan_sip.c:2047 __sip_ack: Stopping retransmission on '7d38441a28a1ea0e6b32e74204f6d74e@192.168.0.252' of Request 102: Match Not Found
Really destroying SIP dialog '7d38441a28a1ea0e6b32e74204f6d74e@192.168.0.252' Method: OPTIONS
[Nov 15 11:09:42] DEBUG[12880]: chan_sip.c:14522 sipsock_read: Invalid SIP message - rejected , no callid, len 359
[Nov 15 11:09:42] DEBUG[12880]: chan_sip.c:14522 sipsock_read: Invalid SIP message - rejected , no callid, len 359
[Nov 15 11:09:42] DEBUG[12880]: chan_sip.c:14522 sipsock_read: Invalid SIP message - rejected , no callid, len 359
[Nov 15 11:09:43] DEBUG[12880]: chan_sip.c:14522 sipsock_read: Invalid SIP message - rejected , no callid, len 390
[Nov 15 11:09:43] DEBUG[12880]: chan_sip.c:2534 do_setnat: Setting NAT on RTP to Off
[Nov 15 11:09:43] DEBUG[12880]: chan_sip.c:4224 sip_alloc: Allocating new SIP dialog for 3c267067f1b3-8m3el721hnip@192-168-0-11 - INVITE (With RTP)
[Nov 15 11:09:43] DEBUG[12880]: chan_sip.c:2534 do_setnat: Setting NAT on RTP to Off
[Nov 15 11:09:43] DEBUG[12880]: chan_sip.c:2047 __sip_ack: Stopping retransmission on '3c267067f1b3-8m3el721hnip@192-168-0-11' of Response 1: Match Not Found
[Nov 15 11:09:43] DEBUG[12880]: chan_sip.c:2534 do_setnat: Setting NAT on RTP to Off
[Nov 15 11:09:43] DEBUG[12880]: chan_sip.c:5015 process_sdp: T38 state changed to 0 on channel <none>
[Nov 15 11:09:43] DEBUG[12880]: chan_sip.c:5092 process_sdp: We're settling with these formats: 0xe (gsm|ulaw|alaw)
[Nov 15 11:09:43] DEBUG[12880]: chan_sip.c:13136 handle_request_invite: Checking SIP call limits for device snom
[Nov 15 11:09:43] DEBUG[12880]: chan_sip.c:2950 update_call_counter: Updating call counter for incoming call
[Nov 15 11:09:43] DEBUG[12880]: chan_sip.c:3022 update_call_counter: Call from user 'snom' is 1 out of 0
[Nov 15 11:09:43] DEBUG[12880]: chan_sip.c:3731 sip_new: *** Our native formats are 0x8 (alaw)
[Nov 15 11:09:43] DEBUG[12880]: chan_sip.c:3732 sip_new: *** Joint capabilities are 0xe (gsm|ulaw|alaw)
[Nov 15 11:09:43] DEBUG[12880]: chan_sip.c:3733 sip_new: *** Our capabilities are 0xe (gsm|ulaw|alaw)
[Nov 15 11:09:43] DEBUG[12880]: chan_sip.c:3734 sip_new: *** AST_CODEC_CHOOSE formats are 0x8 (alaw)
[Nov 15 11:09:43] DEBUG[12880]: chan_sip.c:3757 sip_new: This channel will not be able to handle video.
[Nov 15 11:09:43] DEBUG[12880]: chan_sip.c:7828 build_route: build_route: Contact hop: <sip:snom@192.168.0.11:5060;line=e2mmetc1>
[Nov 15 11:09:43] DEBUG[12880]: chan_sip.c:13209 handle_request_invite: SIP/snom-08520d38: New call is still down.... Trying...
[Nov 15 11:09:43] DEBUG[12880]: devicestate.c:314 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/snom-08520d38
[Nov 15 11:09:43] DEBUG[12878]: chan_sip.c:14935 sip_devicestate: Checking device state for peer snom
[Nov 15 11:09:43] NOTICE[12878]: chan_sip.c:14979 sip_devicestate: sip_devicestate(snom) returning Not in use call-lim=0, inuse=0, onHold=0,  inRinging=0, maxms=2000, lastms=39
[Nov 15 11:09:43] NOTICE[12878]: chan_sip.c:14982 sip_devicestate: sip_devicestate(snom) USER: call_limit=0, inUse=1
[Nov 15 11:09:43] DEBUG[12878]: devicestate.c:298 do_state_change: Changing state for SIP/snom - state 1 (Not in use)
[Nov 15 11:09:43] DEBUG[12935]: pbx.c:1767 pbx_extension_helper: Launching 'Dial'
    -- Executing [5000@default:1] Dial("SIP/snom-08520d38", "SIP/sjphone") in new stack
[Nov 15 11:09:43] DEBUG[12935]: chan_sip.c:15024 sip_request_call: Asked to create a SIP channel with formats: 0x8 (alaw)
[Nov 15 11:09:43] DEBUG[12935]: chan_sip.c:4224 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP)
[Nov 15 11:09:43] DEBUG[12935]: chan_sip.c:2534 do_setnat: Setting NAT on RTP to Off
[Nov 15 11:09:43] DEBUG[12935]: chan_sip.c:3731 sip_new: *** Our native formats are 0x8 (alaw)
[Nov 15 11:09:43] DEBUG[12935]: chan_sip.c:3732 sip_new: *** Joint capabilities are 0x0 (nothing)
[Nov 15 11:09:43] DEBUG[12935]: chan_sip.c:3733 sip_new: *** Our capabilities are 0xe (gsm|ulaw|alaw)
[Nov 15 11:09:43] DEBUG[12935]: chan_sip.c:3734 sip_new: *** AST_CODEC_CHOOSE formats are 0x8 (alaw)
[Nov 15 11:09:43] DEBUG[12935]: chan_sip.c:3736 sip_new: *** Our preferred formats from the incoming channel are 0x8 (alaw)
[Nov 15 11:09:43] DEBUG[12935]: chan_sip.c:3757 sip_new: This channel will not be able to handle video.
[Nov 15 11:09:43] DEBUG[12935]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-default-5000-1.
[Nov 15 11:09:43] DEBUG[12935]: channel.c:3185 ast_channel_inherit_variables: Not copying variable SIPCALLID.
[Nov 15 11:09:43] DEBUG[12935]: channel.c:3185 ast_channel_inherit_variables: Not copying variable SIPUSERAGENT.
[Nov 15 11:09:43] DEBUG[12935]: channel.c:3185 ast_channel_inherit_variables: Not copying variable SIPDOMAIN.
[Nov 15 11:09:43] DEBUG[12935]: channel.c:3185 ast_channel_inherit_variables: Not copying variable SIPURI.
[Nov 15 11:09:43] DEBUG[12935]: chan_sip.c:2785 sip_call: Outgoing Call for sjphone
[Nov 15 11:09:43] DEBUG[12935]: chan_sip.c:2950 update_call_counter: Updating call counter for outgoing call
[Nov 15 11:09:43] DEBUG[12935]: chan_sip.c:3022 update_call_counter: Call to peer 'sjphone' is 1 out of 0
[Nov 15 11:09:43] DEBUG[12935]: devicestate.c:314 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/sjphone
[Nov 15 11:09:43] DEBUG[12935]: chan_sip.c:2799 sip_call: Our T38 capability (0), joint T38 capability (0)
[Nov 15 11:09:43] DEBUG[12935]: chan_sip.c:6065 add_sdp: ** Our capability: 0xe (gsm|ulaw|alaw) Video flag: False
[Nov 15 11:09:43] DEBUG[12935]: chan_sip.c:6066 add_sdp: ** Our prefcodec: 0x8 (alaw)
[Nov 15 11:09:43] DEBUG[12935]: chan_sip.c:6197 add_sdp: -- Done with adding codecs to SDP
[Nov 15 11:09:43] DEBUG[12935]: chan_sip.c:6242 add_sdp: Done building SDP. Settling with this capability: 0xe (gsm|ulaw|alaw)
    -- Called sjphone
[Nov 15 11:09:43] DEBUG[12878]: chan_sip.c:14935 sip_devicestate: Checking device state for peer snom
[Nov 15 11:09:43] NOTICE[12878]: chan_sip.c:14979 sip_devicestate: sip_devicestate(snom) returning Not in use call-lim=0, inuse=0, onHold=0,  inRinging=0, maxms=2000, lastms=39
[Nov 15 11:09:43] NOTICE[12878]: chan_sip.c:14982 sip_devicestate: sip_devicestate(snom) USER: call_limit=0, inUse=1
[Nov 15 11:09:43] DEBUG[12878]: chan_sip.c:14935 sip_devicestate: Checking device state for peer sjphone
[Nov 15 11:09:43] NOTICE[12878]: chan_sip.c:14967 sip_devicestate: sip_devicestate(sjphone) returning Ringing call-lim=0, inuse=1, onHold=0,  inRinging=1, maxms=2000, lastms=1
[Nov 15 11:09:43] DEBUG[12878]: devicestate.c:298 do_state_change: Changing state for SIP/sjphone - state 6 (Ringing)
[Nov 15 11:09:43] DEBUG[12878]: chan_sip.c:14935 sip_devicestate: Checking device state for peer sjphone
[Nov 15 11:09:43] NOTICE[12878]: chan_sip.c:14967 sip_devicestate: sip_devicestate(sjphone) returning Ringing call-lim=0, inuse=1, onHold=0,  inRinging=1, maxms=2000, lastms=1
[Nov 15 11:09:43] DEBUG[12936]: app_queue.c:552 changethread: Device 'SIP/snom' changed to state '1' (Not in use)
[Nov 15 11:09:43] DEBUG[12937]: app_queue.c:552 changethread: Device 'SIP/sjphone' changed to state '6' (Ringing)
[Nov 15 11:09:43] DEBUG[12880]: chan_sip.c:2089 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '3c522e2c12afb2973f2ce9ab557b9fe7@192.168.0.252' Request 102: Found
[Nov 15 11:09:43] DEBUG[12880]: chan_sip.c:2089 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '3c522e2c12afb2973f2ce9ab557b9fe7@192.168.0.252' Request 102: Found
[Nov 15 11:09:43] DEBUG[12880]: devicestate.c:314 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/sjphone-085222b8
    -- SIP/sjphone-085222b8 is ringing
[Nov 15 11:09:43] DEBUG[12878]: chan_sip.c:14935 sip_devicestate: Checking device state for peer sjphone
[Nov 15 11:09:43] NOTICE[12878]: chan_sip.c:14967 sip_devicestate: sip_devicestate(sjphone) returning Ringing call-lim=0, inuse=1, onHold=0,  inRinging=1, maxms=2000, lastms=1
[Nov 15 11:09:43] DEBUG[12878]: devicestate.c:298 do_state_change: Changing state for SIP/sjphone - state 6 (Ringing)
[Nov 15 11:09:43] DEBUG[12878]: chan_sip.c:14935 sip_devicestate: Checking device state for peer sjphone
[Nov 15 11:09:43] NOTICE[12878]: chan_sip.c:14967 sip_devicestate: sip_devicestate(sjphone) returning Ringing call-lim=0, inuse=1, onHold=0,  inRinging=1, maxms=2000, lastms=1
[Nov 15 11:09:43] DEBUG[12938]: app_queue.c:552 changethread: Device 'SIP/sjphone' changed to state '6' (Ringing)
ilha1*CLI> show queues
fila         has 0 calls (max unlimited) in 'rrmemory' strategy (0s holdtime), W:0, C:0, A:0, SL:0.0% within 0s
   Members:
      SIP/snom (Not in use) has taken no calls yet
      SIP/sjphone (Ringing) has taken no calls yet
      SIP/xlite (Not in use) has taken no calls yet
   No Callers

[Nov 15 11:09:54] DEBUG[12880]: chan_sip.c:2030 __sip_ack: Acked pending invite 102
[Nov 15 11:09:54] DEBUG[12880]: chan_sip.c:2047 __sip_ack: Stopping retransmission on '3c522e2c12afb2973f2ce9ab557b9fe7@192.168.0.252' of Request 102: Match Not Found
[Nov 15 11:09:54] DEBUG[12880]: chan_sip.c:5015 process_sdp: T38 state changed to 0 on channel SIP/sjphone-085222b8
[Nov 15 11:09:54] DEBUG[12880]: chan_sip.c:5092 process_sdp: We're settling with these formats: 0x8 (alaw)
[Nov 15 11:09:54] DEBUG[12880]: chan_sip.c:2950 update_call_counter: Updating call counter for outgoing call
[Nov 15 11:09:54] DEBUG[12880]: devicestate.c:314 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/sjphone
[Nov 15 11:09:54] DEBUG[12880]: chan_sip.c:7828 build_route: build_route: Contact hop: <sip:sjphone@192.168.0.254>
[Nov 15 11:09:54] DEBUG[12878]: chan_sip.c:14935 sip_devicestate: Checking device state for peer sjphone
[Nov 15 11:09:54] NOTICE[12878]: chan_sip.c:14975 sip_devicestate: sip_devicestate(sjphone) returning In use call-lim=0, inuse=1, onHold=0,  inRinging=0, maxms=2000, lastms=1
[Nov 15 11:09:54] DEBUG[12878]: devicestate.c:298 do_state_change: Changing state for SIP/sjphone - state 2 (In use)
[Nov 15 11:09:54] DEBUG[12878]: chan_sip.c:14935 sip_devicestate: Checking device state for peer sjphone
[Nov 15 11:09:54] NOTICE[12878]: chan_sip.c:14975 sip_devicestate: sip_devicestate(sjphone) returning In use call-lim=0, inuse=1, onHold=0,  inRinging=0, maxms=2000, lastms=1
[Nov 15 11:09:54] DEBUG[12935]: devicestate.c:314 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/sjphone-085222b8
[Nov 15 11:09:54] DEBUG[12878]: chan_sip.c:14935 sip_devicestate: Checking device state for peer sjphone
[Nov 15 11:09:54] NOTICE[12878]: chan_sip.c:14975 sip_devicestate: sip_devicestate(sjphone) returning In use call-lim=0, inuse=1, onHold=0,  inRinging=0, maxms=2000, lastms=1
[Nov 15 11:09:54] DEBUG[12878]: devicestate.c:298 do_state_change: Changing state for SIP/sjphone - state 2 (In use)
[Nov 15 11:09:54] DEBUG[12878]: chan_sip.c:14935 sip_devicestate: Checking device state for peer sjphone
[Nov 15 11:09:54] NOTICE[12878]: chan_sip.c:14975 sip_devicestate: sip_devicestate(sjphone) returning In use call-lim=0, inuse=1, onHold=0,  inRinging=0, maxms=2000, lastms=1
    -- SIP/sjphone-085222b8 answered SIP/snom-08520d38
[Nov 15 11:09:54] DEBUG[12935]: devicestate.c:314 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/snom-08520d38
[Nov 15 11:09:54] DEBUG[12878]: chan_sip.c:14935 sip_devicestate: Checking device state for peer snom
[Nov 15 11:09:54] NOTICE[12878]: chan_sip.c:14979 sip_devicestate: sip_devicestate(snom) returning Not in use call-lim=0, inuse=0, onHold=0,  inRinging=0, maxms=2000, lastms=39
[Nov 15 11:09:54] NOTICE[12878]: chan_sip.c:14982 sip_devicestate: sip_devicestate(snom) USER: call_limit=0, inUse=1
[Nov 15 11:09:54] DEBUG[12878]: devicestate.c:298 do_state_change: Changing state for SIP/snom - state 1 (Not in use)
[Nov 15 11:09:54] DEBUG[12878]: chan_sip.c:14935 sip_devicestate: Checking device state for peer snom
[Nov 15 11:09:54] NOTICE[12878]: chan_sip.c:14979 sip_devicestate: sip_devicestate(snom) returning Not in use call-lim=0, inuse=0, onHold=0,  inRinging=0, maxms=2000, lastms=39
[Nov 15 11:09:54] NOTICE[12878]: chan_sip.c:14982 sip_devicestate: sip_devicestate(snom) USER: call_limit=0, inUse=1
[Nov 15 11:09:54] DEBUG[12935]: chan_sip.c:3400 sip_answer: SIP answering channel: SIP/snom-08520d38
[Nov 15 11:09:54] DEBUG[12935]: chan_sip.c:6297 transmit_response_with_sdp: Setting framing from config on incoming call
[Nov 15 11:09:54] DEBUG[12935]: chan_sip.c:6065 add_sdp: ** Our capability: 0xe (gsm|ulaw|alaw) Video flag: True
[Nov 15 11:09:54] DEBUG[12935]: chan_sip.c:6066 add_sdp: ** Our prefcodec: 0x0 (nothing)
[Nov 15 11:09:54] DEBUG[12935]: chan_sip.c:6197 add_sdp: -- Done with adding codecs to SDP
[Nov 15 11:09:54] DEBUG[12935]: chan_sip.c:6242 add_sdp: Done building SDP. Settling with this capability: 0xe (gsm|ulaw|alaw)
    -- Packet2Packet bridging SIP/snom-08520d38 and SIP/sjphone-085222b8
[Nov 15 11:09:54] DEBUG[12939]: app_queue.c:552 changethread: Device 'SIP/sjphone' changed to state '2' (In use)
[Nov 15 11:09:54] DEBUG[12940]: app_queue.c:552 changethread: Device 'SIP/sjphone' changed to state '2' (In use)
[Nov 15 11:09:54] DEBUG[12941]: app_queue.c:552 changethread: Device 'SIP/snom' changed to state '1' (Not in use)
[Nov 15 11:09:54] DEBUG[12880]: chan_sip.c:2047 __sip_ack: Stopping retransmission on '3c267067f1b3-8m3el721hnip@192-168-0-11' of Response 2: Match Not Found
ilha1*CLI> show queues
fila         has 0 calls (max unlimited) in 'rrmemory' strategy (0s holdtime), W:0, C:0, A:0, SL:0.0% within 0s
   Members:
      SIP/snom (Not in use) has taken no calls yet
      SIP/sjphone (In use) has taken no calls yet
      SIP/xlite (Not in use) has taken no calls yet
   No Callers

[Nov 15 11:10:01] DEBUG[12880]: chan_sip.c:13918 handle_request_bye: Received bye, issuing owner hangup
.[Nov 15 11:10:01] DEBUG[12880]: rtp.c:1023 bridge_p2p_rtp_write: RTP Transmission error of packet to 0.0.0.0:0: Invalid argument
[Nov 15 11:10:01] DEBUG[12935]: rtp.c:2951 bridge_p2p_loop: Oooh, got a hangup
[Nov 15 11:10:01] DEBUG[12935]: channel.c:3918 ast_channel_bridge: Returning from native bridge, channels: SIP/snom-08520d38, SIP/sjphone-085222b8
[Nov 15 11:10:01] DEBUG[12935]: channel.c:1606 ast_hangup: Hanging up channel 'SIP/sjphone-085222b8'
[Nov 15 11:10:01] DEBUG[12935]: chan_sip.c:3252 sip_hangup: Hangup call SIP/sjphone-085222b8, SIP callid 3c522e2c12afb2973f2ce9ab557b9fe7@192.168.0.252)
[Nov 15 11:10:01] DEBUG[12935]: chan_sip.c:2950 update_call_counter: Updating call counter for outgoing call
[Nov 15 11:10:01] DEBUG[12935]: chan_sip.c:2996 update_call_counter: Call to peer 'sjphone' removed from call limit 0
[Nov 15 11:10:01] DEBUG[12935]: devicestate.c:314 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/sjphone
[Nov 15 11:10:01] DEBUG[12878]: chan_sip.c:14935 sip_devicestate: Checking device state for peer sjphone
[Nov 15 11:10:01] NOTICE[12878]: chan_sip.c:14979 sip_devicestate: sip_devicestate(sjphone) returning Not in use call-lim=0, inuse=0, onHold=0,  inRinging=0, maxms=2000, lastms=1
[Nov 15 11:10:01] NOTICE[12878]: chan_sip.c:14982 sip_devicestate: sip_devicestate(sjphone) USER: call_limit=0, inUse=0
[Nov 15 11:10:01] DEBUG[12878]: devicestate.c:298 do_state_change: Changing state for SIP/sjphone - state 1 (Not in use)
[Nov 15 11:10:01] DEBUG[12878]: chan_sip.c:14935 sip_devicestate: Checking device state for peer sjphone
[Nov 15 11:10:01] NOTICE[12878]: chan_sip.c:14979 sip_devicestate: sip_devicestate(sjphone) returning Not in use call-lim=0, inuse=0, onHold=0,  inRinging=0, maxms=2000, lastms=1
[Nov 15 11:10:01] NOTICE[12878]: chan_sip.c:14982 sip_devicestate: sip_devicestate(sjphone) USER: call_limit=0, inUse=0
[Nov 15 11:10:01] DEBUG[12935]: devicestate.c:314 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/sjphone-085222b8
[Nov 15 11:10:01] DEBUG[12878]: chan_sip.c:14935 sip_devicestate: Checking device state for peer sjphone
[Nov 15 11:10:01] NOTICE[12878]: chan_sip.c:14979 sip_devicestate: sip_devicestate(sjphone) returning Not in use call-lim=0, inuse=0, onHold=0,  inRinging=0, maxms=2000, lastms=1
[Nov 15 11:10:01] NOTICE[12878]: chan_sip.c:14982 sip_devicestate: sip_devicestate(sjphone) USER: call_limit=0, inUse=0
[Nov 15 11:10:01] DEBUG[12878]: devicestate.c:298 do_state_change: Changing state for SIP/sjphone - state 1 (Not in use)
[Nov 15 11:10:01] DEBUG[12878]: chan_sip.c:14935 sip_devicestate: Checking device state for peer sjphone
[Nov 15 11:10:01] NOTICE[12878]: chan_sip.c:14979 sip_devicestate: sip_devicestate(sjphone) returning Not in use call-lim=0, inuse=0, onHold=0,  inRinging=0, maxms=2000, lastms=1
[Nov 15 11:10:01] NOTICE[12878]: chan_sip.c:14982 sip_devicestate: sip_devicestate(sjphone) USER: call_limit=0, inUse=0
[Nov 15 11:10:01] DEBUG[12935]: rtp.c:1419 ast_rtp_early_bridge: Channel '<unspecified>' has no RTP, not doing anything
[Nov 15 11:10:01] DEBUG[12935]: app_dial.c:1639 dial_exec_full: Exiting with DIALSTATUS=ANSWER.
[Nov 15 11:10:01] DEBUG[12935]: pbx.c:2363 __ast_pbx_run: Spawn extension (default,5000,1) exited non-zero on 'SIP/snom-08520d38'
  == Spawn extension (default, 5000, 1) exited non-zero on 'SIP/snom-08520d38'
[Nov 15 11:10:01] DEBUG[12935]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '"Telefone 6000" <6000>'
[Nov 15 11:10:01] DEBUG[12935]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '6000'
[Nov 15 11:10:01] DEBUG[12935]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '5000'
[Nov 15 11:10:01] DEBUG[12935]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'default'
[Nov 15 11:10:01] DEBUG[12935]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'SIP/snom-08520d38'
[Nov 15 11:10:01] DEBUG[12935]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'SIP/sjphone-085222b8'
[Nov 15 11:10:01] DEBUG[12935]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'Dial'
[Nov 15 11:10:01] DEBUG[12935]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'SIP/sjphone'
[Nov 15 11:10:01] DEBUG[12935]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '2006-11-15 11:09:43'
[Nov 15 11:10:01] DEBUG[12935]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '2006-11-15 11:09:54'
[Nov 15 11:10:01] DEBUG[12935]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '2006-11-15 11:10:01'
[Nov 15 11:10:01] DEBUG[12935]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '18'
[Nov 15 11:10:01] DEBUG[12935]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '7'
[Nov 15 11:10:01] DEBUG[12935]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'ANSWERED'
[Nov 15 11:10:01] DEBUG[12935]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION'
[Nov 15 11:10:01] DEBUG[12935]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is ''
[Nov 15 11:10:01] DEBUG[12935]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '1163599783.2'
[Nov 15 11:10:01] DEBUG[12935]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is ''
[Nov 15 11:10:01] DEBUG[12935]: channel.c:1606 ast_hangup: Hanging up channel 'SIP/snom-08520d38'
[Nov 15 11:10:01] DEBUG[12935]: chan_sip.c:3252 sip_hangup: Hangup call SIP/snom-08520d38, SIP callid 3c267067f1b3-8m3el721hnip@192-168-0-11)
[Nov 15 11:10:01] DEBUG[12935]: chan_sip.c:2950 update_call_counter: Updating call counter for incoming call
[Nov 15 11:10:01] DEBUG[12935]: chan_sip.c:2996 update_call_counter: Call from user 'snom' removed from call limit 0
[Nov 15 11:10:01] DEBUG[12935]: devicestate.c:314 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/snom-08520d38
[Nov 15 11:10:01] DEBUG[12878]: chan_sip.c:14935 sip_devicestate: Checking device state for peer snom
[Nov 15 11:10:01] NOTICE[12878]: chan_sip.c:14979 sip_devicestate: sip_devicestate(snom) returning Not in use call-lim=0, inuse=0, onHold=0,  inRinging=0, maxms=2000, lastms=39
[Nov 15 11:10:01] NOTICE[12878]: chan_sip.c:14982 sip_devicestate: sip_devicestate(snom) USER: call_limit=0, inUse=0
[Nov 15 11:10:01] DEBUG[12878]: devicestate.c:298 do_state_change: Changing state for SIP/snom - state 1 (Not in use)
[Nov 15 11:10:01] DEBUG[12878]: chan_sip.c:14935 sip_devicestate: Checking device state for peer snom
[Nov 15 11:10:01] NOTICE[12878]: chan_sip.c:14979 sip_devicestate: sip_devicestate(snom) returning Not in use call-lim=0, inuse=0, onHold=0,  inRinging=0, maxms=2000, lastms=39
[Nov 15 11:10:01] NOTICE[12878]: chan_sip.c:14982 sip_devicestate: sip_devicestate(snom) USER: call_limit=0, inUse=0
[Nov 15 11:10:01] DEBUG[12943]: app_queue.c:552 changethread: Device 'SIP/sjphone' changed to state '1' (Not in use)
[Nov 15 11:10:01] DEBUG[12944]: app_queue.c:552 changethread: Device 'SIP/sjphone' changed to state '1' (Not in use)
[Nov 15 11:10:01] DEBUG[12945]: app_queue.c:552 changethread: Device 'SIP/snom' changed to state '1' (Not in use)
[Nov 15 11:10:01] DEBUG[12880]: chan_sip.c:2047 __sip_ack: Stopping retransmission on '3c522e2c12afb2973f2ce9ab557b9fe7@192.168.0.252' of Request 103: Match Not Found
Really destroying SIP dialog '3c522e2c12afb2973f2ce9ab557b9fe7@192.168.0.252' Method: INVITE
Really destroying SIP dialog '3c267067f1b3-8m3el721hnip@192-168-0-11' Method: BYE
[Nov 15 11:10:03] DEBUG[12880]: chan_sip.c:1969 __sip_autodestruct: Auto destroying SIP dialog 'D2A8EC31-3F05-4986-95E4-08C62D5445BC@192.168.0.254'
[Nov 15 11:10:03] DEBUG[12880]: chan_sip.c:3054 sip_destroy: Destroying SIP dialog D2A8EC31-3F05-4986-95E4-08C62D5445BC@192.168.0.254
Really destroying SIP dialog 'D2A8EC31-3F05-4986-95E4-08C62D5445BC@192.168.0.254' Method: REGISTER
ilha1*CLI> show queues
fila         has 0 calls (max unlimited) in 'rrmemory' strategy (0s holdtime), W:0, C:0, A:0, SL:0.0% within 0s
   Members:
      SIP/snom (Not in use) has taken no calls yet
      SIP/sjphone (Not in use) has taken no calls yet
      SIP/xlite (Not in use) has taken no calls yet
   No Callers

[Nov 15 11:10:11] DEBUG[12880]: chan_sip.c:14522 sipsock_read: Invalid SIP message - rejected , no callid, len 359
[Nov 15 11:10:11] DEBUG[12880]: chan_sip.c:14522 sipsock_read: Invalid SIP message - rejected , no callid, len 359
[Nov 15 11:10:12] DEBUG[12880]: chan_sip.c:14522 sipsock_read: Invalid SIP message - rejected , no callid, len 359
[Nov 15 11:10:12] DEBUG[12880]: chan_sip.c:14522 sipsock_read: Invalid SIP message - rejected , no callid, len 390
[Nov 15 11:10:12] DEBUG[12880]: chan_sip.c:2534 do_setnat: Setting NAT on RTP to Off
[Nov 15 11:10:12] DEBUG[12880]: chan_sip.c:4224 sip_alloc: Allocating new SIP dialog for 3c26708541eb-a7ehyxtprfpn@192-168-0-11 - INVITE (With RTP)
[Nov 15 11:10:12] DEBUG[12880]: chan_sip.c:2534 do_setnat: Setting NAT on RTP to Off
[Nov 15 11:10:12] DEBUG[12880]: chan_sip.c:2047 __sip_ack: Stopping retransmission on '3c26708541eb-a7ehyxtprfpn@192-168-0-11' of Response 1: Match Not Found
[Nov 15 11:10:12] DEBUG[12880]: chan_sip.c:2534 do_setnat: Setting NAT on RTP to Off
[Nov 15 11:10:12] DEBUG[12880]: chan_sip.c:5015 process_sdp: T38 state changed to 0 on channel <none>
[Nov 15 11:10:12] DEBUG[12880]: chan_sip.c:5092 process_sdp: We're settling with these formats: 0xe (gsm|ulaw|alaw)
[Nov 15 11:10:12] DEBUG[12880]: chan_sip.c:13136 handle_request_invite: Checking SIP call limits for device snom
[Nov 15 11:10:12] DEBUG[12880]: chan_sip.c:2950 update_call_counter: Updating call counter for incoming call
[Nov 15 11:10:12] DEBUG[12880]: chan_sip.c:3022 update_call_counter: Call from user 'snom' is 1 out of 0
[Nov 15 11:10:12] DEBUG[12880]: chan_sip.c:3731 sip_new: *** Our native formats are 0x8 (alaw)
[Nov 15 11:10:12] DEBUG[12880]: chan_sip.c:3732 sip_new: *** Joint capabilities are 0xe (gsm|ulaw|alaw)
[Nov 15 11:10:12] DEBUG[12880]: chan_sip.c:3733 sip_new: *** Our capabilities are 0xe (gsm|ulaw|alaw)
[Nov 15 11:10:12] DEBUG[12880]: chan_sip.c:3734 sip_new: *** AST_CODEC_CHOOSE formats are 0x8 (alaw)
[Nov 15 11:10:12] DEBUG[12880]: chan_sip.c:3757 sip_new: This channel will not be able to handle video.
[Nov 15 11:10:12] DEBUG[12880]: chan_sip.c:7828 build_route: build_route: Contact hop: <sip:snom@192.168.0.11:5060;line=e2mmetc1>
[Nov 15 11:10:12] DEBUG[12880]: chan_sip.c:13209 handle_request_invite: SIP/snom-084f89d8: New call is still down.... Trying...
[Nov 15 11:10:12] DEBUG[12880]: devicestate.c:314 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/snom-084f89d8
[Nov 15 11:10:12] DEBUG[12878]: chan_sip.c:14935 sip_devicestate: Checking device state for peer snom
[Nov 15 11:10:12] NOTICE[12878]: chan_sip.c:14979 sip_devicestate: sip_devicestate(snom) returning Not in use call-lim=0, inuse=0, onHold=0,  inRinging=0, maxms=2000, lastms=39
[Nov 15 11:10:12] NOTICE[12878]: chan_sip.c:14982 sip_devicestate: sip_devicestate(snom) USER: call_limit=0, inUse=1
[Nov 15 11:10:12] DEBUG[12878]: devicestate.c:298 do_state_change: Changing state for SIP/snom - state 1 (Not in use)
[Nov 15 11:10:12] DEBUG[12878]: chan_sip.c:14935 sip_devicestate: Checking device state for peer snom
[Nov 15 11:10:12] NOTICE[12878]: chan_sip.c:14979 sip_devicestate: sip_devicestate(snom) returning Not in use call-lim=0, inuse=0, onHold=0,  inRinging=0, maxms=2000, lastms=39
[Nov 15 11:10:12] NOTICE[12878]: chan_sip.c:14982 sip_devicestate: sip_devicestate(snom) USER: call_limit=0, inUse=1
[Nov 15 11:10:12] DEBUG[12947]: pbx.c:1767 pbx_extension_helper: Launching 'Dial'
    -- Executing [4000@default:1] Dial("SIP/snom-084f89d8", "SIP/xlite") in new stack
[Nov 15 11:10:12] DEBUG[12947]: chan_sip.c:15024 sip_request_call: Asked to create a SIP channel with formats: 0x8 (alaw)
[Nov 15 11:10:12] DEBUG[12947]: chan_sip.c:4224 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP)
[Nov 15 11:10:12] DEBUG[12947]: chan_sip.c:2534 do_setnat: Setting NAT on RTP to Off
[Nov 15 11:10:12] DEBUG[12947]: chan_sip.c:3731 sip_new: *** Our native formats are 0x8 (alaw)
[Nov 15 11:10:12] DEBUG[12947]: chan_sip.c:3732 sip_new: *** Joint capabilities are 0x0 (nothing)
[Nov 15 11:10:12] DEBUG[12947]: chan_sip.c:3733 sip_new: *** Our capabilities are 0xe (gsm|ulaw|alaw)
[Nov 15 11:10:12] DEBUG[12947]: chan_sip.c:3734 sip_new: *** AST_CODEC_CHOOSE formats are 0x8 (alaw)
[Nov 15 11:10:12] DEBUG[12947]: chan_sip.c:3736 sip_new: *** Our preferred formats from the incoming channel are 0x8 (alaw)
[Nov 15 11:10:12] DEBUG[12947]: chan_sip.c:3757 sip_new: This channel will not be able to handle video.
[Nov 15 11:10:12] DEBUG[12947]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-default-4000-1.
[Nov 15 11:10:12] DEBUG[12947]: channel.c:3185 ast_channel_inherit_variables: Not copying variable SIPCALLID.
[Nov 15 11:10:12] DEBUG[12947]: channel.c:3185 ast_channel_inherit_variables: Not copying variable SIPUSERAGENT.
[Nov 15 11:10:12] DEBUG[12947]: channel.c:3185 ast_channel_inherit_variables: Not copying variable SIPDOMAIN.
[Nov 15 11:10:12] DEBUG[12947]: channel.c:3185 ast_channel_inherit_variables: Not copying variable SIPURI.
[Nov 15 11:10:12] DEBUG[12947]: chan_sip.c:2785 sip_call: Outgoing Call for xlite
[Nov 15 11:10:12] DEBUG[12947]: chan_sip.c:2950 update_call_counter: Updating call counter for outgoing call
[Nov 15 11:10:12] DEBUG[12947]: chan_sip.c:3022 update_call_counter: Call to peer 'xlite' is 1 out of 0
[Nov 15 11:10:12] DEBUG[12947]: devicestate.c:314 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/xlite
[Nov 15 11:10:12] DEBUG[12947]: chan_sip.c:2799 sip_call: Our T38 capability (0), joint T38 capability (0)
[Nov 15 11:10:12] DEBUG[12947]: chan_sip.c:6065 add_sdp: ** Our capability: 0xe (gsm|ulaw|alaw) Video flag: False
[Nov 15 11:10:12] DEBUG[12947]: chan_sip.c:6066 add_sdp: ** Our prefcodec: 0x8 (alaw)
[Nov 15 11:10:12] DEBUG[12947]: chan_sip.c:6197 add_sdp: -- Done with adding codecs to SDP
[Nov 15 11:10:12] DEBUG[12947]: chan_sip.c:6242 add_sdp: Done building SDP. Settling with this capability: 0xe (gsm|ulaw|alaw)
    -- Called xlite
[Nov 15 11:10:12] DEBUG[12878]: chan_sip.c:14935 sip_devicestate: Checking device state for peer xlite
[Nov 15 11:10:12] NOTICE[12878]: chan_sip.c:14967 sip_devicestate: sip_devicestate(xlite) returning Ringing call-lim=0, inuse=1, onHold=0,  inRinging=1, maxms=2000, lastms=103
[Nov 15 11:10:12] DEBUG[12878]: devicestate.c:298 do_state_change: Changing state for SIP/xlite - state 6 (Ringing)
[Nov 15 11:10:12] DEBUG[12878]: chan_sip.c:14935 sip_devicestate: Checking device state for peer xlite
[Nov 15 11:10:12] NOTICE[12878]: chan_sip.c:14967 sip_devicestate: sip_devicestate(xlite) returning Ringing call-lim=0, inuse=1, onHold=0,  inRinging=1, maxms=2000, lastms=103
[Nov 15 11:10:12] DEBUG[12948]: app_queue.c:552 changethread: Device 'SIP/snom' changed to state '1' (Not in use)
[Nov 15 11:10:12] DEBUG[12949]: app_queue.c:552 changethread: Device 'SIP/xlite' changed to state '6' (Ringing)
[Nov 15 11:10:13] DEBUG[12880]: chan_sip.c:2089 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '05814a7369a011f960b4cc375ded1051@192.168.0.252' Request 102: Found
[Nov 15 11:10:13] DEBUG[12880]: devicestate.c:314 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/xlite-08524db8
    -- SIP/xlite-08524db8 is ringing
[Nov 15 11:10:13] DEBUG[12878]: chan_sip.c:14935 sip_devicestate: Checking device state for peer xlite
[Nov 15 11:10:13] NOTICE[12878]: chan_sip.c:14967 sip_devicestate: sip_devicestate(xlite) returning Ringing call-lim=0, inuse=1, onHold=0,  inRinging=1, maxms=2000, lastms=103
[Nov 15 11:10:13] DEBUG[12878]: devicestate.c:298 do_state_change: Changing state for SIP/xlite - state 6 (Ringing)
[Nov 15 11:10:13] DEBUG[12878]: chan_sip.c:14935 sip_devicestate: Checking device state for peer xlite
[Nov 15 11:10:13] NOTICE[12878]: chan_sip.c:14967 sip_devicestate: sip_devicestate(xlite) returning Ringing call-lim=0, inuse=1, onHold=0,  inRinging=1, maxms=2000, lastms=103
[Nov 15 11:10:13] DEBUG[12950]: app_queue.c:552 changethread: Device 'SIP/xlite' changed to state '6' (Ringing)
ilha1*CLI> show queues
fila         has 0 calls (max unlimited) in 'rrmemory' strategy (0s holdtime), W:0, C:0, A:0, SL:0.0% within 0s
   Members:
      SIP/snom (Not in use) has taken no calls yet
      SIP/sjphone (Not in use) has taken no calls yet
      SIP/xlite (Ringing) has taken no calls yet
   No Callers

[Nov 15 11:10:17] DEBUG[12880]: chan_sip.c:4224 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Nov 15 11:10:17] DEBUG[12880]: chan_sip.c:2047 __sip_ack: Stopping retransmission on '27a1d0ce15193d8034f4cedf31299ed6@192.168.0.252' of Request 102: Match Not Found
Really destroying SIP dialog '27a1d0ce15193d8034f4cedf31299ed6@192.168.0.252' Method: OPTIONS
[Nov 15 11:10:18] DEBUG[12880]: chan_sip.c:4224 sip_alloc: Allocating new SIP dialog for YzRmZGFiNWRiMWQ3ZDA4Y2RjYTY3YzQxZGMzNGMyYTI. - SUBSCRIBE (No RTP)
Really destroying SIP dialog 'YzRmZGFiNWRiMWQ3ZDA4Y2RjYTY3YzQxZGMzNGMyYTI.' Method: SUBSCRIBE
[Nov 15 11:10:18] DEBUG[12880]: chan_sip.c:4224 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Nov 15 11:10:18] DEBUG[12880]: chan_sip.c:2047 __sip_ack: Stopping retransmission on '0003c3db21d2166b01d0c60b04499c70@192.168.0.252' of Request 102: Match Not Found
Really destroying SIP dialog '0003c3db21d2166b01d0c60b04499c70@192.168.0.252' Method: OPTIONS
[Nov 15 11:10:21] DEBUG[12947]: rtp.c:808 ast_rtcp_read: Got RTCP report of 132 bytes
[Nov 15 11:10:21] DEBUG[12880]: chan_sip.c:2030 __sip_ack: Acked pending invite 102
[Nov 15 11:10:21] DEBUG[12880]: chan_sip.c:2047 __sip_ack: Stopping retransmission on '05814a7369a011f960b4cc375ded1051@192.168.0.252' of Request 102: Match Not Found
[Nov 15 11:10:21] DEBUG[12880]: chan_sip.c:5015 process_sdp: T38 state changed to 0 on channel SIP/xlite-08524db8
[Nov 15 11:10:21] DEBUG[12880]: chan_sip.c:5092 process_sdp: We're settling with these formats: 0xe (gsm|ulaw|alaw)
[Nov 15 11:10:21] DEBUG[12880]: chan_sip.c:2950 update_call_counter: Updating call counter for outgoing call
[Nov 15 11:10:21] DEBUG[12880]: devicestate.c:314 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/xlite
[Nov 15 11:10:21] DEBUG[12880]: chan_sip.c:7828 build_route: build_route: Contact hop: <sip:xlite@192.168.0.254:14930;rinstance=512b7f1e996433cc>
[Nov 15 11:10:21] DEBUG[12880]: chan_sip.c:14522 sipsock_read: Invalid SIP message - rejected , no callid, len 1080
[Nov 15 11:10:21] DEBUG[12878]: chan_sip.c:14935 sip_devicestate: Checking device state for peer xlite
[Nov 15 11:10:21] NOTICE[12878]: chan_sip.c:14975 sip_devicestate: sip_devicestate(xlite) returning In use call-lim=0, inuse=1, onHold=0,  inRinging=0, maxms=2000, lastms=101
[Nov 15 11:10:21] DEBUG[12878]: devicestate.c:298 do_state_change: Changing state for SIP/xlite - state 2 (In use)
[Nov 15 11:10:21] DEBUG[12878]: chan_sip.c:14935 sip_devicestate: Checking device state for peer xlite
[Nov 15 11:10:21] NOTICE[12878]: chan_sip.c:14975 sip_devicestate: sip_devicestate(xlite) returning In use call-lim=0, inuse=1, onHold=0,  inRinging=0, maxms=2000, lastms=101
[Nov 15 11:10:21] DEBUG[12947]: devicestate.c:314 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/xlite-08524db8
    -- SIP/xlite-08524db8 answered SIP/snom-084f89d8
[Nov 15 11:10:21] DEBUG[12947]: devicestate.c:314 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/snom-084f89d8
[Nov 15 11:10:21] DEBUG[12947]: chan_sip.c:3400 sip_answer: SIP answering channel: SIP/snom-084f89d8
[Nov 15 11:10:21] DEBUG[12947]: chan_sip.c:6297 transmit_response_with_sdp: Setting framing from config on incoming call
[Nov 15 11:10:21] DEBUG[12947]: chan_sip.c:6065 add_sdp: ** Our capability: 0xe (gsm|ulaw|alaw) Video flag: True
[Nov 15 11:10:21] DEBUG[12947]: chan_sip.c:6066 add_sdp: ** Our prefcodec: 0x0 (nothing)
[Nov 15 11:10:21] DEBUG[12947]: chan_sip.c:6197 add_sdp: -- Done with adding codecs to SDP
[Nov 15 11:10:21] DEBUG[12947]: chan_sip.c:6242 add_sdp: Done building SDP. Settling with this capability: 0xe (gsm|ulaw|alaw)
    -- Packet2Packet bridging SIP/snom-084f89d8 and SIP/xlite-08524db8
[Nov 15 11:10:21] DEBUG[12878]: chan_sip.c:14935 sip_devicestate: Checking device state for peer xlite
[Nov 15 11:10:21] NOTICE[12878]: chan_sip.c:14975 sip_devicestate: sip_devicestate(xlite) returning In use call-lim=0, inuse=1, onHold=0,  inRinging=0, maxms=2000, lastms=101
[Nov 15 11:10:21] DEBUG[12878]: devicestate.c:298 do_state_change: Changing state for SIP/xlite - state 2 (In use)
[Nov 15 11:10:21] DEBUG[12878]: chan_sip.c:14935 sip_devicestate: Checking device state for peer xlite
[Nov 15 11:10:21] NOTICE[12878]: chan_sip.c:14975 sip_devicestate: sip_devicestate(xlite) returning In use call-lim=0, inuse=1, onHold=0,  inRinging=0, maxms=2000, lastms=101
[Nov 15 11:10:21] DEBUG[12878]: chan_sip.c:14935 sip_devicestate: Checking device state for peer snom
[Nov 15 11:10:21] NOTICE[12878]: chan_sip.c:14979 sip_devicestate: sip_devicestate(snom) returning Not in use call-lim=0, inuse=0, onHold=0,  inRinging=0, maxms=2000, lastms=39
[Nov 15 11:10:21] NOTICE[12878]: chan_sip.c:14982 sip_devicestate: sip_devicestate(snom) USER: call_limit=0, inUse=1
[Nov 15 11:10:21] DEBUG[12878]: devicestate.c:298 do_state_change: Changing state for SIP/snom - state 1 (Not in use)
[Nov 15 11:10:21] DEBUG[12878]: chan_sip.c:14935 sip_devicestate: Checking device state for peer snom
[Nov 15 11:10:21] NOTICE[12878]: chan_sip.c:14979 sip_devicestate: sip_devicestate(snom) returning Not in use call-lim=0, inuse=0, onHold=0,  inRinging=0, maxms=2000, lastms=39
[Nov 15 11:10:21] NOTICE[12878]: chan_sip.c:14982 sip_devicestate: sip_devicestate(snom) USER: call_limit=0, inUse=1
[Nov 15 11:10:21] DEBUG[12951]: app_queue.c:552 changethread: Device 'SIP/xlite' changed to state '2' (In use)
[Nov 15 11:10:21] DEBUG[12952]: app_queue.c:552 changethread: Device 'SIP/xlite' changed to state '2' (In use)
[Nov 15 11:10:21] DEBUG[12953]: app_queue.c:552 changethread: Device 'SIP/snom' changed to state '1' (Not in use)
[Nov 15 11:10:21] DEBUG[12880]: chan_sip.c:2047 __sip_ack: Stopping retransmission on '3c26708541eb-a7ehyxtprfpn@192-168-0-11' of Response 2: Match Not Found
ilha1*CLI> show queues
fila         has 0 calls (max unlimited) in 'rrmemory' strategy (0s holdtime), W:0, C:0, A:0, SL:0.0% within 0s
   Members:
      SIP/snom (Not in use) has taken no calls yet
      SIP/sjphone (Not in use) has taken no calls yet
      SIP/xlite (In use) has taken no calls yet
   No Callers

[Nov 15 11:10:28] DEBUG[12880]: chan_sip.c:5015 process_sdp: T38 state changed to 0 on channel SIP/xlite-08524db8
[Nov 15 11:10:28] DEBUG[12880]: chan_sip.c:5092 process_sdp: We're settling with these formats: 0xe (gsm|ulaw|alaw)
[Nov 15 11:10:28] NOTICE[12880]: chan_sip.c:8037 sip_peer_hold: onHold now: 1;  hold arg was: 1
[Nov 15 11:10:28] DEBUG[12880]: devicestate.c:314 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/xlite
[Nov 15 11:10:28] DEBUG[12880]: chan_sip.c:13276 handle_request_invite: SIP/xlite-08524db8: This call is UP....
[Nov 15 11:10:28] DEBUG[12880]: chan_sip.c:6297 transmit_response_with_sdp: Setting framing from config on incoming call
[Nov 15 11:10:28] DEBUG[12880]: chan_sip.c:6065 add_sdp: ** Our capability: 0xe (gsm|ulaw|alaw) Video flag: True
[Nov 15 11:10:28] DEBUG[12880]: chan_sip.c:6066 add_sdp: ** Our prefcodec: 0x8 (alaw)
[Nov 15 11:10:28] DEBUG[12880]: chan_sip.c:6197 add_sdp: -- Done with adding codecs to SDP
[Nov 15 11:10:28] DEBUG[12880]: chan_sip.c:6242 add_sdp: Done building SDP. Settling with this capability: 0xe (gsm|ulaw|alaw)
    -- Started music on hold, class 'default', on SIP/snom-084f89d8
[Nov 15 11:10:28] DEBUG[12878]: chan_sip.c:14935 sip_devicestate: Checking device state for peer xlite
[Nov 15 11:10:28] NOTICE[12878]: chan_sip.c:14963 sip_devicestate: sip_devicestate(xlite) returning On Hold call-lim=0, inuse=1, onHold=1,  inRinging=0, maxms=2000, lastms=101
[Nov 15 11:10:28] DEBUG[12878]: devicestate.c:298 do_state_change: Changing state for SIP/xlite - state 8 (On Hold)
[Nov 15 11:10:28] DEBUG[12878]: chan_sip.c:14935 sip_devicestate: Checking device state for peer xlite
[Nov 15 11:10:28] NOTICE[12878]: chan_sip.c:14963 sip_devicestate: sip_devicestate(xlite) returning On Hold call-lim=0, inuse=1, onHold=1,  inRinging=0, maxms=2000, lastms=101
[Nov 15 11:10:28] DEBUG[12955]: app_queue.c:552 changethread: Device 'SIP/xlite' changed to state '8' (On Hold)
[Nov 15 11:10:28] DEBUG[12947]: chan_sip.c:4009 sip_rtp_read: Oooh, format changed to 4
[Nov 15 11:10:28] DEBUG[12947]: channel.c:2731 set_format: Set channel SIP/xlite-08524db8 to read format alaw
[Nov 15 11:10:28] DEBUG[12947]: channel.c:2731 set_format: Set channel SIP/xlite-08524db8 to write format alaw
[Nov 15 11:10:28] DEBUG[12947]: channel.c:2731 set_format: Set channel SIP/snom-084f89d8 to write format slin
[Nov 15 11:10:28] DEBUG[12947]: res_musiconhold.c:252 ast_moh_files_next: SIP/snom-084f89d8 Opened file 0 '/var/lib/asterisk/moh/fpm-sunshine'
[Nov 15 11:10:28] DEBUG[12947]: rtp.c:2563 ast_rtp_write: Ooh, format changed from unknown to alaw
[Nov 15 11:10:28] DEBUG[12947]: rtp.c:2580 ast_rtp_write: Created smoother: format: 8 ms: 20 len: 160
[Nov 15 11:10:28] DEBUG[12880]: chan_sip.c:2047 __sip_ack: Stopping retransmission on '05814a7369a011f960b4cc375ded1051@192.168.0.252' of Response 2: Match Not Found
[Nov 15 11:10:30] DEBUG[12947]: rtp.c:808 ast_rtcp_read: Got RTCP report of 176 bytes
ilha1*CLI> show queues
fila         has 0 calls (max unlimited) in 'rrmemory' strategy (0s holdtime), W:0, C:0, A:0, SL:0.0% within 0s
   Members:
      SIP/snom (Not in use) has taken no calls yet
      SIP/sjphone (Not in use) has taken no calls yet
      SIP/xlite (On Hold) has taken no calls yet
   No Callers

[Nov 15 11:10:33] DEBUG[12947]: rtp.c:808 ast_rtcp_read: Got RTCP report of 156 bytes
[Nov 15 11:10:33] DEBUG[12947]: rtp.c:808 ast_rtcp_read: Got RTCP report of 44 bytes
[Nov 15 11:10:33] DEBUG[12947]: rtp.c:903 ast_rtcp_read: Unknown RTCP packet (pt=207) received from 0.0.0.0:0
[Nov 15 11:10:36] DEBUG[12947]: rtp.c:808 ast_rtcp_read: Got RTCP report of 156 bytes
[Nov 15 11:10:36] DEBUG[12880]: chan_sip.c:5015 process_sdp: T38 state changed to 0 on channel SIP/xlite-08524db8
[Nov 15 11:10:36] DEBUG[12880]: chan_sip.c:5092 process_sdp: We're settling with these formats: 0xe (gsm|ulaw|alaw)
[Nov 15 11:10:36] NOTICE[12880]: chan_sip.c:8037 sip_peer_hold: onHold now: 0;  hold arg was: 0
[Nov 15 11:10:36] DEBUG[12880]: devicestate.c:314 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/xlite
[Nov 15 11:10:36] DEBUG[12880]: chan_sip.c:13276 handle_request_invite: SIP/xlite-08524db8: This call is UP....
[Nov 15 11:10:36] DEBUG[12880]: chan_sip.c:6297 transmit_response_with_sdp: Setting framing from config on incoming call
[Nov 15 11:10:36] DEBUG[12880]: chan_sip.c:6065 add_sdp: ** Our capability: 0xe (gsm|ulaw|alaw) Video flag: True
[Nov 15 11:10:36] DEBUG[12880]: chan_sip.c:6066 add_sdp: ** Our prefcodec: 0x8 (alaw)
[Nov 15 11:10:36] DEBUG[12880]: chan_sip.c:6197 add_sdp: -- Done with adding codecs to SDP
[Nov 15 11:10:36] DEBUG[12880]: chan_sip.c:6242 add_sdp: Done building SDP. Settling with this capability: 0xe (gsm|ulaw|alaw)
    -- Stopped music on hold on SIP/snom-084f89d8
[Nov 15 11:10:36] DEBUG[12947]: channel.c:2731 set_format: Set channel SIP/snom-084f89d8 to write format alaw
[Nov 15 11:10:36] DEBUG[12878]: chan_sip.c:14935 sip_devicestate: Checking device state for peer xlite
[Nov 15 11:10:36] NOTICE[12878]: chan_sip.c:14975 sip_devicestate: sip_devicestate(xlite) returning In use call-lim=0, inuse=1, onHold=0,  inRinging=0, maxms=2000, lastms=101
[Nov 15 11:10:36] DEBUG[12878]: devicestate.c:298 do_state_change: Changing state for SIP/xlite - state 2 (In use)
[Nov 15 11:10:36] DEBUG[12878]: chan_sip.c:14935 sip_devicestate: Checking device state for peer xlite
[Nov 15 11:10:36] NOTICE[12878]: chan_sip.c:14975 sip_devicestate: sip_devicestate(xlite) returning In use call-lim=0, inuse=1, onHold=0,  inRinging=0, maxms=2000, lastms=101
[Nov 15 11:10:36] DEBUG[12956]: app_queue.c:552 changethread: Device 'SIP/xlite' changed to state '2' (In use)
[Nov 15 11:10:37] DEBUG[12880]: chan_sip.c:2047 __sip_ack: Stopping retransmission on '05814a7369a011f960b4cc375ded1051@192.168.0.252' of Response 3: Match Not Found
ilha1*CLI> show queues
fila         has 0 calls (max unlimited) in 'rrmemory' strategy (0s holdtime), W:0, C:0, A:0, SL:0.0% within 0s
   Members:
      SIP/snom (Not in use) has taken no calls yet
      SIP/sjphone (Not in use) has taken no calls yet
      SIP/xlite (In use) has taken no calls yet
   No Callers

[Nov 15 11:10:41] DEBUG[12880]: chan_sip.c:4224 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Nov 15 11:10:41] DEBUG[12880]: chan_sip.c:2047 __sip_ack: Stopping retransmission on '6bbf82e70cd0627e350b12e6072b9fee@192.168.0.252' of Request 102: Match Not Found
Really destroying SIP dialog '6bbf82e70cd0627e350b12e6072b9fee@192.168.0.252' Method: OPTIONS
[Nov 15 11:10:42] DEBUG[12880]: chan_sip.c:13918 handle_request_bye: Received bye, issuing owner hangup
.[Nov 15 11:10:42] DEBUG[12947]: rtp.c:2951 bridge_p2p_loop: Oooh, got a hangup
[Nov 15 11:10:42] DEBUG[12947]: channel.c:3918 ast_channel_bridge: Returning from native bridge, channels: SIP/snom-084f89d8, SIP/xlite-08524db8
[Nov 15 11:10:42] DEBUG[12947]: channel.c:1606 ast_hangup: Hanging up channel 'SIP/xlite-08524db8'
[Nov 15 11:10:42] DEBUG[12947]: chan_sip.c:3252 sip_hangup: Hangup call SIP/xlite-08524db8, SIP callid 05814a7369a011f960b4cc375ded1051@192.168.0.252)
[Nov 15 11:10:42] DEBUG[12947]: chan_sip.c:2950 update_call_counter: Updating call counter for incoming call
[Nov 15 11:10:42] DEBUG[12947]: chan_sip.c:2996 update_call_counter: Call from user 'xlite' removed from call limit 0
[Nov 15 11:10:42] DEBUG[12947]: devicestate.c:314 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/xlite-08524db8
[Nov 15 11:10:42] DEBUG[12947]: rtp.c:1419 ast_rtp_early_bridge: Channel '<unspecified>' has no RTP, not doing anything
[Nov 15 11:10:42] DEBUG[12947]: app_dial.c:1639 dial_exec_full: Exiting with DIALSTATUS=ANSWER.
[Nov 15 11:10:42] DEBUG[12947]: pbx.c:2363 __ast_pbx_run: Spawn extension (default,4000,1) exited non-zero on 'SIP/snom-084f89d8'
  == Spawn extension (default, 4000, 1) exited non-zero on 'SIP/snom-084f89d8'
[Nov 15 11:10:42] DEBUG[12947]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '"Telefone 6000" <6000>'
[Nov 15 11:10:42] DEBUG[12947]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '6000'
[Nov 15 11:10:42] DEBUG[12947]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '4000'
[Nov 15 11:10:42] DEBUG[12947]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'default'
[Nov 15 11:10:42] DEBUG[12947]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'SIP/snom-084f89d8'
[Nov 15 11:10:42] DEBUG[12947]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'SIP/xlite-08524db8'
[Nov 15 11:10:42] DEBUG[12947]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'Dial'
[Nov 15 11:10:42] DEBUG[12947]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'SIP/xlite'
[Nov 15 11:10:42] DEBUG[12947]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '2006-11-15 11:10:12'
[Nov 15 11:10:42] DEBUG[12947]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '2006-11-15 11:10:21'
[Nov 15 11:10:42] DEBUG[12947]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '2006-11-15 11:10:42'
[Nov 15 11:10:42] DEBUG[12947]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '30'
[Nov 15 11:10:42] DEBUG[12947]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '21'
[Nov 15 11:10:42] DEBUG[12947]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'ANSWERED'
[Nov 15 11:10:42] DEBUG[12947]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION'
[Nov 15 11:10:42] DEBUG[12947]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is ''
[Nov 15 11:10:42] DEBUG[12947]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '1163599812.4'
[Nov 15 11:10:42] DEBUG[12947]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is ''
[Nov 15 11:10:42] DEBUG[12947]: channel.c:1606 ast_hangup: Hanging up channel 'SIP/snom-084f89d8'
[Nov 15 11:10:42] DEBUG[12947]: chan_sip.c:3252 sip_hangup: Hangup call SIP/snom-084f89d8, SIP callid 3c26708541eb-a7ehyxtprfpn@192-168-0-11)
[Nov 15 11:10:42] DEBUG[12947]: chan_sip.c:2950 update_call_counter: Updating call counter for incoming call
[Nov 15 11:10:42] DEBUG[12947]: chan_sip.c:2996 update_call_counter: Call from user 'snom' removed from call limit 0
[Nov 15 11:10:42] DEBUG[12947]: devicestate.c:314 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/snom-084f89d8
[Nov 15 11:10:42] DEBUG[12880]: chan_sip.c:14522 sipsock_read: Invalid SIP message - rejected , no callid, len 1044
Really destroying SIP dialog '05814a7369a011f960b4cc375ded1051@192.168.0.252' Method: BYE
[Nov 15 11:10:42] DEBUG[12878]: chan_sip.c:14935 sip_devicestate: Checking device state for peer xlite
[Nov 15 11:10:42] NOTICE[12878]: chan_sip.c:14975 sip_devicestate: sip_devicestate(xlite) returning In use call-lim=0, inuse=1, onHold=0,  inRinging=0, maxms=2000, lastms=101
[Nov 15 11:10:42] DEBUG[12878]: devicestate.c:298 do_state_change: Changing state for SIP/xlite - state 2 (In use)
[Nov 15 11:10:42] DEBUG[12878]: chan_sip.c:14935 sip_devicestate: Checking device state for peer xlite
[Nov 15 11:10:42] NOTICE[12878]: chan_sip.c:14975 sip_devicestate: sip_devicestate(xlite) returning In use call-lim=0, inuse=1, onHold=0,  inRinging=0, maxms=2000, lastms=101
[Nov 15 11:10:42] DEBUG[12878]: chan_sip.c:14935 sip_devicestate: Checking device state for peer snom
[Nov 15 11:10:42] NOTICE[12878]: chan_sip.c:14979 sip_devicestate: sip_devicestate(snom) returning Not in use call-lim=0, inuse=0, onHold=0,  inRinging=0, maxms=2000, lastms=39
[Nov 15 11:10:42] NOTICE[12878]: chan_sip.c:14982 sip_devicestate: sip_devicestate(snom) USER: call_limit=0, inUse=0
[Nov 15 11:10:42] DEBUG[12878]: devicestate.c:298 do_state_change: Changing state for SIP/snom - state 1 (Not in use)
[Nov 15 11:10:42] DEBUG[12878]: chan_sip.c:14935 sip_devicestate: Checking device state for peer snom
[Nov 15 11:10:42] NOTICE[12878]: chan_sip.c:14979 sip_devicestate: sip_devicestate(snom) returning Not in use call-lim=0, inuse=0, onHold=0,  inRinging=0, maxms=2000, lastms=39
[Nov 15 11:10:42] NOTICE[12878]: chan_sip.c:14982 sip_devicestate: sip_devicestate(snom) USER: call_limit=0, inUse=0
[Nov 15 11:10:42] DEBUG[12958]: app_queue.c:552 changethread: Device 'SIP/xlite' changed to state '2' (In use)
[Nov 15 11:10:42] DEBUG[12959]: app_queue.c:552 changethread: Device 'SIP/snom' changed to state '1' (Not in use)
[Nov 15 11:10:42] DEBUG[12880]: chan_sip.c:2047 __sip_ack: Stopping retransmission on '3c26708541eb-a7ehyxtprfpn@192-168-0-11' of Request 102: Match Not Found
Really destroying SIP dialog '3c26708541eb-a7ehyxtprfpn@192-168-0-11' Method: ACK
ilha1*CLI> quit