ilha1*CLI> core set debug 3 Core debug was 0 and is now 3 [Nov 15 11:14:36] DEBUG[13026]: chan_sip.c:14522 sipsock_read: Invalid SIP message - rejected , no callid, len 1080 [Nov 15 11:14:42] DEBUG[13026]: chan_sip.c:2534 do_setnat: Setting NAT on RTP to Off [Nov 15 11:14:42] DEBUG[13026]: chan_sip.c:4224 sip_alloc: Allocating new SIP dialog for NmUzZGRiMzRjMTZlNDI2OTI3MzM4NWI0YjgyMzcxZWQ. - INVITE (With RTP) [Nov 15 11:14:42] DEBUG[13026]: chan_sip.c:2534 do_setnat: Setting NAT on RTP to Off [Nov 15 11:14:42] DEBUG[13026]: chan_sip.c:2047 __sip_ack: Stopping retransmission on 'NmUzZGRiMzRjMTZlNDI2OTI3MzM4NWI0YjgyMzcxZWQ.' of Response 1: Match Not Found [Nov 15 11:14:42] DEBUG[13026]: chan_sip.c:2534 do_setnat: Setting NAT on RTP to Off [Nov 15 11:14:42] DEBUG[13026]: chan_sip.c:5015 process_sdp: T38 state changed to 0 on channel [Nov 15 11:14:42] DEBUG[13026]: chan_sip.c:5092 process_sdp: We're settling with these formats: 0xe (gsm|ulaw|alaw) [Nov 15 11:14:42] DEBUG[13026]: chan_sip.c:13136 handle_request_invite: Checking SIP call limits for device xlite [Nov 15 11:14:42] DEBUG[13026]: chan_sip.c:2950 update_call_counter: Updating call counter for incoming call [Nov 15 11:14:42] DEBUG[13026]: chan_sip.c:3022 update_call_counter: Call from peer 'xlite' is 1 out of 0 [Nov 15 11:14:42] DEBUG[13026]: devicestate.c:314 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/xlite [Nov 15 11:14:42] DEBUG[13026]: chan_sip.c:3731 sip_new: *** Our native formats are 0x8 (alaw) [Nov 15 11:14:42] DEBUG[13026]: chan_sip.c:3732 sip_new: *** Joint capabilities are 0xe (gsm|ulaw|alaw) [Nov 15 11:14:42] DEBUG[13026]: chan_sip.c:3733 sip_new: *** Our capabilities are 0xe (gsm|ulaw|alaw) [Nov 15 11:14:42] DEBUG[13026]: chan_sip.c:3734 sip_new: *** AST_CODEC_CHOOSE formats are 0x8 (alaw) [Nov 15 11:14:42] DEBUG[13026]: chan_sip.c:3757 sip_new: This channel will not be able to handle video. [Nov 15 11:14:42] DEBUG[13026]: chan_sip.c:7828 build_route: build_route: Contact hop: [Nov 15 11:14:42] DEBUG[13026]: chan_sip.c:13209 handle_request_invite: SIP/xlite-09fec380: New call is still down.... Trying... [Nov 15 11:14:42] DEBUG[13026]: devicestate.c:314 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/xlite-09fec380 [Nov 15 11:14:42] DEBUG[13024]: chan_sip.c:14935 sip_devicestate: Checking device state for peer xlite [Nov 15 11:14:42] NOTICE[13024]: chan_sip.c:14975 sip_devicestate: sip_devicestate(xlite) returning In use call-lim=0, inuse=1, onHold=0, inRinging=0, maxms=2000, lastms=102 [Nov 15 11:14:42] DEBUG[13024]: devicestate.c:298 do_state_change: Changing state for SIP/xlite - state 2 (In use) [Nov 15 11:14:42] DEBUG[13024]: chan_sip.c:14935 sip_devicestate: Checking device state for peer xlite [Nov 15 11:14:42] NOTICE[13024]: chan_sip.c:14975 sip_devicestate: sip_devicestate(xlite) returning In use call-lim=0, inuse=1, onHold=0, inRinging=0, maxms=2000, lastms=102 [Nov 15 11:14:42] DEBUG[13024]: chan_sip.c:14935 sip_devicestate: Checking device state for peer xlite [Nov 15 11:14:42] NOTICE[13024]: chan_sip.c:14975 sip_devicestate: sip_devicestate(xlite) returning In use call-lim=0, inuse=1, onHold=0, inRinging=0, maxms=2000, lastms=102 [Nov 15 11:14:42] DEBUG[13024]: devicestate.c:298 do_state_change: Changing state for SIP/xlite - state 2 (In use) [Nov 15 11:14:42] DEBUG[13024]: chan_sip.c:14935 sip_devicestate: Checking device state for peer xlite [Nov 15 11:14:42] NOTICE[13024]: chan_sip.c:14975 sip_devicestate: sip_devicestate(xlite) returning In use call-lim=0, inuse=1, onHold=0, inRinging=0, maxms=2000, lastms=102 [Nov 15 11:14:42] DEBUG[13055]: pbx.c:1767 pbx_extension_helper: Launching 'Dial' -- Executing [6000@default:1] Dial("SIP/xlite-09fec380", "SIP/snom") in new stack [Nov 15 11:14:42] DEBUG[13055]: chan_sip.c:15024 sip_request_call: Asked to create a SIP channel with formats: 0x8 (alaw) [Nov 15 11:14:42] DEBUG[13055]: chan_sip.c:4224 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Nov 15 11:14:42] DEBUG[13055]: chan_sip.c:2534 do_setnat: Setting NAT on RTP to Off [Nov 15 11:14:42] DEBUG[13055]: chan_sip.c:3731 sip_new: *** Our native formats are 0x8 (alaw) [Nov 15 11:14:42] DEBUG[13055]: chan_sip.c:3732 sip_new: *** Joint capabilities are 0x0 (nothing) [Nov 15 11:14:42] DEBUG[13055]: chan_sip.c:3733 sip_new: *** Our capabilities are 0xe (gsm|ulaw|alaw) [Nov 15 11:14:42] DEBUG[13055]: chan_sip.c:3734 sip_new: *** AST_CODEC_CHOOSE formats are 0x8 (alaw) [Nov 15 11:14:42] DEBUG[13055]: chan_sip.c:3736 sip_new: *** Our preferred formats from the incoming channel are 0x8 (alaw) [Nov 15 11:14:42] DEBUG[13055]: chan_sip.c:3757 sip_new: This channel will not be able to handle video. [Nov 15 11:14:42] DEBUG[13055]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-default-6000-1. [Nov 15 11:14:42] DEBUG[13055]: channel.c:3185 ast_channel_inherit_variables: Not copying variable SIPCALLID. [Nov 15 11:14:42] DEBUG[13055]: channel.c:3185 ast_channel_inherit_variables: Not copying variable SIPUSERAGENT. [Nov 15 11:14:42] DEBUG[13055]: channel.c:3185 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [Nov 15 11:14:42] DEBUG[13055]: channel.c:3185 ast_channel_inherit_variables: Not copying variable SIPURI. [Nov 15 11:14:42] DEBUG[13055]: chan_sip.c:2785 sip_call: Outgoing Call for snom [Nov 15 11:14:42] DEBUG[13055]: chan_sip.c:2950 update_call_counter: Updating call counter for outgoing call [Nov 15 11:14:42] DEBUG[13055]: chan_sip.c:3022 update_call_counter: Call to peer 'snom' is 1 out of 0 [Nov 15 11:14:42] DEBUG[13055]: devicestate.c:314 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/snom [Nov 15 11:14:42] DEBUG[13055]: chan_sip.c:2799 sip_call: Our T38 capability (0), joint T38 capability (0) [Nov 15 11:14:42] DEBUG[13055]: chan_sip.c:6065 add_sdp: ** Our capability: 0xe (gsm|ulaw|alaw) Video flag: False [Nov 15 11:14:42] DEBUG[13055]: chan_sip.c:6066 add_sdp: ** Our prefcodec: 0x8 (alaw) [Nov 15 11:14:42] DEBUG[13055]: chan_sip.c:6197 add_sdp: -- Done with adding codecs to SDP [Nov 15 11:14:42] DEBUG[13055]: chan_sip.c:6242 add_sdp: Done building SDP. Settling with this capability: 0xe (gsm|ulaw|alaw) -- Called snom [Nov 15 11:14:42] DEBUG[13024]: chan_sip.c:14935 sip_devicestate: Checking device state for peer snom [Nov 15 11:14:42] NOTICE[13024]: chan_sip.c:14967 sip_devicestate: sip_devicestate(snom) returning Ringing call-lim=0, inuse=1, onHold=0, inRinging=1, maxms=2000, lastms=39 [Nov 15 11:14:42] DEBUG[13024]: devicestate.c:298 do_state_change: Changing state for SIP/snom - state 6 (Ringing) [Nov 15 11:14:42] DEBUG[13024]: chan_sip.c:14935 sip_devicestate: Checking device state for peer snom [Nov 15 11:14:42] NOTICE[13024]: chan_sip.c:14967 sip_devicestate: sip_devicestate(snom) returning Ringing call-lim=0, inuse=1, onHold=0, inRinging=1, maxms=2000, lastms=39 [Nov 15 11:14:42] DEBUG[13056]: app_queue.c:552 changethread: Device 'SIP/xlite' changed to state '2' (In use) [Nov 15 11:14:42] DEBUG[13057]: app_queue.c:552 changethread: Device 'SIP/xlite' changed to state '2' (In use) [Nov 15 11:14:42] DEBUG[13058]: app_queue.c:552 changethread: Device 'SIP/snom' changed to state '6' (Ringing) [Nov 15 11:14:42] DEBUG[13026]: chan_sip.c:2089 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '5f4d33be3867d6b0090ded344bd34a47@192.168.0.252' Request 102: Found [Nov 15 11:14:42] DEBUG[13026]: devicestate.c:314 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/snom-09ff13f0 -- SIP/snom-09ff13f0 is ringing [Nov 15 11:14:42] DEBUG[13024]: chan_sip.c:14935 sip_devicestate: Checking device state for peer snom [Nov 15 11:14:42] NOTICE[13024]: chan_sip.c:14967 sip_devicestate: sip_devicestate(snom) returning Ringing call-lim=0, inuse=1, onHold=0, inRinging=1, maxms=2000, lastms=39 [Nov 15 11:14:42] DEBUG[13024]: devicestate.c:298 do_state_change: Changing state for SIP/snom - state 6 (Ringing) [Nov 15 11:14:42] DEBUG[13024]: chan_sip.c:14935 sip_devicestate: Checking device state for peer snom [Nov 15 11:14:42] NOTICE[13024]: chan_sip.c:14967 sip_devicestate: sip_devicestate(snom) returning Ringing call-lim=0, inuse=1, onHold=0, inRinging=1, maxms=2000, lastms=39 [Nov 15 11:14:42] DEBUG[13059]: app_queue.c:552 changethread: Device 'SIP/snom' changed to state '6' (Ringing) [Nov 15 11:14:43] DEBUG[13026]: chan_sip.c:2089 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '5f4d33be3867d6b0090ded344bd34a47@192.168.0.252' Request 102: Found -- SIP/snom-09ff13f0 is ringing [Nov 15 11:14:44] DEBUG[13026]: chan_sip.c:2089 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '5f4d33be3867d6b0090ded344bd34a47@192.168.0.252' Request 102: Found -- SIP/snom-09ff13f0 is ringing [Nov 15 11:14:46] DEBUG[13026]: chan_sip.c:2089 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '5f4d33be3867d6b0090ded344bd34a47@192.168.0.252' Request 102: Found -- SIP/snom-09ff13f0 is 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 (Ringing) 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:14:50] DEBUG[13026]: chan_sip.c:2089 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '5f4d33be3867d6b0090ded344bd34a47@192.168.0.252' Request 102: Found -- SIP/snom-09ff13f0 is ringing [Nov 15 11:14:53] DEBUG[13026]: chan_sip.c:2030 __sip_ack: Acked pending invite 102 [Nov 15 11:14:53] DEBUG[13026]: chan_sip.c:2047 __sip_ack: Stopping retransmission on '5f4d33be3867d6b0090ded344bd34a47@192.168.0.252' of Request 102: Match Not Found [Nov 15 11:14:53] DEBUG[13026]: chan_sip.c:5015 process_sdp: T38 state changed to 0 on channel SIP/snom-09ff13f0 [Nov 15 11:14:53] DEBUG[13026]: chan_sip.c:5092 process_sdp: We're settling with these formats: 0x8 (alaw) [Nov 15 11:14:53] DEBUG[13026]: chan_sip.c:2950 update_call_counter: Updating call counter for outgoing call [Nov 15 11:14:53] DEBUG[13026]: devicestate.c:314 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/snom [Nov 15 11:14:53] DEBUG[13026]: chan_sip.c:7828 build_route: build_route: Contact hop: [Nov 15 11:14:53] DEBUG[13055]: devicestate.c:314 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/snom-09ff13f0 -- SIP/snom-09ff13f0 answered SIP/xlite-09fec380 [Nov 15 11:14:53] DEBUG[13055]: devicestate.c:314 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/xlite-09fec380 [Nov 15 11:14:53] DEBUG[13055]: chan_sip.c:3400 sip_answer: SIP answering channel: SIP/xlite-09fec380 [Nov 15 11:14:53] DEBUG[13055]: chan_sip.c:6297 transmit_response_with_sdp: Setting framing from config on incoming call [Nov 15 11:14:53] DEBUG[13055]: chan_sip.c:6065 add_sdp: ** Our capability: 0xe (gsm|ulaw|alaw) Video flag: True [Nov 15 11:14:53] DEBUG[13055]: chan_sip.c:6066 add_sdp: ** Our prefcodec: 0x0 (nothing) [Nov 15 11:14:53] DEBUG[13055]: chan_sip.c:6197 add_sdp: -- Done with adding codecs to SDP [Nov 15 11:14:53] DEBUG[13055]: chan_sip.c:6242 add_sdp: Done building SDP. Settling with this capability: 0xe (gsm|ulaw|alaw) -- Packet2Packet bridging SIP/xlite-09fec380 and SIP/snom-09ff13f0 [Nov 15 11:14:53] DEBUG[13024]: chan_sip.c:14935 sip_devicestate: Checking device state for peer snom [Nov 15 11:14:53] NOTICE[13024]: chan_sip.c:14975 sip_devicestate: sip_devicestate(snom) returning In use call-lim=0, inuse=1, onHold=0, inRinging=0, maxms=2000, lastms=39 [Nov 15 11:14:53] DEBUG[13024]: devicestate.c:298 do_state_change: Changing state for SIP/snom - state 2 (In use) [Nov 15 11:14:53] DEBUG[13024]: chan_sip.c:14935 sip_devicestate: Checking device state for peer snom [Nov 15 11:14:53] NOTICE[13024]: chan_sip.c:14975 sip_devicestate: sip_devicestate(snom) returning In use call-lim=0, inuse=1, onHold=0, inRinging=0, maxms=2000, lastms=39 [Nov 15 11:14:53] DEBUG[13024]: chan_sip.c:14935 sip_devicestate: Checking device state for peer snom [Nov 15 11:14:53] NOTICE[13024]: chan_sip.c:14975 sip_devicestate: sip_devicestate(snom) returning In use call-lim=0, inuse=1, onHold=0, inRinging=0, maxms=2000, lastms=39 [Nov 15 11:14:53] DEBUG[13024]: devicestate.c:298 do_state_change: Changing state for SIP/snom - state 2 (In use) [Nov 15 11:14:53] DEBUG[13024]: chan_sip.c:14935 sip_devicestate: Checking device state for peer snom [Nov 15 11:14:53] NOTICE[13024]: chan_sip.c:14975 sip_devicestate: sip_devicestate(snom) returning In use call-lim=0, inuse=1, onHold=0, inRinging=0, maxms=2000, lastms=39 [Nov 15 11:14:53] DEBUG[13024]: chan_sip.c:14935 sip_devicestate: Checking device state for peer xlite [Nov 15 11:14:53] NOTICE[13024]: chan_sip.c:14975 sip_devicestate: sip_devicestate(xlite) returning In use call-lim=0, inuse=1, onHold=0, inRinging=0, maxms=2000, lastms=102 [Nov 15 11:14:53] DEBUG[13024]: devicestate.c:298 do_state_change: Changing state for SIP/xlite - state 2 (In use) [Nov 15 11:14:53] DEBUG[13024]: chan_sip.c:14935 sip_devicestate: Checking device state for peer xlite [Nov 15 11:14:53] NOTICE[13024]: chan_sip.c:14975 sip_devicestate: sip_devicestate(xlite) returning In use call-lim=0, inuse=1, onHold=0, inRinging=0, maxms=2000, lastms=102 [Nov 15 11:14:53] DEBUG[13060]: app_queue.c:552 changethread: Device 'SIP/snom' changed to state '2' (In use) [Nov 15 11:14:53] DEBUG[13061]: app_queue.c:552 changethread: Device 'SIP/snom' changed to state '2' (In use) [Nov 15 11:14:53] DEBUG[13062]: app_queue.c:552 changethread: Device 'SIP/xlite' changed to state '2' (In use) [Nov 15 11:14:53] DEBUG[13026]: chan_sip.c:2047 __sip_ack: Stopping retransmission on 'NmUzZGRiMzRjMTZlNDI2OTI3MzM4NWI0YjgyMzcxZWQ.' 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 (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:15:03] DEBUG[13026]: chan_sip.c:5015 process_sdp: T38 state changed to 0 on channel SIP/xlite-09fec380 [Nov 15 11:15:03] DEBUG[13026]: chan_sip.c:5092 process_sdp: We're settling with these formats: 0xe (gsm|ulaw|alaw) [Nov 15 11:15:03] NOTICE[13026]: chan_sip.c:8037 sip_peer_hold: onHold now: 1; hold arg was: 1 [Nov 15 11:15:03] DEBUG[13026]: devicestate.c:314 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/xlite [Nov 15 11:15:03] DEBUG[13026]: chan_sip.c:13276 handle_request_invite: SIP/xlite-09fec380: This call is UP.... [Nov 15 11:15:03] DEBUG[13026]: chan_sip.c:6297 transmit_response_with_sdp: Setting framing from config on incoming call [Nov 15 11:15:03] DEBUG[13026]: chan_sip.c:6065 add_sdp: ** Our capability: 0xe (gsm|ulaw|alaw) Video flag: True [Nov 15 11:15:03] DEBUG[13026]: chan_sip.c:6066 add_sdp: ** Our prefcodec: 0x0 (nothing) [Nov 15 11:15:03] DEBUG[13026]: chan_sip.c:6197 add_sdp: -- Done with adding codecs to SDP [Nov 15 11:15:03] DEBUG[13026]: 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-09ff13f0 [Nov 15 11:15:03] DEBUG[13024]: chan_sip.c:14935 sip_devicestate: Checking device state for peer xlite [Nov 15 11:15:03] NOTICE[13024]: chan_sip.c:14963 sip_devicestate: sip_devicestate(xlite) returning On Hold call-lim=0, inuse=1, onHold=1, inRinging=0, maxms=2000, lastms=102 [Nov 15 11:15:03] DEBUG[13024]: devicestate.c:298 do_state_change: Changing state for SIP/xlite - state 8 (On Hold) [Nov 15 11:15:03] DEBUG[13024]: chan_sip.c:14935 sip_devicestate: Checking device state for peer xlite [Nov 15 11:15:03] NOTICE[13024]: chan_sip.c:14963 sip_devicestate: sip_devicestate(xlite) returning On Hold call-lim=0, inuse=1, onHold=1, inRinging=0, maxms=2000, lastms=102 [Nov 15 11:15:03] DEBUG[13064]: app_queue.c:552 changethread: Device 'SIP/xlite' changed to state '8' (On Hold) [Nov 15 11:15:03] DEBUG[13055]: channel.c:2731 set_format: Set channel SIP/snom-09ff13f0 to write format slin [Nov 15 11:15:03] DEBUG[13055]: res_musiconhold.c:252 ast_moh_files_next: SIP/snom-09ff13f0 Opened file 0 '/var/lib/asterisk/moh/fpm-sunshine' [Nov 15 11:15:03] DEBUG[13055]: rtp.c:2563 ast_rtp_write: Ooh, format changed from unknown to alaw [Nov 15 11:15:03] DEBUG[13055]: rtp.c:2580 ast_rtp_write: Created smoother: format: 8 ms: 20 len: 160 [Nov 15 11:15:03] DEBUG[13026]: chan_sip.c:2047 __sip_ack: Stopping retransmission on 'NmUzZGRiMzRjMTZlNDI2OTI3MzM4NWI0YjgyMzcxZWQ.' 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 (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:15:05] DEBUG[13055]: rtp.c:808 ast_rtcp_read: Got RTCP report of 44 bytes [Nov 15 11:15:05] DEBUG[13055]: rtp.c:903 ast_rtcp_read: Unknown RTCP packet (pt=207) received from 0.0.0.0:0 [Nov 15 11:15:05] DEBUG[13055]: rtp.c:808 ast_rtcp_read: Got RTCP report of 176 bytes [Nov 15 11:15:08] DEBUG[13055]: rtp.c:808 ast_rtcp_read: Got RTCP report of 156 bytes [Nov 15 11:15:11] DEBUG[13055]: rtp.c:808 ast_rtcp_read: Got RTCP report of 44 bytes [Nov 15 11:15:11] DEBUG[13055]: rtp.c:903 ast_rtcp_read: Unknown RTCP packet (pt=207) received from 0.0.0.0:0 [Nov 15 11:15:11] DEBUG[13055]: rtp.c:808 ast_rtcp_read: Got RTCP report of 156 bytes [Nov 15 11:15:13] NOTICE[13055]: rtp.c:1214 ast_rtp_read: Unknown RTP codec 126 received from '0.0.0.0' [Nov 15 11:15:14] DEBUG[13055]: rtp.c:808 ast_rtcp_read: Got RTCP report of 176 bytes [Nov 15 11:15:17] DEBUG[13026]: chan_sip.c:5015 process_sdp: T38 state changed to 0 on channel SIP/xlite-09fec380 [Nov 15 11:15:17] DEBUG[13026]: chan_sip.c:5092 process_sdp: We're settling with these formats: 0xe (gsm|ulaw|alaw) [Nov 15 11:15:17] NOTICE[13026]: chan_sip.c:8037 sip_peer_hold: onHold now: 0; hold arg was: 0 [Nov 15 11:15:17] DEBUG[13026]: devicestate.c:314 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/xlite [Nov 15 11:15:17] DEBUG[13026]: chan_sip.c:13276 handle_request_invite: SIP/xlite-09fec380: This call is UP.... [Nov 15 11:15:17] DEBUG[13026]: chan_sip.c:6297 transmit_response_with_sdp: Setting framing from config on incoming call [Nov 15 11:15:17] DEBUG[13026]: chan_sip.c:6065 add_sdp: ** Our capability: 0xe (gsm|ulaw|alaw) Video flag: True [Nov 15 11:15:17] DEBUG[13026]: chan_sip.c:6066 add_sdp: ** Our prefcodec: 0x0 (nothing) [Nov 15 11:15:17] DEBUG[13026]: chan_sip.c:6197 add_sdp: -- Done with adding codecs to SDP [Nov 15 11:15:17] DEBUG[13026]: chan_sip.c:6242 add_sdp: Done building SDP. Settling with this capability: 0xe (gsm|ulaw|alaw) -- Stopped music on hold on SIP/snom-09ff13f0 [Nov 15 11:15:17] DEBUG[13055]: channel.c:2731 set_format: Set channel SIP/snom-09ff13f0 to write format alaw [Nov 15 11:15:17] DEBUG[13024]: chan_sip.c:14935 sip_devicestate: Checking device state for peer xlite [Nov 15 11:15:17] NOTICE[13024]: chan_sip.c:14975 sip_devicestate: sip_devicestate(xlite) returning In use call-lim=0, inuse=1, onHold=0, inRinging=0, maxms=2000, lastms=102 [Nov 15 11:15:17] DEBUG[13024]: devicestate.c:298 do_state_change: Changing state for SIP/xlite - state 2 (In use) [Nov 15 11:15:17] DEBUG[13024]: chan_sip.c:14935 sip_devicestate: Checking device state for peer xlite [Nov 15 11:15:17] NOTICE[13024]: chan_sip.c:14975 sip_devicestate: sip_devicestate(xlite) returning In use call-lim=0, inuse=1, onHold=0, inRinging=0, maxms=2000, lastms=102 [Nov 15 11:15:17] DEBUG[13066]: app_queue.c:552 changethread: Device 'SIP/xlite' changed to state '2' (In use) [Nov 15 11:15:17] DEBUG[13026]: chan_sip.c:2047 __sip_ack: Stopping retransmission on 'NmUzZGRiMzRjMTZlNDI2OTI3MzM4NWI0YjgyMzcxZWQ.' of Response 4: 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 (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:15:19] DEBUG[13026]: chan_sip.c:4224 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Nov 15 11:15:19] DEBUG[13026]: chan_sip.c:2047 __sip_ack: Stopping retransmission on '3fb7609631f4171c6623961221f3811d@192.168.0.252' of Request 102: Match Not Found Really destroying SIP dialog '3fb7609631f4171c6623961221f3811d@192.168.0.252' Method: OPTIONS [Nov 15 11:15:20] DEBUG[13026]: chan_sip.c:4224 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Nov 15 11:15:20] DEBUG[13026]: chan_sip.c:2047 __sip_ack: Stopping retransmission on '0300c76f20d052b02846cbd234a02f94@192.168.0.252' of Request 102: Match Not Found Really destroying SIP dialog '0300c76f20d052b02846cbd234a02f94@192.168.0.252' Method: OPTIONS [Nov 15 11:15:20] DEBUG[13026]: chan_sip.c:4224 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Nov 15 11:15:20] DEBUG[13026]: chan_sip.c:2047 __sip_ack: Stopping retransmission on '06eaca001588aaf703e1c21d49580f5b@192.168.0.252' of Request 102: Match Not Found Really destroying SIP dialog '06eaca001588aaf703e1c21d49580f5b@192.168.0.252' Method: OPTIONS [Nov 15 11:15:21] DEBUG[13026]: chan_sip.c:13918 handle_request_bye: Received bye, issuing owner hangup .[Nov 15 11:15:21] DEBUG[13055]: rtp.c:2951 bridge_p2p_loop: Oooh, got a hangup [Nov 15 11:15:21] DEBUG[13055]: channel.c:3918 ast_channel_bridge: Returning from native bridge, channels: SIP/xlite-09fec380, SIP/snom-09ff13f0 [Nov 15 11:15:21] DEBUG[13055]: channel.c:1606 ast_hangup: Hanging up channel 'SIP/snom-09ff13f0' [Nov 15 11:15:21] DEBUG[13055]: chan_sip.c:3252 sip_hangup: Hangup call SIP/snom-09ff13f0, SIP callid 5f4d33be3867d6b0090ded344bd34a47@192.168.0.252) [Nov 15 11:15:21] DEBUG[13055]: chan_sip.c:2950 update_call_counter: Updating call counter for outgoing call [Nov 15 11:15:21] DEBUG[13055]: chan_sip.c:2996 update_call_counter: Call to peer 'snom' removed from call limit 0 [Nov 15 11:15:21] DEBUG[13055]: devicestate.c:314 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/snom [Nov 15 11:15:21] DEBUG[13055]: devicestate.c:314 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/snom-09ff13f0 [Nov 15 11:15:21] DEBUG[13055]: rtp.c:1419 ast_rtp_early_bridge: Channel '' has no RTP, not doing anything [Nov 15 11:15:21] DEBUG[13055]: app_dial.c:1639 dial_exec_full: Exiting with DIALSTATUS=ANSWER. [Nov 15 11:15:21] DEBUG[13055]: pbx.c:2363 __ast_pbx_run: Spawn extension (default,6000,1) exited non-zero on 'SIP/xlite-09fec380' == Spawn extension (default, 6000, 1) exited non-zero on 'SIP/xlite-09fec380' [Nov 15 11:15:21] DEBUG[13055]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '"Telefone 4000" <4000>' [Nov 15 11:15:21] DEBUG[13055]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '4000' [Nov 15 11:15:21] DEBUG[13055]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '6000' [Nov 15 11:15:21] DEBUG[13055]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'default' [Nov 15 11:15:21] DEBUG[13055]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'SIP/xlite-09fec380' [Nov 15 11:15:21] DEBUG[13055]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'SIP/snom-09ff13f0' [Nov 15 11:15:21] DEBUG[13055]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'Dial' [Nov 15 11:15:21] DEBUG[13055]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'SIP/snom' [Nov 15 11:15:21] DEBUG[13055]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '2006-11-15 11:14:42' [Nov 15 11:15:21] DEBUG[13055]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '2006-11-15 11:14:53' [Nov 15 11:15:21] DEBUG[13055]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '2006-11-15 11:15:21' [Nov 15 11:15:21] DEBUG[13055]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '39' [Nov 15 11:15:21] DEBUG[13055]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '28' [Nov 15 11:15:21] DEBUG[13055]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'ANSWERED' [Nov 15 11:15:21] DEBUG[13055]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' [Nov 15 11:15:21] DEBUG[13055]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '' [Nov 15 11:15:21] DEBUG[13055]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '1163600082.0' [Nov 15 11:15:21] DEBUG[13055]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '' [Nov 15 11:15:21] DEBUG[13055]: channel.c:1606 ast_hangup: Hanging up channel 'SIP/xlite-09fec380' [Nov 15 11:15:21] DEBUG[13055]: chan_sip.c:3252 sip_hangup: Hangup call SIP/xlite-09fec380, SIP callid NmUzZGRiMzRjMTZlNDI2OTI3MzM4NWI0YjgyMzcxZWQ.) [Nov 15 11:15:21] DEBUG[13055]: chan_sip.c:2950 update_call_counter: Updating call counter for incoming call [Nov 15 11:15:21] DEBUG[13055]: chan_sip.c:2996 update_call_counter: Call from peer 'xlite' removed from call limit 0 [Nov 15 11:15:21] DEBUG[13055]: devicestate.c:314 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/xlite [Nov 15 11:15:21] DEBUG[13055]: devicestate.c:314 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/xlite-09fec380 [Nov 15 11:15:21] DEBUG[13024]: chan_sip.c:14935 sip_devicestate: Checking device state for peer snom [Nov 15 11:15:21] NOTICE[13024]: 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:15:21] NOTICE[13024]: chan_sip.c:14982 sip_devicestate: sip_devicestate(snom) USER: call_limit=0, inUse=0 [Nov 15 11:15:21] DEBUG[13024]: devicestate.c:298 do_state_change: Changing state for SIP/snom - state 1 (Not in use) [Nov 15 11:15:21] DEBUG[13024]: chan_sip.c:14935 sip_devicestate: Checking device state for peer snom [Nov 15 11:15:21] NOTICE[13024]: 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:15:21] NOTICE[13024]: chan_sip.c:14982 sip_devicestate: sip_devicestate(snom) USER: call_limit=0, inUse=0 [Nov 15 11:15:21] DEBUG[13024]: chan_sip.c:14935 sip_devicestate: Checking device state for peer snom [Nov 15 11:15:21] NOTICE[13024]: 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:15:21] NOTICE[13024]: chan_sip.c:14982 sip_devicestate: sip_devicestate(snom) USER: call_limit=0, inUse=0 [Nov 15 11:15:21] DEBUG[13024]: devicestate.c:298 do_state_change: Changing state for SIP/snom - state 1 (Not in use) [Nov 15 11:15:21] DEBUG[13024]: chan_sip.c:14935 sip_devicestate: Checking device state for peer snom [Nov 15 11:15:21] NOTICE[13024]: 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:15:21] NOTICE[13024]: chan_sip.c:14982 sip_devicestate: sip_devicestate(snom) USER: call_limit=0, inUse=0 [Nov 15 11:15:21] DEBUG[13024]: chan_sip.c:14935 sip_devicestate: Checking device state for peer xlite [Nov 15 11:15:21] NOTICE[13024]: 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=102 [Nov 15 11:15:21] NOTICE[13024]: chan_sip.c:14982 sip_devicestate: sip_devicestate(xlite) USER: call_limit=0, inUse=0 [Nov 15 11:15:21] DEBUG[13024]: devicestate.c:298 do_state_change: Changing state for SIP/xlite - state 1 (Not in use) [Nov 15 11:15:21] DEBUG[13024]: chan_sip.c:14935 sip_devicestate: Checking device state for peer xlite [Nov 15 11:15:21] NOTICE[13024]: 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=102 [Nov 15 11:15:21] NOTICE[13024]: chan_sip.c:14982 sip_devicestate: sip_devicestate(xlite) USER: call_limit=0, inUse=0 [Nov 15 11:15:21] DEBUG[13024]: chan_sip.c:14935 sip_devicestate: Checking device state for peer xlite [Nov 15 11:15:21] NOTICE[13024]: 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=102 [Nov 15 11:15:21] NOTICE[13024]: chan_sip.c:14982 sip_devicestate: sip_devicestate(xlite) USER: call_limit=0, inUse=0 [Nov 15 11:15:21] DEBUG[13024]: devicestate.c:298 do_state_change: Changing state for SIP/xlite - state 1 (Not in use) Really destroying SIP dialog '5f4d33be3867d6b0090ded344bd34a47@192.168.0.252' Method: BYE [Nov 15 11:15:21] DEBUG[13024]: chan_sip.c:14935 sip_devicestate: Checking device state for peer xlite [Nov 15 11:15:21] NOTICE[13024]: 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=102 [Nov 15 11:15:21] NOTICE[13024]: chan_sip.c:14982 sip_devicestate: sip_devicestate(xlite) USER: call_limit=0, inUse=0 [Nov 15 11:15:21] DEBUG[13067]: app_queue.c:552 changethread: Device 'SIP/snom' changed to state '1' (Not in use) [Nov 15 11:15:21] DEBUG[13068]: app_queue.c:552 changethread: Device 'SIP/snom' changed to state '1' (Not in use) [Nov 15 11:15:21] DEBUG[13069]: app_queue.c:552 changethread: Device 'SIP/xlite' changed to state '1' (Not in use) [Nov 15 11:15:21] DEBUG[13070]: app_queue.c:552 changethread: Device 'SIP/xlite' changed to state '1' (Not in use) [Nov 15 11:15:21] DEBUG[13026]: chan_sip.c:2047 __sip_ack: Stopping retransmission on 'NmUzZGRiMzRjMTZlNDI2OTI3MzM4NWI0YjgyMzcxZWQ.' of Request 102: Match Not Found Really destroying SIP dialog 'NmUzZGRiMzRjMTZlNDI2OTI3MzM4NWI0YjgyMzcxZWQ.' Method: ACK [Nov 15 11:15:21] DEBUG[13026]: chan_sip.c:14522 sipsock_read: Invalid SIP message - rejected , no callid, len 1044 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 ilha1*CLI> quit