[Sep 14 09:34:28] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 0: (0) [Sep 14 09:34:28] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: (0) --- (0 headers 1 lines)--- [Sep 14 09:34:30] DEBUG[15724]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Zap/1-1 -- Accepting call from '07803034440' to '444606' on channel 0/1, span 1 [Sep 14 09:34:30] DEBUG[15718]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for Zap - 1 [Sep 14 09:34:30] DEBUG[15718]: devicestate.c:287 do_state_change: Changing state for Zap/1 - state 2 (In use) [Sep 14 09:34:30] DEBUG[15724]: chan_zap.c:1455 zt_enable_ec: Enabled echo cancellation on channel 1 [Sep 14 09:34:30] DEBUG[23084]: pbx.c:1684 pbx_extension_helper: Launching 'Answer' -- Executing [444606@isdn10:1] Answer("Zap/1-1", "") in new stack [Sep 14 09:34:30] DEBUG[23084]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Zap/1-1 [Sep 14 09:34:30] DEBUG[15718]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for Zap - 1 [Sep 14 09:34:30] DEBUG[15718]: channel.c:880 channel_find_locked: Avoiding initial deadlock for channel '0x94b6dc8' [Sep 14 09:34:30] DEBUG[23084]: pbx.c:1684 pbx_extension_helper: Launching 'MixMonitor' -- Executing [444606@isdn10:2] MixMonitor("Zap/1-1", "jls.gsm") in new stack [Sep 14 09:34:30] DEBUG[23084]: channel.c:1200 ast_channel_spy_add: Spy MixMonitor added to channel Zap/1-1 [Sep 14 09:34:30] DEBUG[23084]: pbx.c:1684 pbx_extension_helper: Launching 'Dial' -- Executing [444606@isdn10:3] Dial("Zap/1-1", "SIP/5706") in new stack [Sep 14 09:34:30] DEBUG[23084]: chan_sip.c:14710 sip_request_call: Asked to create a SIP channel with formats: 0x8 (alaw) [Sep 14 09:34:30] DEBUG[15718]: devicestate.c:287 do_state_change: Changing state for Zap/1 - state 2 (In use) [Sep 14 09:34:30] DEBUG[23085]: app_queue.c:535 changethread: Device 'Zap/1' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Sep 14 09:34:30] DEBUG[23087]: app_queue.c:535 changethread: Device 'Zap/1' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Sep 14 09:34:30] DEBUG[23084]: chan_sip.c:4152 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Sep 14 09:34:30] DEBUG[23084]: chan_sip.c:2518 create_addr_from_peer: Setting NAT on RTP to Off [Sep 14 09:34:30] DEBUG[23084]: chan_sip.c:3647 sip_new: *** Our native formats are 0x4 (ulaw) [Sep 14 09:34:30] DEBUG[23084]: chan_sip.c:3648 sip_new: *** Joint capabilities are 0x0 (nothing) [Sep 14 09:34:30] DEBUG[23084]: chan_sip.c:3649 sip_new: *** Our capabilities are 0x404 (ulaw|ilbc) [Sep 14 09:34:30] DEBUG[23084]: chan_sip.c:3650 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Sep 14 09:34:30] DEBUG[23084]: chan_sip.c:3652 sip_new: *** Our preferred formats from the incoming channel are 0x8 (alaw) [Sep 14 09:34:30] DEBUG[23084]: chan_sip.c:3673 sip_new: This channel will not be able to handle video. [Sep 14 09:34:30] DEBUG[23084]: rtp.c:1477 ast_rtp_make_compatible: Channel 'Zap/1-1' has no RTP, not doing anything [Sep 14 09:34:30] DEBUG[23084]: channel.c:3103 ast_channel_inherit_variables: Not copying variable STACK-isdn10-444606-3. [Sep 14 09:34:30] DEBUG[23084]: channel.c:3103 ast_channel_inherit_variables: Not copying variable MIXMONITOR_FILENAME. [Sep 14 09:34:30] DEBUG[23084]: channel.c:3103 ast_channel_inherit_variables: Not copying variable STACK-isdn10-444606-2. [Sep 14 09:34:30] DEBUG[23084]: channel.c:3103 ast_channel_inherit_variables: Not copying variable STACK-isdn10-444606-1. [Sep 14 09:34:30] DEBUG[23084]: channel.c:3103 ast_channel_inherit_variables: Not copying variable CALLEDTON. [Sep 14 09:34:30] DEBUG[23084]: channel.c:3103 ast_channel_inherit_variables: Not copying variable ANI2. [Sep 14 09:34:30] DEBUG[23084]: channel.c:3103 ast_channel_inherit_variables: Not copying variable TRANSFERCAPABILITY. [Sep 14 09:34:30] DEBUG[23084]: chan_sip.c:2718 sip_call: Outgoing Call for 5706 [Sep 14 09:34:30] DEBUG[23084]: chan_sip.c:2879 update_call_counter: Updating call counter for outgoing call [Sep 14 09:34:30] DEBUG[23084]: chan_sip.c:2726 sip_call: Our T38 capability (0), joint T38 capability (0) [Sep 14 09:34:30] DEBUG[23084]: chan_sip.c:5847 add_sdp: ** Our capability: 0x404 (ulaw|ilbc) Video flag: False [Sep 14 09:34:30] DEBUG[23084]: chan_sip.c:5848 add_sdp: ** Our prefcodec: 0x8 (alaw) Audio is at 90.0.0.62 port 15836 Adding codec 0x4 (ulaw) to SDP Adding codec 0x400 (ilbc) to SDP Adding non-codec 0x1 (telephone-event) to SDP [Sep 14 09:34:30] DEBUG[23084]: chan_sip.c:6000 add_sdp: -- Done with adding codecs to SDP [Sep 14 09:34:30] DEBUG[23084]: chan_sip.c:6039 add_sdp: Done building SDP. Settling with this capability: 0x404 (ulaw|ilbc) [Sep 14 09:34:30] DEBUG[23084]: chan_sip.c:4372 parse_request: Header 0: INVITE sip:5706@192.168.0.200:5060 SIP/2.0 (42) [Sep 14 09:34:30] DEBUG[23084]: chan_sip.c:4372 parse_request: Header 1: Via: SIP/2.0/UDP 90.0.0.62:5060;branch=z9hG4bK38666bad;rport (60) [Sep 14 09:34:30] DEBUG[23084]: chan_sip.c:4372 parse_request: Header 2: From: "07803034440" ;tag=as7d0cfcef (62) [Sep 14 09:34:30] DEBUG[23084]: chan_sip.c:4372 parse_request: Header 3: To: (33) [Sep 14 09:34:30] DEBUG[23084]: chan_sip.c:4372 parse_request: Header 4: Contact: (36) [Sep 14 09:34:30] DEBUG[23084]: chan_sip.c:4372 parse_request: Header 5: Call-ID: 660ba5b156e7b87838cb44e973401a18@90.0.0.62 (51) [Sep 14 09:34:30] DEBUG[23084]: chan_sip.c:4372 parse_request: Header 6: CSeq: 102 INVITE (16) [Sep 14 09:34:30] DEBUG[23084]: chan_sip.c:4372 parse_request: Header 7: User-Agent: Asterisk PBX (24) [Sep 14 09:34:30] DEBUG[23084]: chan_sip.c:4372 parse_request: Header 8: Max-Forwards: 70 (16) [Sep 14 09:34:30] DEBUG[23084]: chan_sip.c:4372 parse_request: Header 9: Date: Thu, 14 Sep 2006 08:34:30 GMT (35) [Sep 14 09:34:30] DEBUG[23084]: chan_sip.c:4372 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Sep 14 09:34:30] DEBUG[23084]: chan_sip.c:4372 parse_request: Header 11: Supported: replaces (19) [Sep 14 09:34:30] DEBUG[23084]: chan_sip.c:4372 parse_request: Header 12: Content-Type: application/sdp (29) [Sep 14 09:34:30] DEBUG[23084]: chan_sip.c:4372 parse_request: Header 13: Content-Length: 267 (19) [Sep 14 09:34:30] DEBUG[23084]: chan_sip.c:4372 parse_request: Header 14: (0) [Sep 14 09:34:30] DEBUG[23084]: chan_sip.c:4404 parse_request: Line: v=0 (3) [Sep 14 09:34:30] DEBUG[23084]: chan_sip.c:4404 parse_request: Line: o=root 15662 15662 IN IP4 90.0.0.62 (35) [Sep 14 09:34:30] DEBUG[23084]: chan_sip.c:4404 parse_request: Line: s=session (9) [Sep 14 09:34:30] DEBUG[23084]: chan_sip.c:4404 parse_request: Line: c=IN IP4 90.0.0.62 (18) [Sep 14 09:34:30] DEBUG[23084]: chan_sip.c:4404 parse_request: Line: t=0 0 (5) [Sep 14 09:34:30] DEBUG[23084]: chan_sip.c:4404 parse_request: Line: m=audio 15836 RTP/AVP 0 97 101 (30) [Sep 14 09:34:30] DEBUG[23084]: chan_sip.c:4404 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Sep 14 09:34:30] DEBUG[23084]: chan_sip.c:4404 parse_request: Line: a=rtpmap:97 iLBC/8000 (21) [Sep 14 09:34:30] DEBUG[23084]: chan_sip.c:4404 parse_request: Line: a=fmtp:97 mode=20 (17) [Sep 14 09:34:30] DEBUG[23084]: chan_sip.c:4404 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Sep 14 09:34:30] DEBUG[23084]: chan_sip.c:4404 parse_request: Line: a=fmtp:101 0-16 (15) [Sep 14 09:34:30] DEBUG[23084]: chan_sip.c:4404 parse_request: Line: a=silenceSupp:off - - - - (25) [Sep 14 09:34:30] DEBUG[23084]: chan_sip.c:4404 parse_request: Line: a=sendrecv (10) Reliably Transmitting (no NAT) to 192.168.0.200:5060: INVITE sip:5706@192.168.0.200:5060 SIP/2.0 Via: SIP/2.0/UDP 90.0.0.62:5060;branch=z9hG4bK38666bad;rport From: "07803034440" ;tag=as7d0cfcef To: Contact: Call-ID: 660ba5b156e7b87838cb44e973401a18@90.0.0.62 CSeq: 102 INVITE User-Agent: Asterisk PBX Max-Forwards: 70 Date: Thu, 14 Sep 2006 08:34:30 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Type: application/sdp Content-Length: 267 v=0 o=root 15662 15662 IN IP4 90.0.0.62 s=session c=IN IP4 90.0.0.62 t=0 0 =audio 15836 RTP/AVP 0 97 101 a=rtpmap:0 PCMU/8000 a=rtpmap:97 iLBC/8000 a=fmtp:97 mode=20 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=sendrecv --- [Sep 14 09:34:30] DEBUG[23084]: chan_sip.c:1909 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #1960 -- Called 5706 [Sep 14 09:34:30] DEBUG[23084]: channel.c:2638 set_format: Set channel SIP/5706-0951ae00 to read format alaw [Sep 14 09:34:30] DEBUG[23084]: channel.c:2638 set_format: Set channel Zap/1-1 to read format ulaw [Sep 14 09:34:30] DEBUG[23084]: channel.c:1381 queue_frame_to_spies: Building translator from alaw to SLINEAR for spies on channel Zap/1-1 == Begin MixMonitor Recording Zap/1-1 [Sep 14 09:34:30] DEBUG[23084]: channel.c:1436 queue_frame_to_spies: Triggering queue flush for spy 'MixMonitor' on 'Zap/1-1' foxtrot*CLI> <-- SIP read from 192.168.0.200:50628: SIP/2.0 100 Trying Via: SIP/2.0/UDP 90.0.0.62:5060;branch=z9hG4bK38666bad;rport From: "07803034440" ;tag=as7d0cfcef To: Call-ID: 660ba5b156e7b87838cb44e973401a18@90.0.0.62 Date: Thu, 14 Sep 2006 08:34:29 GMT CSeq: 102 INVITE Server: CSCO/7 Contact: Content-Length: 0 [Sep 14 09:34:31] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 0: SIP/2.0 100 Trying (18) [Sep 14 09:34:31] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 1: Via: SIP/2.0/UDP 90.0.0.62:5060;branch=z9hG4bK38666bad;rport (60) [Sep 14 09:34:31] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 2: From: "07803034440" ;tag=as7d0cfcef (62) [Sep 14 09:34:31] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 3: To: (33) [Sep 14 09:34:31] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 4: Call-ID: 660ba5b156e7b87838cb44e973401a18@90.0.0.62 (51) [Sep 14 09:34:31] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 5: Date: Thu, 14 Sep 2006 08:34:29 GMT (35) [Sep 14 09:34:31] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 6: CSeq: 102 INVITE (16) [Sep 14 09:34:31] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 7: Server: CSCO/7 (14) [Sep 14 09:34:31] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 8: Contact: (38) [Sep 14 09:34:31] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 9: Content-Length: 0 (17) [Sep 14 09:34:31] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 10: (0) --- (10 headers 0 lines)--- [Sep 14 09:34:31] DEBUG[15727]: chan_sip.c:2045 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #1960 - INVITE (got response) [Sep 14 09:34:31] DEBUG[15727]: chan_sip.c:2054 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '660ba5b156e7b87838cb44e973401a18@90.0.0.62' Request 102: Found [Sep 14 09:34:31] DEBUG[15727]: chan_sip.c:11221 handle_response_invite: SIP response 100 to standard invite foxtrot*CLI> <-- SIP read from 192.168.0.200:50628: SIP/2.0 180 Ringing Via: SIP/2.0/UDP 90.0.0.62:5060;branch=z9hG4bK38666bad;rport From: "07803034440" ;tag=as7d0cfcef To: ;tag=000785993d3d00351b424905-04a45e44 Call-ID: 660ba5b156e7b87838cb44e973401a18@90.0.0.62 Date: Thu, 14 Sep 2006 08:34:29 GMT CSeq: 102 INVITE Server: CSCO/7 Contact: Content-Length: 0 [Sep 14 09:34:31] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 0: SIP/2.0 180 Ringing (19) [Sep 14 09:34:31] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 1: Via: SIP/2.0/UDP 90.0.0.62:5060;branch=z9hG4bK38666bad;rport (60) [Sep 14 09:34:31] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 2: From: "07803034440" ;tag=as7d0cfcef (62) [Sep 14 09:34:31] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 3: To: ;tag=000785993d3d00351b424905-04a45e44 (71) [Sep 14 09:34:31] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 4: Call-ID: 660ba5b156e7b87838cb44e973401a18@90.0.0.62 (51) [Sep 14 09:34:31] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 5: Date: Thu, 14 Sep 2006 08:34:29 GMT (35) [Sep 14 09:34:31] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 6: CSeq: 102 INVITE (16) [Sep 14 09:34:31] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 7: Server: CSCO/7 (14) [Sep 14 09:34:31] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 8: Contact: (38) [Sep 14 09:34:31] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 9: Content-Length: 0 (17) [Sep 14 09:34:31] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 10: (0) --- (10 headers 0 lines)--- [Sep 14 09:34:31] DEBUG[15727]: chan_sip.c:2054 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '660ba5b156e7b87838cb44e973401a18@90.0.0.62' Request 102: Found [Sep 14 09:34:31] DEBUG[15727]: chan_sip.c:11221 handle_response_invite: SIP response 180 to standard invite [Sep 14 09:34:31] DEBUG[15727]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/5706-0951ae00 -- SIP/5706-0951ae00 is ringing [Sep 14 09:34:31] DEBUG[23084]: rtp.c:1401 ast_rtp_early_bridge: Channel 'Zap/1-1' has no RTP, not doing anything [Sep 14 09:34:31] DEBUG[23084]: chan_zap.c:4976 zt_indicate: Requested indication 3 on channel Zap/1-1 [Sep 14 09:34:31] DEBUG[15718]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5706 [Sep 14 09:34:31] DEBUG[15718]: chan_sip.c:14652 sip_devicestate: Checking device state for peer 5706 [Sep 14 09:34:31] DEBUG[15718]: devicestate.c:287 do_state_change: Changing state for SIP/5706 - state 8 (On Hold) [Sep 14 09:34:31] DEBUG[23088]: app_queue.c:535 changethread: Device 'SIP/5706' changed to state '8' (On Hold) but we don't care because they're not a member of any queue. [Sep 14 09:34:31] DEBUG[23084]: channel.c:1436 queue_frame_to_spies: Triggering queue flush for spy 'MixMonitor' on 'Zap/1-1' [Sep 14 09:34:31] DEBUG[23084]: channel.c:1436 queue_frame_to_spies: Triggering queue flush for spy 'MixMonitor' on 'Zap/1-1' [Sep 14 09:34:32] DEBUG[23084]: channel.c:1436 queue_frame_to_spies: Triggering queue flush for spy 'MixMonitor' on 'Zap/1-1' foxtrot*CLI> <-- SIP read from 192.168.0.200:50628: SIP/2.0 200 OK Via: SIP/2.0/UDP 90.0.0.62:5060;branch=z9hG4bK38666bad;rport From: "07803034440" ;tag=as7d0cfcef To: ;tag=000785993d3d00351b424905-04a45e44 Call-ID: 660ba5b156e7b87838cb44e973401a18@90.0.0.62 Date: Thu, 14 Sep 2006 08:34:31 GMT CSeq: 102 INVITE Server: CSCO/7 Contact: Content-Type: application/sdp Content-Length: 198 v=0 o=Cisco-SIPUA 21692 4234 IN IP4 192.168.0.200 s=SIP Call c=IN IP4 192.168.0.200 t=0 0 m=audio 23920 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 [Sep 14 09:34:32] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 0: SIP/2.0 200 OK (14) [Sep 14 09:34:32] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 1: Via: SIP/2.0/UDP 90.0.0.62:5060;branch=z9hG4bK38666bad;rport (60) [Sep 14 09:34:32] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 2: From: "07803034440" ;tag=as7d0cfcef (62) [Sep 14 09:34:32] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 3: To: ;tag=000785993d3d00351b424905-04a45e44 (71) [Sep 14 09:34:32] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 4: Call-ID: 660ba5b156e7b87838cb44e973401a18@90.0.0.62 (51) [Sep 14 09:34:32] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 5: Date: Thu, 14 Sep 2006 08:34:31 GMT (35) [Sep 14 09:34:32] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 6: CSeq: 102 INVITE (16) [Sep 14 09:34:32] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 7: Server: CSCO/7 (14) [Sep 14 09:34:32] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 8: Contact: (38) [Sep 14 09:34:32] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 9: Content-Type: application/sdp (29) [Sep 14 09:34:32] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 10: Content-Length: 198 (19) [Sep 14 09:34:32] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 11: (0) [Sep 14 09:34:32] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: v=0 (3) [Sep 14 09:34:32] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: o=Cisco-SIPUA 21692 4234 IN IP4 192.168.0.200 (45) [Sep 14 09:34:32] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: s=SIP Call (10) [Sep 14 09:34:32] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: c=IN IP4 192.168.0.200 (22) [Sep 14 09:34:32] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: t=0 0 (5) [Sep 14 09:34:32] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: m=audio 23920 RTP/AVP 0 101 (27) [Sep 14 09:34:32] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Sep 14 09:34:32] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Sep 14 09:34:32] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: a=fmtp:101 0-15 (15) --- (11 headers 9 lines)--- [Sep 14 09:34:32] DEBUG[15727]: chan_sip.c:1994 __sip_ack: Acked pending invite 102 [Sep 14 09:34:32] DEBUG[15727]: chan_sip.c:2012 __sip_ack: Stopping retransmission on '660ba5b156e7b87838cb44e973401a18@90.0.0.62' of Request 102: Match Not Found [Sep 14 09:34:32] DEBUG[15727]: chan_sip.c:11221 handle_response_invite: SIP response 200 to standard invite Found RTP audio format 0 Found RTP audio format 101 Peer audio RTP is at port 192.168.0.200:23920 Found description format PCMU for ID 0 Found description format telephone-event for ID 101 Got unsupported a:fmtp in SDP offer [Sep 14 09:34:32] DEBUG[15727]: chan_sip.c:4877 process_sdp: T38 state changed to 0 on channel SIP/5706-0951ae00 Capabilities: us - 0x404 (ulaw|ilbc), peer - audio=0x4 (ulaw)/video=0x0 (nothing), combined - 0x4 (ulaw) Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) Peer audio RTP is at port 192.168.0.200:23920 [Sep 14 09:34:32] DEBUG[15727]: chan_sip.c:4947 process_sdp: We're settling with these formats: 0x4 (ulaw) [Sep 14 09:34:32] DEBUG[15727]: chan_sip.c:4954 process_sdp: We have an owner, now see if we need to change this call [Sep 14 09:34:32] DEBUG[15727]: chan_sip.c:2879 update_call_counter: Updating call counter for outgoing call [Sep 14 09:34:32] DEBUG[15727]: chan_sip.c:7631 build_route: build_route: Contact hop: list_route: hop: [Sep 14 09:34:32] DEBUG[15727]: chan_sip.c:5378 reqprep: Strict routing enforced for session 660ba5b156e7b87838cb44e973401a18@90.0.0.62 set_destination: Parsing for address/port to send to set_destination: set destination to 192.168.0.200, port 5060 Transmitting (no NAT) to 192.168.0.200:5060: ACK sip:5706@192.168.0.200:5060 SIP/2.0 Via: SIP/2.0/UDP 90.0.0.62:5060;branch=z9hG4bK36f99e42;rport From: "07803034440" ;tag=as7d0cfcef To: ;tag=000785993d3d00351b424905-04a45e44 Contact: Call-ID: 660ba5b156e7b87838cb44e973401a18@90.0.0.62 CSeq: 102 ACK User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- [Sep 14 09:34:32] DEBUG[23084]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/5706-0951ae00 -- SIP/5706-0951ae00 answered Zap/1-1 [Sep 14 09:34:32] DEBUG[23084]: rtp.c:1401 ast_rtp_early_bridge: Channel 'Zap/1-1' has no RTP, not doing anything [Sep 14 09:34:32] DEBUG[23084]: chan_zap.c:4976 zt_indicate: Requested indication -1 on channel Zap/1-1 [Sep 14 09:34:32] DEBUG[15718]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5706 [Sep 14 09:34:32] DEBUG[15718]: chan_sip.c:14652 sip_devicestate: Checking device state for peer 5706 [Sep 14 09:34:32] DEBUG[15718]: devicestate.c:287 do_state_change: Changing state for SIP/5706 - state 8 (On Hold) [Sep 14 09:34:32] DEBUG[23089]: app_queue.c:535 changethread: Device 'SIP/5706' changed to state '8' (On Hold) but we don't care because they're not a member of any queue. [Sep 14 09:34:32] DEBUG[23084]: rtp.c:2518 ast_rtp_write: Ooh, format changed from unknown to ulaw [Sep 14 09:34:32] DEBUG[23084]: channel.c:1436 queue_frame_to_spies: Triggering queue flush for spy 'MixMonitor' on 'Zap/1-1' [Sep 14 09:34:32] DEBUG[23084]: channel.c:1381 queue_frame_to_spies: Building translator from alaw to SLINEAR for spies on channel Zap/1-1 foxtrot*CLI> <-- SIP read from 192.168.6.174:5060: REGISTER sip:192.168.6.6 SIP/2.0 Via: SIP/2.0/UDP 192.168.6.174;branch=z9hG4bK23294b34e Max-Forwards: 70 Content-Length: 0 To: 5708 From: 5708 ;tag=49299fc62d2e543 Call-ID: 2bb0e100fef4a23e14f8682b7d47ecd7@192.168.6.174 CSeq: 981795109 REGISTER Contact: 5708 Allow-Events: talk,hold,conference Allow:NOTIFY,REFER,OPTIONS,INVITE,ACK,CANCEL,BYE,INFO Authorization:Digest response="d55ef8752fa378e5b963e5a84f7a68e7",username="5708",realm="asterisk",nonce="443c21d5",algorithm=MD5,uri="sip:192.168.6.6" User-Agent: Aastra 480i/1.4.0.1048 Brcm Callctrl/1.5.1.0 MxSF/v3.2.6.26 [Sep 14 09:34:33] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 0: REGISTER sip:192.168.6.6 SIP/2.0 (32) [Sep 14 09:34:33] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.6.174;branch=z9hG4bK23294b34e (54) [Sep 14 09:34:33] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 2: Max-Forwards: 70 (16) [Sep 14 09:34:33] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 3: Content-Length: 0 (17) [Sep 14 09:34:33] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 4: To: 5708 (31) [Sep 14 09:34:33] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 5: From: 5708 ;tag=49299fc62d2e543 (53) [Sep 14 09:34:33] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 6: Call-ID: 2bb0e100fef4a23e14f8682b7d47ecd7@192.168.6.174 (55) [Sep 14 09:34:33] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 7: CSeq: 981795109 REGISTER (24) [Sep 14 09:34:33] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 8: Contact: 5708 (38) [Sep 14 09:34:33] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 9: Allow-Events: talk,hold,conference (34) [Sep 14 09:34:33] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 10: Allow:NOTIFY,REFER,OPTIONS,INVITE,ACK,CANCEL,BYE,INFO (53) [Sep 14 09:34:33] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 11: Authorization:Digest response="d55ef8752fa378e5b963e5a84f7a68e7",username="5708",realm="asterisk",nonce="443c21d5",algorithm=MD5,uri="sip:192.168.6.6" (150) [Sep 14 09:34:33] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 12: User-Agent: Aastra 480i/1.4.0.1048 Brcm Callctrl/1.5.1.0 MxSF/v3.2.6.26 (71) [Sep 14 09:34:33] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 13: (0) --- (13 headers 0 lines)--- [Sep 14 09:34:33] DEBUG[15727]: chan_sip.c:4152 sip_alloc: Allocating new SIP dialog for 2bb0e100fef4a23e14f8682b7d47ecd7@192.168.6.174 - REGISTER (No RTP) [Sep 14 09:34:33] DEBUG[15727]: chan_sip.c:14065 handle_request: **** Received REGISTER (2) - Command in SIP REGISTER Using latest REGISTER request as basis request Sending to 192.168.6.174 : 5060 (no NAT) Transmitting (no NAT) to 192.168.6.174:5060: SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.6.174;branch=z9hG4bK23294b34e;received=192.168.6.174 From: 5708 ;tag=49299fc62d2e543 To: 5708 Call-ID: 2bb0e100fef4a23e14f8682b7d47ecd7@192.168.6.174 CSeq: 981795109 REGISTER User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 --- Transmitting (no NAT) to 192.168.6.174:5060: SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 192.168.6.174;branch=z9hG4bK23294b34e;received=192.168.6.174 From: 5708 ;tag=49299fc62d2e543 To: 5708 ;tag=as6def598a Call-ID: 2bb0e100fef4a23e14f8682b7d47ecd7@192.168.6.174 CSeq: 981795109 REGISTER User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="628a29d0" Content-Length: 0 --- Scheduling destruction of SIP dialog '2bb0e100fef4a23e14f8682b7d47ecd7@192.168.6.174' in 32000 ms (Method: REGISTER) foxtrot*CLI> <-- SIP read from 192.168.6.174:5060: REGISTER sip:192.168.6.6 SIP/2.0 Via: SIP/2.0/UDP 192.168.6.174;branch=z9hG4bKa9daed7d9 Max-Forwards: 70 Content-Length: 0 To: 5708 From: 5708 ;tag=49299fc62d2e543 Call-ID: 2bb0e100fef4a23e14f8682b7d47ecd7@192.168.6.174 CSeq: 981795110 REGISTER Contact: 5708 Allow-Events: talk,hold,conference Allow:NOTIFY,REFER,OPTIONS,INVITE,ACK,CANCEL,BYE,INFO Authorization:Digest response="7ee5d62ef699dcb9fbfe213cf939da61",username="5708",realm="asterisk",nonce="628a29d0",algorithm=MD5,uri="sip:192.168.6.6" User-Agent: Aastra 480i/1.4.0.1048 Brcm Callctrl/1.5.1.0 MxSF/v3.2.6.26 [Sep 14 09:34:33] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 0: REGISTER sip:192.168.6.6 SIP/2.0 (32) [Sep 14 09:34:33] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.6.174;branch=z9hG4bKa9daed7d9 (54) [Sep 14 09:34:33] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 2: Max-Forwards: 70 (16) [Sep 14 09:34:33] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 3: Content-Length: 0 (17) [Sep 14 09:34:33] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 4: To: 5708 (31) [Sep 14 09:34:33] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 5: From: 5708 ;tag=49299fc62d2e543 (53) [Sep 14 09:34:33] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 6: Call-ID: 2bb0e100fef4a23e14f8682b7d47ecd7@192.168.6.174 (55) [Sep 14 09:34:33] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 7: CSeq: 981795110 REGISTER (24) [Sep 14 09:34:33] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 8: Contact: 5708 (38) [Sep 14 09:34:33] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 9: Allow-Events: talk,hold,conference (34) [Sep 14 09:34:33] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 10: Allow:NOTIFY,REFER,OPTIONS,INVITE,ACK,CANCEL,BYE,INFO (53) [Sep 14 09:34:33] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 11: Authorization:Digest response="7ee5d62ef699dcb9fbfe213cf939da61",username="5708",realm="asterisk",nonce="628a29d0",algorithm=MD5,uri="sip:192.168.6.6" (150) [Sep 14 09:34:33] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 12: User-Agent: Aastra 480i/1.4.0.1048 Brcm Callctrl/1.5.1.0 MxSF/v3.2.6.26 (71) [Sep 14 09:34:33] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 13: (0) --- (13 headers 0 lines)--- [Sep 14 09:34:33] DEBUG[15727]: chan_sip.c:14065 handle_request: **** Received REGISTER (2) - Command in SIP REGISTER Using latest REGISTER request as basis request Sending to 192.168.6.174 : 5060 (no NAT) Transmitting (no NAT) to 192.168.6.174:5060: SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.6.174;branch=z9hG4bKa9daed7d9;received=192.168.6.174 From: 5708 ;tag=49299fc62d2e543 To: 5708 Call-ID: 2bb0e100fef4a23e14f8682b7d47ecd7@192.168.6.174 CSeq: 981795110 REGISTER User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 --- Transmitting (no NAT) to 192.168.6.174:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.6.174;branch=z9hG4bKa9daed7d9;received=192.168.6.174 From: 5708 ;tag=49299fc62d2e543 To: 5708 ;tag=as6def598a Call-ID: 2bb0e100fef4a23e14f8682b7d47ecd7@192.168.6.174 CSeq: 981795110 REGISTER User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Expires: 120 Contact: ;expires=120 Date: Thu, 14 Sep 2006 08:34:33 GMT Content-Length: 0 --- [Sep 14 09:34:33] DEBUG[15727]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/5708 Scheduling destruction of SIP dialog '2bb0e100fef4a23e14f8682b7d47ecd7@192.168.6.174' in 15000 ms (Method: REGISTER) [Sep 14 09:34:33] DEBUG[15718]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5708 [Sep 14 09:34:33] DEBUG[15718]: chan_sip.c:14652 sip_devicestate: Checking device state for peer 5708 [Sep 14 09:34:33] DEBUG[15718]: devicestate.c:287 do_state_change: Changing state for SIP/5708 - state 1 (Not in use) [Sep 14 09:34:33] DEBUG[23090]: app_queue.c:535 changethread: Device 'SIP/5708' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. foxtrot*CLI> <-- SIP read from 192.168.0.200:50628: INVITE sip:07803034440@90.0.0.62:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.0.200:5060;branch=z9hG4bK343a4abf From: ;tag=000785993d3d00351b424905-04a45e44 To: "07803034440" ;tag=as7d0cfcef Call-ID: 660ba5b156e7b87838cb44e973401a18@90.0.0.62 Date: Thu, 14 Sep 2006 08:34:37 GMT CSeq: 101 INVITE User-Agent: CSCO/7 Contact: Content-Type: application/sdp Content-Length: 191 Remote-Party-ID: "5706" ;party=calling;id-type=subscriber;privacy=off;screen=no v=0 o=Cisco-SIPUA 8599 6266 IN IP4 192.168.0.200 s=SIP Call c=IN IP4 0.0.0.0 t=0 0 m=audio 23920 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 [Sep 14 09:34:38] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 0: INVITE sip:07803034440@90.0.0.62:5060 SIP/2.0 (45) [Sep 14 09:34:38] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.0.200:5060;branch=z9hG4bK343a4abf (58) [Sep 14 09:34:38] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 2: From: ;tag=000785993d3d00351b424905-04a45e44 (73) [Sep 14 09:34:38] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 3: To: "07803034440" ;tag=as7d0cfcef (60) [Sep 14 09:34:38] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 4: Call-ID: 660ba5b156e7b87838cb44e973401a18@90.0.0.62 (51) [Sep 14 09:34:38] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 5: Date: Thu, 14 Sep 2006 08:34:37 GMT (35) [Sep 14 09:34:38] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 6: CSeq: 101 INVITE (16) [Sep 14 09:34:38] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 7: User-Agent: CSCO/7 (18) [Sep 14 09:34:38] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 8: Contact: (38) [Sep 14 09:34:38] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 9: Content-Type: application/sdp (29) [Sep 14 09:34:38] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 10: Content-Length: 191 (19) [Sep 14 09:34:38] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 11: Remote-Party-ID: "5706" ;party=calling;id-type=subscriber;privacy=off;screen=no (103) [Sep 14 09:34:38] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 12: (0) [Sep 14 09:34:38] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: v=0 (3) [Sep 14 09:34:38] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: o=Cisco-SIPUA 8599 6266 IN IP4 192.168.0.200 (44) [Sep 14 09:34:38] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: s=SIP Call (10) [Sep 14 09:34:38] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: c=IN IP4 0.0.0.0 (16) [Sep 14 09:34:38] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: t=0 0 (5) [Sep 14 09:34:38] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: m=audio 23920 RTP/AVP 0 101 (27) [Sep 14 09:34:38] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Sep 14 09:34:38] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Sep 14 09:34:38] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: a=fmtp:101 0-15 (15) --- (12 headers 9 lines)--- [Sep 14 09:34:38] DEBUG[15727]: chan_sip.c:14065 handle_request: **** Received INVITE (5) - Command in SIP INVITE Sending to 192.168.0.200 : 5060 (no NAT) Found RTP audio format 0 Found RTP audio format 101 Peer audio RTP is at port 0.0.0.0:23920 Found description format PCMU for ID 0 Found description format telephone-event for ID 101 Got unsupported a:fmtp in SDP offer [Sep 14 09:34:38] DEBUG[15727]: chan_sip.c:4877 process_sdp: T38 state changed to 0 on channel SIP/5706-0951ae00 Capabilities: us - 0x404 (ulaw|ilbc), peer - audio=0x4 (ulaw)/video=0x0 (nothing), combined - 0x4 (ulaw) Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) Peer audio RTP is at port 0.0.0.0:23920 [Sep 14 09:34:38] DEBUG[15727]: chan_sip.c:4947 process_sdp: We're settling with these formats: 0x4 (ulaw) [Sep 14 09:34:38] DEBUG[15727]: chan_sip.c:4954 process_sdp: We have an owner, now see if we need to change this call [Sep 14 09:34:38] DEBUG[15727]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/5706 [Sep 14 09:34:38] DEBUG[15727]: chan_sip.c:12921 handle_request_invite: Got a SIP re-invite for call 660ba5b156e7b87838cb44e973401a18@90.0.0.62 [Sep 14 09:34:38] DEBUG[15727]: chan_sip.c:13010 handle_request_invite: SIP/5706-0951ae00: This call is UP.... [Sep 14 09:34:38] DEBUG[15727]: chan_sip.c:5847 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True [Sep 14 09:34:38] DEBUG[15727]: chan_sip.c:5848 add_sdp: ** Our prefcodec: 0x8 (alaw) Audio is at 90.0.0.62 port 15836 Adding codec 0x4 (ulaw) to SDP Adding non-codec 0x1 (telephone-event) to SDP [Sep 14 09:34:38] DEBUG[15727]: chan_sip.c:6000 add_sdp: -- Done with adding codecs to SDP [Sep 14 09:34:38] DEBUG[15727]: chan_sip.c:6039 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw) Reliably Transmitting (no NAT) to 192.168.0.200:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.0.200:5060;branch=z9hG4bK343a4abf;received=192.168.0.200 From: ;tag=000785993d3d00351b424905-04a45e44 To: "07803034440" ;tag=as7d0cfcef Call-ID: 660ba5b156e7b87838cb44e973401a18@90.0.0.62 CSeq: 101 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 222 v=0 o=root 15662 15663 IN IP4 90.0.0.62 s=session c=IN IP4 90.0.0.62 t=0 0 m=audio 15836 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=sendrecv --- [Sep 14 09:34:38] DEBUG[15727]: chan_sip.c:1909 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #1966 [Sep 14 09:34:38] DEBUG[23084]: chan_zap.c:4976 zt_indicate: Requested indication 16 on channel Zap/1-1 -- Started music on hold, class 'default', on Zap/1-1 [Sep 14 09:34:38] DEBUG[23084]: channel.c:1845 ast_settimeout: Scheduling timer at 160 sample intervals [Sep 14 09:34:38] DEBUG[15718]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5706 [Sep 14 09:34:38] DEBUG[15718]: chan_sip.c:14652 sip_devicestate: Checking device state for peer 5706 [Sep 14 09:34:38] DEBUG[15718]: devicestate.c:287 do_state_change: Changing state for SIP/5706 - state 8 (On Hold) [Sep 14 09:34:38] DEBUG[23091]: app_queue.c:535 changethread: Device 'SIP/5706' changed to state '8' (On Hold) but we don't care because they're not a member of any queue. [Sep 14 09:34:38] DEBUG[23084]: channel.c:2162 __ast_read: Generator got voice, switching to phase locked mode [Sep 14 09:34:38] DEBUG[23084]: channel.c:1845 ast_settimeout: Scheduling timer at 0 sample intervals [Sep 14 09:34:38] DEBUG[23084]: channel.c:2638 set_format: Set channel Zap/1-1 to write format ulaw [Sep 14 09:34:38] DEBUG[23084]: res_musiconhold.c:252 ast_moh_files_next: Zap/1-1 Opened file 17 '/var/lib/asterisk/sounds/custom/moh/track11' foxtrot*CLI> <-- SIP read from 192.168.0.200:50628: ACK sip:07803034440@90.0.0.62:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.0.200:5060;branch=z9hG4bK19fe38cd From: ;tag=000785993d3d00351b424905-04a45e44 To: "07803034440" ;tag=as7d0cfcef Call-ID: 660ba5b156e7b87838cb44e973401a18@90.0.0.62 Date: Thu, 14 Sep 2006 08:34:37 GMT CSeq: 101 ACK User-Agent: CSCO/7 Content-Length: 0 [Sep 14 09:34:39] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 0: ACK sip:07803034440@90.0.0.62:5060 SIP/2.0 (42) [Sep 14 09:34:39] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.0.200:5060;branch=z9hG4bK19fe38cd (58) [Sep 14 09:34:39] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 2: From: ;tag=000785993d3d00351b424905-04a45e44 (73) [Sep 14 09:34:39] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 3: To: "07803034440" ;tag=as7d0cfcef (60) [Sep 14 09:34:39] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 4: Call-ID: 660ba5b156e7b87838cb44e973401a18@90.0.0.62 (51) [Sep 14 09:34:39] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 5: Date: Thu, 14 Sep 2006 08:34:37 GMT (35) [Sep 14 09:34:39] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 6: CSeq: 101 ACK (13) [Sep 14 09:34:39] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 7: User-Agent: CSCO/7 (18) [Sep 14 09:34:39] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 8: Content-Length: 0 (17) [Sep 14 09:34:39] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 9: (0) --- (9 headers 0 lines)--- [Sep 14 09:34:39] DEBUG[15727]: chan_sip.c:14065 handle_request: **** Received ACK (6) - Command in SIP ACK [Sep 14 09:34:39] DEBUG[15727]: chan_sip.c:2002 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #1966 [Sep 14 09:34:39] DEBUG[15727]: chan_sip.c:2012 __sip_ack: Stopping retransmission on '660ba5b156e7b87838cb44e973401a18@90.0.0.62' of Response 101: Match Not Found foxtrot*CLI> <-- SIP read from 192.168.0.200:50628: INVITE sip:5709@90.0.0.62 SIP/2.0 Via: SIP/2.0/UDP 192.168.0.200:5060;branch=z9hG4bK3098ff27 From: "5706" ;tag=000785993d3d0036156163f1-07501bb1 To: Call-ID: 00078599-3d3d001d-129a6fe0-34d614d5@192.168.0.200 Date: Thu, 14 Sep 2006 08:34:39 GMT CSeq: 101 INVITE User-Agent: CSCO/7 Contact: Expires: 180 Content-Type: application/sdp Content-Length: 247 Accept: application/sdp Remote-Party-ID: "5706" ;party=calling;id-type=subscriber;privacy=off;screen=no v=0 o=Cisco-SIPUA 9049 8631 IN IP4 192.168.0.200 s=SIP Call c=IN IP4 192.168.0.200 t=0 0 m=audio 23922 RTP/AVP 0 8 18 101 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:18 G729/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 0: INVITE sip:5709@90.0.0.62 SIP/2.0 (33) [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.0.200:5060;branch=z9hG4bK3098ff27 (58) [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 2: From: "5706" ;tag=000785993d3d0036156163f1-07501bb1 (71) [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 3: To: (24) [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 4: Call-ID: 00078599-3d3d001d-129a6fe0-34d614d5@192.168.0.200 (58) [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 5: Date: Thu, 14 Sep 2006 08:34:39 GMT (35) [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 6: CSeq: 101 INVITE (16) [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 7: User-Agent: CSCO/7 (18) [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 8: Contact: (38) [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 9: Expires: 180 (12) [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 10: Content-Type: application/sdp (29) [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 11: Content-Length: 247 (19) [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 12: Accept: application/sdp (23) [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 13: Remote-Party-ID: "5706" ;party=calling;id-type=subscriber;privacy=off;screen=no (103) [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 14: (0) [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: v=0 (3) [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: o=Cisco-SIPUA 9049 8631 IN IP4 192.168.0.200 (44) [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: s=SIP Call (10) [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: c=IN IP4 192.168.0.200 (22) [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: t=0 0 (5) [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: m=audio 23922 RTP/AVP 0 8 18 101 (32) [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: a=rtpmap:18 G729/8000 (21) [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: a=fmtp:101 0-15 (15) --- (14 headers 11 lines)--- [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:4152 sip_alloc: Allocating new SIP dialog for 00078599-3d3d001d-129a6fe0-34d614d5@192.168.0.200 - INVITE (With RTP) [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:14065 handle_request: **** Received INVITE (5) - Command in SIP INVITE Sending to 192.168.0.200 : 5060 (no NAT) Using INVITE request as basis request - 00078599-3d3d001d-129a6fe0-34d614d5@192.168.0.200 [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:8690 check_user_full: Setting NAT on RTP to Off Reliably Transmitting (no NAT) to 192.168.0.200:5060: SIP/2.0 407 Proxy Authentication Required Via: SIP/2.0/UDP 192.168.0.200:5060;branch=z9hG4bK3098ff27;received=192.168.0.200 From: "5706" ;tag=000785993d3d0036156163f1-07501bb1 To: ;tag=as520540e2 Call-ID: 00078599-3d3d001d-129a6fe0-34d614d5@192.168.0.200 CSeq: 101 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Proxy-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="64128275" Content-Length: 0 --- [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:1909 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #1967 Scheduling destruction of SIP dialog '00078599-3d3d001d-129a6fe0-34d614d5@192.168.0.200' in 32000 ms (Method: INVITE) Found user '5706' foxtrot*CLI> <-- SIP read from 192.168.0.200:50636: ACK sip:5709@90.0.0.62 SIP/2.0 Via: SIP/2.0/UDP 192.168.0.200:5060;branch=z9hG4bK3098ff27 From: "5706" ;tag=000785993d3d0036156163f1-07501bb1 To: ;tag=as520540e2 Call-ID: 00078599-3d3d001d-129a6fe0-34d614d5@192.168.0.200 Date: Thu, 14 Sep 2006 08:34:39 GMT CSeq: 101 ACK Content-Length: 0 [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 0: ACK sip:5709@90.0.0.62 SIP/2.0 (30) [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.0.200:5060;branch=z9hG4bK3098ff27 (58) [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 2: From: "5706" ;tag=000785993d3d0036156163f1-07501bb1 (71) [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 3: To: ;tag=as520540e2 (39) [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 4: Call-ID: 00078599-3d3d001d-129a6fe0-34d614d5@192.168.0.200 (58) [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 5: Date: Thu, 14 Sep 2006 08:34:39 GMT (35) [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 6: CSeq: 101 ACK (13) [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 7: Content-Length: 0 (17) [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 8: (0) --- (8 headers 0 lines)--- [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:14065 handle_request: **** Received ACK (6) - Command in SIP ACK [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:2002 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #1967 [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:2012 __sip_ack: Stopping retransmission on '00078599-3d3d001d-129a6fe0-34d614d5@192.168.0.200' of Response 101: Match Not Found foxtrot*CLI> <-- SIP read from 192.168.0.200:50628: INVITE sip:5709@90.0.0.62 SIP/2.0 Via: SIP/2.0/UDP 192.168.0.200:5060;branch=z9hG4bK0ef23b4b From: "5706" ;tag=000785993d3d0036156163f1-07501bb1 To: Call-ID: 00078599-3d3d001d-129a6fe0-34d614d5@192.168.0.200 Date: Thu, 14 Sep 2006 08:34:40 GMT CSeq: 102 INVITE User-Agent: CSCO/7 Contact: Proxy-Authorization: Digest username="5706",realm="asterisk",uri="sip:90.0.0.62",response="936cf75f69b6c64b3d725b6255417ef8",nonce="64128275",algorithm=MD5 Expires: 180 Content-Type: application/sdp Content-Length: 247 Remote-Party-ID: "5706" ;party=calling;id-type=subscriber;privacy=off;screen=no v=0 o=Cisco-SIPUA 9049 8631 IN IP4 192.168.0.200 s=SIP Call c=IN IP4 192.168.0.200 t=0 0 m=audio 23922 RTP/AVP 0 8 18 101 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:18 G729/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 0: INVITE sip:5709@90.0.0.62 SIP/2.0 (33) [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.0.200:5060;branch=z9hG4bK0ef23b4b (58) [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 2: From: "5706" ;tag=000785993d3d0036156163f1-07501bb1 (71) [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 3: To: (24) [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 4: Call-ID: 00078599-3d3d001d-129a6fe0-34d614d5@192.168.0.200 (58) [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 5: Date: Thu, 14 Sep 2006 08:34:40 GMT (35) [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 6: CSeq: 102 INVITE (16) [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 7: User-Agent: CSCO/7 (18) [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 8: Contact: (38) [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 9: Proxy-Authorization: Digest username="5706",realm="asterisk",uri="sip:90.0.0.62",response="936cf75f69b6c64b3d725b6255417ef8",nonce="64128275",algorithm=MD5 (155) [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 10: Expires: 180 (12) [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 11: Content-Type: application/sdp (29) [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 12: Content-Length: 247 (19) [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 13: Remote-Party-ID: "5706" ;party=calling;id-type=subscriber;privacy=off;screen=no (103) [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 14: (0) [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: v=0 (3) [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: o=Cisco-SIPUA 9049 8631 IN IP4 192.168.0.200 (44) [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: s=SIP Call (10) [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: c=IN IP4 192.168.0.200 (22) [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: t=0 0 (5) [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: m=audio 23922 RTP/AVP 0 8 18 101 (32) [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: a=rtpmap:18 G729/8000 (21) [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: a=fmtp:101 0-15 (15) --- (14 headers 11 lines)--- [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:14065 handle_request: **** Received INVITE (5) - Command in SIP INVITE Sending to 192.168.0.200 : 5060 (no NAT) Using INVITE request as basis request - 00078599-3d3d001d-129a6fe0-34d614d5@192.168.0.200 [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:8690 check_user_full: Setting NAT on RTP to Off Found user '5706' Found RTP audio format 0 Found RTP audio format 8 Found RTP audio format 18 Found RTP audio format 101 Peer audio RTP is at port 192.168.0.200:23922 Found description format PCMU for ID 0 Found description format PCMA for ID 8 Found description format G729 for ID 18 Found description format telephone-event for ID 101 Got unsupported a:fmtp in SDP offer [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:4877 process_sdp: T38 state changed to 0 on channel Capabilities: us - 0x404 (ulaw|ilbc), peer - audio=0x10c (ulaw|alaw|g729)/video=0x0 (nothing), combined - 0x4 (ulaw) Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) Peer audio RTP is at port 192.168.0.200:23922 [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:4947 process_sdp: We're settling with these formats: 0x4 (ulaw) [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:12872 handle_request_invite: Checking SIP call limits for device 5706 [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:2879 update_call_counter: Updating call counter for incoming call Looking for 5709 in from-sip (domain 90.0.0.62) [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:3647 sip_new: *** Our native formats are 0x4 (ulaw) [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:3648 sip_new: *** Joint capabilities are 0x4 (ulaw) [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:3649 sip_new: *** Our capabilities are 0x404 (ulaw|ilbc) [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:3650 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:3673 sip_new: This channel will not be able to handle video. [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:7631 build_route: build_route: Contact hop: list_route: hop: [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:12943 handle_request_invite: SIP/5706-09541108: New call is still down.... Trying... Transmitting (no NAT) to 192.168.0.200:5060: SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.0.200:5060;branch=z9hG4bK0ef23b4b;received=192.168.0.200 From: "5706" ;tag=000785993d3d0036156163f1-07501bb1 To: Call-ID: 00078599-3d3d001d-129a6fe0-34d614d5@192.168.0.200 CSeq: 102 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 --- [Sep 14 09:34:41] DEBUG[15727]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/5706-09541108 [Sep 14 09:34:41] DEBUG[15718]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5706 [Sep 14 09:34:41] DEBUG[15718]: chan_sip.c:14652 sip_devicestate: Checking device state for peer 5706 [Sep 14 09:34:41] DEBUG[15718]: devicestate.c:287 do_state_change: Changing state for SIP/5706 - state 8 (On Hold) [Sep 14 09:34:41] DEBUG[23093]: app_queue.c:535 changethread: Device 'SIP/5706' changed to state '8' (On Hold) but we don't care because they're not a member of any queue. [Sep 14 09:34:41] DEBUG[23092]: pbx.c:1684 pbx_extension_helper: Launching 'Answer' -- Executing [5709@from-sip:1] Answer("SIP/5706-09541108", "") in new stack [Sep 14 09:34:41] DEBUG[23092]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/5706-09541108 [Sep 14 09:34:41] DEBUG[23092]: chan_sip.c:3328 sip_answer: SIP answering channel: SIP/5706-09541108 [Sep 14 09:34:41] DEBUG[15718]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5706 [Sep 14 09:34:41] DEBUG[15718]: chan_sip.c:14652 sip_devicestate: Checking device state for peer 5706 [Sep 14 09:34:41] DEBUG[15718]: devicestate.c:287 do_state_change: Changing state for SIP/5706 - state 8 (On Hold) [Sep 14 09:34:41] DEBUG[23092]: chan_sip.c:5847 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True [Sep 14 09:34:41] DEBUG[23092]: chan_sip.c:5848 add_sdp: ** Our prefcodec: 0x0 (nothing) Audio is at 90.0.0.62 port 16170 Adding codec 0x4 (ulaw) to SDP Adding non-codec 0x1 (telephone-event) to SDP [Sep 14 09:34:41] DEBUG[23092]: chan_sip.c:6000 add_sdp: -- Done with adding codecs to SDP [Sep 14 09:34:41] DEBUG[23092]: chan_sip.c:6039 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw) Reliably Transmitting (no NAT) to 192.168.0.200:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.0.200:5060;branch=z9hG4bK0ef23b4b;received=192.168.0.200 From: "5706" ;tag=000785993d3d0036156163f1-07501bb1 To: ;tag=as52f5986f Call-ID: 00078599-3d3d001d-129a6fe0-34d614d5@192.168.0.200 CSeq: 102 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: ontent-Type: application/sdp Content-Length: 222 v=0 o=root 15662 15662 IN IP4 90.0.0.62 s=session c=IN IP4 90.0.0.62 t=0 0 m=audio 16170 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=sendrecv --- [Sep 14 09:34:41] DEBUG[23092]: chan_sip.c:1909 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #1969 [Sep 14 09:34:41] DEBUG[23092]: pbx.c:1684 pbx_extension_helper: Launching 'Dial' -- Executing [5709@from-sip:2] Dial("SIP/5706-09541108", "Local/5710@from-sip/n") in new stack [Sep 14 09:34:41] DEBUG[23092]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Local/5710@from-sip-928e,2 [Sep 14 09:34:41] DEBUG[15718]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for Local - 5710@from-sip [Sep 14 09:34:41] DEBUG[15718]: chan_local.c:141 local_devicestate: Checking if extension 5710@from-sip exists (devicestate) [Sep 14 09:34:41] DEBUG[15718]: devicestate.c:287 do_state_change: Changing state for Local/5710@from-sip - state 2 (In use) [Sep 14 09:34:41] DEBUG[23092]: rtp.c:1470 ast_rtp_make_compatible: Channel 'Local/5710@from-sip-928e,1' has no RTP, not doing anything [Sep 14 09:34:41] DEBUG[23092]: channel.c:3103 ast_channel_inherit_variables: Not copying variable STACK-from-sip-5709-2. [Sep 14 09:34:41] DEBUG[23092]: channel.c:3103 ast_channel_inherit_variables: Not copying variable STACK-from-sip-5709-1. [Sep 14 09:34:41] DEBUG[23092]: channel.c:3103 ast_channel_inherit_variables: Not copying variable SIPCALLID. [Sep 14 09:34:41] DEBUG[23092]: channel.c:3103 ast_channel_inherit_variables: Not copying variable SIPUSERAGENT. [Sep 14 09:34:41] DEBUG[23092]: channel.c:3103 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [Sep 14 09:34:41] DEBUG[23092]: channel.c:3103 ast_channel_inherit_variables: Not copying variable SIPURI. -- Called 5710@from-sip/n [Sep 14 09:34:41] DEBUG[23095]: app_queue.c:535 changethread: Device 'Local/5710@from-sip' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Sep 14 09:34:41] DEBUG[23094]: app_queue.c:535 changethread: Device 'SIP/5706' changed to state '8' (On Hold) but we don't care because they're not a member of any queue. [Sep 14 09:34:41] DEBUG[23096]: pbx.c:1684 pbx_extension_helper: Launching 'Answer' -- Executing [5710@from-sip:1] Answer("Local/5710@from-sip-928e,2", "") in new stack [Sep 14 09:34:41] DEBUG[23096]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Local/5710@from-sip-928e,2 [Sep 14 09:34:41] DEBUG[15718]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for Local - 5710@from-sip [Sep 14 09:34:41] DEBUG[15718]: chan_local.c:141 local_devicestate: Checking if extension 5710@from-sip exists (devicestate) [Sep 14 09:34:41] DEBUG[15718]: devicestate.c:287 do_state_change: Changing state for Local/5710@from-sip - state 2 (In use) [Sep 14 09:34:41] DEBUG[23096]: pbx.c:1684 pbx_extension_helper: Launching 'MixMonitor' -- Executing [5710@from-sip:2] MixMonitor("Local/5710@from-sip-928e,2", "1158222881.12.gsm") in new stack [Sep 14 09:34:41] DEBUG[23096]: channel.c:1200 ast_channel_spy_add: Spy MixMonitor added to channel Local/5710@from-sip-928e,2 [Sep 14 09:34:41] DEBUG[23096]: pbx.c:1684 pbx_extension_helper: Launching 'Dial' -- Executing [5710@from-sip:3] Dial("Local/5710@from-sip-928e,2", "SIP/5710|120|g") in new stack [Sep 14 09:34:41] DEBUG[23096]: chan_sip.c:14710 sip_request_call: Asked to create a SIP channel with formats: 0x4 (ulaw) [Sep 14 09:34:41] DEBUG[23096]: chan_sip.c:4152 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Sep 14 09:34:41] DEBUG[23096]: chan_sip.c:2518 create_addr_from_peer: Setting NAT on RTP to Off [Sep 14 09:34:41] DEBUG[23096]: chan_sip.c:3647 sip_new: *** Our native formats are 0x4 (ulaw) [Sep 14 09:34:41] DEBUG[23096]: chan_sip.c:3648 sip_new: *** Joint capabilities are 0x0 (nothing) [Sep 14 09:34:41] DEBUG[23096]: chan_sip.c:3649 sip_new: *** Our capabilities are 0x404 (ulaw|ilbc) [Sep 14 09:34:41] DEBUG[23096]: chan_sip.c:3650 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Sep 14 09:34:41] DEBUG[23096]: chan_sip.c:3652 sip_new: *** Our preferred formats from the incoming channel are 0x4 (ulaw) [Sep 14 09:34:41] DEBUG[23096]: chan_sip.c:3673 sip_new: This channel will not be able to handle video. [Sep 14 09:34:41] DEBUG[23097]: app_queue.c:535 changethread: Device 'Local/5710@from-sip' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Sep 14 09:34:41] DEBUG[23096]: rtp.c:1477 ast_rtp_make_compatible: == Begin MixMonitor Recording Local/5710@from-sip-928e,2 Channel 'Local/5710@from-sip-928e,2' has no RTP, not doing anything [Sep 14 09:34:41] DEBUG[23092]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Local/5710@from-sip-928e,1 -- Local/5710@from-sip-928e,1 answered SIP/5706-09541108 [Sep 14 09:34:41] DEBUG[23092]: rtp.c:1409 ast_rtp_early_bridge: Channel 'Local/5710@from-sip-928e,1' has no RTP, not doing anything [Sep 14 09:34:41] DEBUG[15718]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for Local - 5710@from-sip [Sep 14 09:34:41] DEBUG[23096]: channel.c:3103 ast_channel_inherit_variables: Not copying variable STACK-from-sip-5710-3. [Sep 14 09:34:41] DEBUG[15718]: chan_local.c:141 local_devicestate: Checking if extension 5710@from-sip exists (devicestate) [Sep 14 09:34:41] DEBUG[23096]: channel.c:3103 ast_channel_inherit_variables: Not copying variable MIXMONITOR_FILENAME. [Sep 14 09:34:41] DEBUG[15718]: devicestate.c:287 do_state_change: Changing state for Local/5710@from-sip - state 2 (In use) [Sep 14 09:34:41] DEBUG[23096]: channel.c:3103 ast_channel_inherit_variables: Not copying variable STACK-from-sip-5710-2. [Sep 14 09:34:41] DEBUG[23099]: app_queue.c:535 changethread: Device 'Local/5710@from-sip' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Sep 14 09:34:41] DEBUG[23096]: channel.c:3103 ast_channel_inherit_variables: Not copying variable STACK-from-sip-5710-1. [Sep 14 09:34:41] DEBUG[23096]: channel.c:3103 ast_channel_inherit_variables: Not copying variable DIALEDPEERNUMBER. [Sep 14 09:34:41] DEBUG[23096]: chan_sip.c:2718 sip_call: Outgoing Call for 5710 [Sep 14 09:34:41] DEBUG[23096]: chan_sip.c:2879 update_call_counter: Updating call counter for outgoing call [Sep 14 09:34:41] DEBUG[23096]: chan_sip.c:2726 sip_call: Our T38 capability (0), joint T38 capability (0) [Sep 14 09:34:41] DEBUG[23096]: chan_sip.c:5847 add_sdp: ** Our capability: 0x404 (ulaw|ilbc) Video flag: False [Sep 14 09:34:41] DEBUG[23096]: chan_sip.c:5848 add_sdp: ** Our prefcodec: 0x4 (ulaw) Audio is at 90.0.0.62 port 18280 Adding codec 0x4 (ulaw) to SDP Adding codec 0x400 (ilbc) to SDP Adding non-codec 0x1 (telephone-event) to SDP [Sep 14 09:34:41] DEBUG[23096]: chan_sip.c:6000 add_sdp: -- Done with adding codecs to SDP [Sep 14 09:34:41] DEBUG[23096]: chan_sip.c:6039 add_sdp: Done building SDP. Settling with this capability: 0x404 (ulaw|ilbc) [Sep 14 09:34:41] DEBUG[23096]: chan_sip.c:4372 parse_request: Header 0: INVITE sip:5710@192.168.0.12:33918;rinstance=e4acfadb594edd00 SIP/2.0 (69) [Sep 14 09:34:41] DEBUG[23096]: chan_sip.c:4372 parse_request: Header 1: Via: SIP/2.0/UDP 90.0.0.62:5060;branch=z9hG4bK7eb692df;rport (60) [Sep 14 09:34:41] DEBUG[23096]: chan_sip.c:4372 parse_request: Header 2: From: "5706" ;tag=as4b6fea46 (57) [Sep 14 09:34:41] DEBUG[23096]: chan_sip.c:4372 parse_request: Header 3: To: (60) [Sep 14 09:34:41] DEBUG[23096]: chan_sip.c:4372 parse_request: Header 4: Contact: (38) [Sep 14 09:34:41] DEBUG[23096]: chan_sip.c:4372 parse_request: Header 5: Call-ID: 7b8bb499037201f0301f283665868c49@90.0.0.62 (51) [Sep 14 09:34:41] DEBUG[23096]: chan_sip.c:4372 parse_request: Header 6: CSeq: 102 INVITE (16) [Sep 14 09:34:41] DEBUG[23096]: chan_sip.c:4372 parse_request: Header 7: User-Agent: Asterisk PBX (24) [Sep 14 09:34:41] DEBUG[23096]: chan_sip.c:4372 parse_request: Header 8: Max-Forwards: 70 (16) [Sep 14 09:34:41] DEBUG[23096]: chan_sip.c:4372 parse_request: Header 9: Date: Thu, 14 Sep 2006 08:34:41 GMT (35) [Sep 14 09:34:41] DEBUG[23096]: chan_sip.c:4372 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Sep 14 09:34:41] DEBUG[23096]: chan_sip.c:4372 parse_request: Header 11: Supported: replaces (19) [Sep 14 09:34:41] DEBUG[23096]: chan_sip.c:4372 parse_request: Header 12: Content-Type: application/sdp (29) [Sep 14 09:34:41] DEBUG[23096]: chan_sip.c:4372 parse_request: Header 13: Content-Length: 267 (19) [Sep 14 09:34:41] DEBUG[23096]: chan_sip.c:4372 parse_request: Header 14: (0) [Sep 14 09:34:41] DEBUG[23096]: chan_sip.c:4404 parse_request: Line: v=0 (3) [Sep 14 09:34:41] DEBUG[23096]: chan_sip.c:4404 parse_request: Line: o=root 15662 15662 IN IP4 90.0.0.62 (35) [Sep 14 09:34:41] DEBUG[23096]: chan_sip.c:4404 parse_request: Line: s=session (9) [Sep 14 09:34:41] DEBUG[23096]: chan_sip.c:4404 parse_request: Line: c=IN IP4 90.0.0.62 (18) [Sep 14 09:34:41] DEBUG[23096]: chan_sip.c:4404 parse_request: Line: t=0 0 (5) [Sep 14 09:34:41] DEBUG[23096]: chan_sip.c:4404 parse_request: Line: m=audio 18280 RTP/AVP 0 97 101 (30) [Sep 14 09:34:41] DEBUG[23096]: chan_sip.c:4404 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Sep 14 09:34:41] DEBUG[23096]: chan_sip.c:4404 parse_request: Line: a=rtpmap:97 iLBC/8000 (21) [Sep 14 09:34:41] DEBUG[23096]: chan_sip.c:4404 parse_request: Line: a=fmtp:97 mode=20 (17) [Sep 14 09:34:41] DEBUG[23096]: chan_sip.c:4404 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Sep 14 09:34:41] DEBUG[23096]: chan_sip.c:4404 parse_request: Line: a=fmtp:101 0-16 (15) [Sep 14 09:34:41] DEBUG[23096]: chan_sip.c:4404 parse_request: Line: a=silenceSupp:off - - - - (25) [Sep 14 09:34:41] DEBUG[23096]: chan_sip.c:4404 parse_request: Line: a=sendrecv (10) Reliably Transmitting (no NAT) to 192.168.0.12:33918: INVITE sip:5710@192.168.0.12:33918;rinstance=e4acfadb594edd00 SIP/2.0 Via: SIP/2.0/UDP 90.0.0.62:5060;branch=z9hG4bK7eb692df;rport From: "5706" ;tag=as4b6fea46 To: Contact: Call-ID: 7b8bb499037201f0301f283665868c49@90.0.0.62 CSeq: 102 INVITE User-Agent: Asterisk PBX Max-Forwards: 70 Date: Thu, 14 Sep 2006 08:34:41 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Type: application/sdp Content-Length: 267 v=0 o=root 15662 15662 IN IP4 90.0.0.62 s=session c=IN IP4 90.0.0.62 t=0 0 m=audio 18280 RTP/AVP 0 97 101 a=rtpmap:0 PCMU/8000 a=rtpmap:97 iLBC/8000 a=fmtp:97 mode=20 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=sendrecv --- [Sep 14 09:34:41] DEBUG[23096]: chan_sip.c:1909 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #1970 -- Called 5710 foxtrot*CLI> <-- SIP read from 192.168.0.12:33918: SIP/2.0 180 Ringing Via: SIP/2.0/UDP 90.0.0.62:5060;branch=z9hG4bK7eb692df;rport=5060 Contact: To: ;tag=4261f323 From: "5706";tag=as4b6fea46 Call-ID: 7b8bb499037201f0301f283665868c49@90.0.0.62 CSeq: 102 INVITE User-Agent: X-Lite release 1002tx stamp 29712 Content-Length: 0 [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 0: SIP/2.0 180 Ringing (19) [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 1: Via: SIP/2.0/UDP 90.0.0.62:5060;branch=z9hG4bK7eb692df;rport=5060 (65) [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 2: Contact: (65) [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 3: To: ;tag=4261f323 (73) [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 4: From: "5706";tag=as4b6fea46 (56) [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 5: Call-ID: 7b8bb499037201f0301f283665868c49@90.0.0.62 (51) [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 6: CSeq: 102 INVITE (16) [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 7: User-Agent: X-Lite release 1002tx stamp 29712 (45) [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 8: Content-Length: 0 (17) [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 9: (0) --- (9 headers 0 lines)--- [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:2045 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #1970 - INVITE (got response) [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:2054 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '7b8bb499037201f0301f283665868c49@90.0.0.62' Request 102: Found [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:11221 handle_response_invite: SIP response 180 to standard invite [Sep 14 09:34:41] DEBUG[15727]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/5710-09544fe8 [Sep 14 09:34:41] DEBUG[15718]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5710 [Sep 14 09:34:41] DEBUG[15718]: chan_sip.c:14652 sip_devicestate: Checking device state for peer 5710 [Sep 14 09:34:41] DEBUG[15718]: devicestate.c:287 do_state_change: Changing state for SIP/5710 - state 1 (Not in use) -- SIP/5710-09544fe8 is ringing [Sep 14 09:34:41] DEBUG[23096]: rtp.c:1401 ast_rtp_early_bridge: Channel 'Local/5710@from-sip-928e,2' has no RTP, not doing anything [Sep 14 09:34:41] DEBUG[23092]: channel.c:3618 ast_generic_bridge: Got a FRAME_CONTROL (3) frame on channel Local/5710@from-sip-928e,1 [Sep 14 09:34:41] DEBUG[23100]: app_queue.c:535 changethread: Device 'SIP/5710' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Sep 14 09:34:41] DEBUG[23092]: channel.c:3895 ast_channel_bridge: Bridge stops bridging channels SIP/5706-09541108 and Local/5710@from-sip-928e,1 [Sep 14 09:34:41] DEBUG[23092]: channel.c:2264 ast_indicate_data: Driver for channel 'SIP/5706-09541108' does not support indication 3, emulating it [Sep 14 09:34:41] DEBUG[23092]: channel.c:2638 set_format: Set channel SIP/5706-09541108 to write format slin [Sep 14 09:34:41] DEBUG[23092]: channel.c:1845 ast_settimeout: Scheduling timer at 160 sample intervals [Sep 14 09:34:41] DEBUG[23092]: rtp.c:659 process_rfc2833: - RTP 2833 Event: 00000005 (len = 4) [Sep 14 09:34:41] DEBUG[23092]: rtp.c:659 process_rfc2833: - RTP 2833 Event: 00000005 (len = 4) [Sep 14 09:34:41] DEBUG[23092]: rtp.c:659 process_rfc2833: - RTP 2833 Event: 00000005 (len = 4) [Sep 14 09:34:41] DEBUG[23092]: rtp.c:2518 ast_rtp_write: Ooh, format changed from unknown to ulaw [Sep 14 09:34:41] DEBUG[23092]: channel.c:2162 __ast_read: Generator got voice, switching to phase locked mode [Sep 14 09:34:41] DEBUG[23092]: channel.c:1845 ast_settimeout: Scheduling timer at 0 sample intervals [Sep 14 09:34:41] DEBUG[23096]: channel.c:1381 queue_frame_to_spies: Building translator from ulaw to SLINEAR for spies on channel Local/5710@from-sip-928e,2 <-- SIP read from 192.168.0.200:50628: ACK sip:5709@90.0.0.62:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.0.200:5060;branch=z9hG4bK78c84bd6 From: "5706" ;tag=000785993d3d0036156163f1-07501bb1 To: ;tag=as52f5986f Call-ID: 00078599-3d3d001d-129a6fe0-34d614d5@192.168.0.200 Date: Thu, 14 Sep 2006 08:34:40 GMT CSeq: 102 ACK User-Agent: CSCO/7 Proxy-Authorization: Digest username="5706",realm="asterisk",uri="sip:90.0.0.62",response="936cf75f69b6c64b3d725b6255417ef8",nonce="64128275",algorithm=MD5 Content-Length: 0 [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 0: ACK sip:5709@90.0.0.62:5060 SIP/2.0 (35) [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.0.200:5060;branch=z9hG4bK78c84bd6 (58) [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 2: From: "5706" ;tag=000785993d3d0036156163f1-07501bb1 (71) [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 3: To: ;tag=as52f5986f (39) [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 4: Call-ID: 00078599-3d3d001d-129a6fe0-34d614d5@192.168.0.200 (58) [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 5: Date: Thu, 14 Sep 2006 08:34:40 GMT (35) [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 6: CSeq: 102 ACK (13) [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 7: User-Agent: CSCO/7 (18) [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 8: Proxy-Authorization: Digest username="5706",realm="asterisk",uri="sip:90.0.0.62",response="936cf75f69b6c64b3d725b6255417ef8",nonce="64128275",algorithm=MD5 (155) [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 9: Content-Length: 0 (17) [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 10: (0) --- (10 headers 0 lines)--- [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:14065 handle_request: **** Received ACK (6) - Command in SIP ACK [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:2002 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #1969 [Sep 14 09:34:41] DEBUG[15727]: chan_sip.c:2012 __sip_ack: Stopping retransmission on '00078599-3d3d001d-129a6fe0-34d614d5@192.168.0.200' of Response 102: Match Not Found [Sep 14 09:34:42] DEBUG[23092]: rtp.c:2417 ast_rtp_raw_write: Difference is 1280, ms is 180 [Sep 14 09:34:42] DEBUG[23092]: rtp.c:2417 ast_rtp_raw_write: Difference is 1192, ms is 169 [Sep 14 09:34:42] DEBUG[23096]: channel.c:1436 queue_frame_to_spies: Triggering queue flush for spy 'MixMonitor' on 'Local/5710@from-sip-928e,2' RTCP SR transmission error, rtcp halted Interrupted system call [Sep 14 09:34:42] NOTICE[15727]: sched.c:283 ast_sched_del: Attempted to delete nonexistent schedule entry 1962! [Sep 14 09:34:42] DEBUG[23096]: channel.c:1436 queue_frame_to_spies: Triggering queue flush for spy 'MixMonitor' on 'Local/5710@from-sip-928e,2' [Sep 14 09:34:43] DEBUG[23096]: channel.c:1436 queue_frame_to_spies: Triggering queue flush for spy 'MixMonitor' on 'Local/5710@from-sip-928e,2' [Sep 14 09:34:43] DEBUG[23096]: channel.c:1436 queue_frame_to_spies: Triggering queue flush for spy 'MixMonitor' on 'Local/5710@from-sip-928e,2' [Sep 14 09:34:44] DEBUG[23096]: channel.c:1436 queue_frame_to_spies: Triggering queue flush for spy 'MixMonitor' on 'Local/5710@from-sip-928e,2' [Sep 14 09:34:44] DEBUG[23096]: channel.c:1436 queue_frame_to_spies: Triggering queue flush for spy 'MixMonitor' on 'Local/5710@from-sip-928e,2' [Sep 14 09:34:45] DEBUG[23096]: channel.c:1436 queue_frame_to_spies: Triggering queue flush for spy 'MixMonitor' on 'Local/5710@from-sip-928e,2' [Sep 14 09:34:45] DEBUG[23096]: channel.c:1436 queue_frame_to_spies: Triggering queue flush for spy 'MixMonitor' on 'Local/5710@from-sip-928e,2' [Sep 14 09:34:46] DEBUG[23096]: channel.c:1436 queue_frame_to_spies: Triggering queue flush for spy 'MixMonitor' on 'Local/5710@from-sip-928e,2' [Sep 14 09:34:46] DEBUG[23096]: channel.c:1436 queue_frame_to_spies: Triggering queue flush for spy 'MixMonitor' on 'Local/5710@from-sip-928e,2' [Sep 14 09:34:47] DEBUG[23096]: channel.c:1436 queue_frame_to_spies: Triggering queue flush for spy 'MixMonitor' on 'Local/5710@from-sip-928e,2' [Sep 14 09:34:48] DEBUG[23096]: channel.c:1436 queue_frame_to_spies: Triggering queue flush for spy 'MixMonitor' on 'Local/5710@from-sip-928e,2' [Sep 14 09:34:48] DEBUG[15727]: chan_sip.c:1941 __sip_autodestruct: Auto destroying call '2bb0e100fef4a23e14f8682b7d47ecd7@192.168.6.174' [Sep 14 09:34:48] DEBUG[15727]: chan_sip.c:2985 sip_destroy: Destroying SIP dialog 2bb0e100fef4a23e14f8682b7d47ecd7@192.168.6.174 Really destroying SIP dialog '2bb0e100fef4a23e14f8682b7d47ecd7@192.168.6.174' Method: REGISTER [Sep 14 09:34:48] DEBUG[23096]: channel.c:1436 queue_frame_to_spies: Triggering queue flush for spy 'MixMonitor' on 'Local/5710@from-sip-928e,2' [Sep 14 09:34:49] DEBUG[23096]: channel.c:1436 queue_frame_to_spies: Triggering queue flush for spy 'MixMonitor' on 'Local/5710@from-sip-928e,2' [Sep 14 09:34:49] DEBUG[23096]: channel.c:1436 queue_frame_to_spies: Triggering queue flush for spy 'MixMonitor' on 'Local/5710@from-sip-928e,2' [Sep 14 09:34:49] DEBUG[23096]: rtp.c:801 ast_rtcp_read: Got RTCP report of 132 bytes foxtrot*CLI> <-- SIP read from 192.168.0.12:33918: SIP/2.0 200 OK Via: SIP/2.0/UDP 90.0.0.62:5060;branch=z9hG4bK7eb692df;rport=5060 Contact: To: ;tag=4261f323 From: "5706";tag=as4b6fea46 Call-ID: 7b8bb499037201f0301f283665868c49@90.0.0.62 CSeq: 102 INVITE Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO Content-Type: application/sdp User-Agent: X-Lite release 1002tx stamp 29712 Content-Length: 265 v=0 o=- 6 2 IN IP4 192.168.0.12 s= c=IN IP4 192.168.0.12 t=0 0 m=audio 20328 RTP/AVP 0 97 101 a=fmtp:101 0-15 a=rtpmap:97 iLBC/8000 a=rtpmap:101 telephone-event/8000 a=sendrecv a=x-rtp-session-id:905AA952ED9F40FDBABEBC4270EA908F [Sep 14 09:34:49] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 0: SIP/2.0 200 OK (14) [Sep 14 09:34:49] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 1: Via: SIP/2.0/UDP 90.0.0.62:5060;branch=z9hG4bK7eb692df;rport=5060 (65) [Sep 14 09:34:49] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 2: Contact: (65) [Sep 14 09:34:49] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 3: To: ;tag=4261f323 (73) [Sep 14 09:34:49] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 4: From: "5706";tag=as4b6fea46 (56) [Sep 14 09:34:49] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 5: Call-ID: 7b8bb499037201f0301f283665868c49@90.0.0.62 (51) [Sep 14 09:34:49] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 6: CSeq: 102 INVITE (16) [Sep 14 09:34:49] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 7: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO (81) [Sep 14 09:34:49] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 8: Content-Type: application/sdp (29) [Sep 14 09:34:49] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 9: User-Agent: X-Lite release 1002tx stamp 29712 (45) [Sep 14 09:34:49] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 10: Content-Length: 265 (19) [Sep 14 09:34:49] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 11: (0) [Sep 14 09:34:49] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: v=0 (3) [Sep 14 09:34:49] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: o=- 6 2 IN IP4 192.168.0.12 (27) [Sep 14 09:34:49] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: s= (27) [Sep 14 09:34:49] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: c=IN IP4 192.168.0.12 (21) [Sep 14 09:34:49] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: t=0 0 (5) [Sep 14 09:34:49] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: m=audio 20328 RTP/AVP 0 97 101 (30) [Sep 14 09:34:49] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: a=fmtp:101 0-15 (15) [Sep 14 09:34:49] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: a=rtpmap:97 iLBC/8000 (21) [Sep 14 09:34:49] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Sep 14 09:34:49] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: a=sendrecv (10) [Sep 14 09:34:49] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: a=x-rtp-session-id:905AA952ED9F40FDBABEBC4270EA908F (51) --- (11 headers 11 lines)--- [Sep 14 09:34:49] DEBUG[15727]: chan_sip.c:1994 __sip_ack: Acked pending invite 102 [Sep 14 09:34:49] DEBUG[15727]: chan_sip.c:2012 __sip_ack: Stopping retransmission on '7b8bb499037201f0301f283665868c49@90.0.0.62' of Request 102: Match Not Found [Sep 14 09:34:49] DEBUG[15727]: chan_sip.c:11221 handle_response_invite: SIP response 200 to standard invite Found RTP audio format 0 Found RTP audio format 97 Found RTP audio format 101 Peer audio RTP is at port 192.168.0.12:20328 Got unsupported a:fmtp in SDP offer Found description format iLBC for ID 97 Found description format telephone-event for ID 101 [Sep 14 09:34:49] DEBUG[15727]: chan_sip.c:4877 process_sdp: T38 state changed to 0 on channel SIP/5710-09544fe8 Capabilities: us - 0x404 (ulaw|ilbc), peer - audio=0x404 (ulaw|ilbc)/video=0x0 (nothing), combined - 0x404 (ulaw|ilbc) Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) Peer audio RTP is at port 192.168.0.12:20328 [Sep 14 09:34:49] DEBUG[15727]: chan_sip.c:4947 process_sdp: We're settling with these formats: 0x404 (ulaw|ilbc) [Sep 14 09:34:49] DEBUG[15727]: chan_sip.c:4954 process_sdp: We have an owner, now see if we need to change this call [Sep 14 09:34:49] DEBUG[15727]: chan_sip.c:2879 update_call_counter: Updating call counter for outgoing call [Sep 14 09:34:49] DEBUG[15727]: chan_sip.c:7631 build_route: build_route: Contact hop: list_route: hop: [Sep 14 09:34:49] DEBUG[15727]: chan_sip.c:5378 reqprep: Strict routing enforced for session 7b8bb499037201f0301f283665868c49@90.0.0.62 set_destination: Parsing for address/port to send to set_destination: set destination to 192.168.0.12, port 33918 Transmitting (no NAT) to 192.168.0.12:33918: ACK sip:5710@192.168.0.12:33918;rinstance=e4acfadb594edd00 SIP/2.0 Via: SIP/2.0/UDP 90.0.0.62:5060;branch=z9hG4bK0a9485ff;rport From: "5706" ;tag=as4b6fea46 To: ;tag=4261f323 Contact: Call-ID: 7b8bb499037201f0301f283665868c49@90.0.0.62 CSeq: 102 ACK User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- [Sep 14 09:34:49] DEBUG[23096]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/5710-09544fe8 -- SIP/5710-09544fe8 answered Local/5710@from-sip-928e,2 [Sep 14 09:34:49] DEBUG[23096]: rtp.c:1401 ast_rtp_early_bridge: Channel 'Local/5710@from-sip-928e,2' has no RTP, not doing anything [Sep 14 09:34:49] DEBUG[23092]: channel.c:3618 ast_generic_bridge: Got a FRAME_CONTROL (-1) frame on channel Local/5710@from-sip-928e,1 [Sep 14 09:34:49] DEBUG[23092]: channel.c:3895 ast_channel_bridge: Bridge stops bridging channels SIP/5706-09541108 and Local/5710@from-sip-928e,1 [Sep 14 09:34:49] DEBUG[23092]: channel.c:2638 set_format: Set channel SIP/5706-09541108 to write format ulaw [Sep 14 09:34:49] DEBUG[23092]: channel.c:1845 ast_settimeout: Scheduling timer at 0 sample intervals [Sep 14 09:34:49] DEBUG[15718]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5710 [Sep 14 09:34:49] DEBUG[15718]: chan_sip.c:14652 sip_devicestate: Checking device state for peer 5710 [Sep 14 09:34:49] DEBUG[15718]: devicestate.c:287 do_state_change: Changing state for SIP/5710 - state 1 (Not in use) [Sep 14 09:34:49] DEBUG[23101]: app_queue.c:535 changethread: Device 'SIP/5710' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Sep 14 09:34:49] DEBUG[23096]: rtp.c:2518 ast_rtp_write: Ooh, format changed from unknown to ulaw [Sep 14 09:34:49] DEBUG[23096]: channel.c:1381 queue_frame_to_spies: Building translator from ulaw to SLINEAR for spies on channel Local/5710@from-sip-928e,2 [Sep 14 09:34:52] DEBUG[23096]: rtp.c:801 ast_rtcp_read: Got RTCP report of 176 bytes [Sep 14 09:34:55] DEBUG[23096]: rtp.c:801 ast_rtcp_read: Got RTCP report of 176 bytes foxtrot*CLI> <-- SIP read from 192.168.0.200:50628: INVITE sip:5709@90.0.0.62:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.0.200:5060;branch=z9hG4bK4addaddd From: "5706" ;tag=000785993d3d0036156163f1-07501bb1 To: ;tag=as52f5986f Call-ID: 00078599-3d3d001d-129a6fe0-34d614d5@192.168.0.200 Date: Thu, 14 Sep 2006 08:34:55 GMT CSeq: 103 INVITE User-Agent: CSCO/7 Contact: Content-Type: application/sdp Content-Length: 239 Remote-Party-ID: "5706" ;party=calling;id-type=subscriber;privacy=off;screen=no Proxy-Authorization: Digest username="5706",realm="asterisk",uri="sip:90.0.0.62",response="936cf75f69b6c64b3d725b6255417ef8",nonce="64128275",algorithm=MD5 v=0 o=Cisco-SIPUA 80 1122 IN IP4 192.168.0.200 s=SIP Call c=IN IP4 0.0.0.0 t=0 0 m=audio 23922 RTP/AVP 0 8 18 101 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:18 G729/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 0: INVITE sip:5709@90.0.0.62:5060 SIP/2.0 (38) [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.0.200:5060;branch=z9hG4bK4addaddd (58) [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 2: From: "5706" ;tag=000785993d3d0036156163f1-07501bb1 (71) [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 3: To: ;tag=as52f5986f (39) [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 4: Call-ID: 00078599-3d3d001d-129a6fe0-34d614d5@192.168.0.200 (58) [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 5: Date: Thu, 14 Sep 2006 08:34:55 GMT (35) [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 6: CSeq: 103 INVITE (16) [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 7: User-Agent: CSCO/7 (18) [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 8: Contact: (38) [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 9: Content-Type: application/sdp (29) [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 10: Content-Length: 239 (19) [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 11: Remote-Party-ID: "5706" ;party=calling;id-type=subscriber;privacy=off;screen=no (103) [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 12: Proxy-Authorization: Digest username="5706",realm="asterisk",uri="sip:90.0.0.62",response="936cf75f69b6c64b3d725b6255417ef8",nonce="64128275",algorithm=MD5 (155) [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 13: (0) [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: v=0 (3) [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: o=Cisco-SIPUA 80 1122 IN IP4 192.168.0.200 (42) [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: s=SIP Call (10) [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: c=IN IP4 0.0.0.0 (16) [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: t=0 0 (5) [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: m=audio 23922 RTP/AVP 0 8 18 101 (32) [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: a=rtpmap:18 G729/8000 (21) [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: a=fmtp:101 0-15 (15) --- (13 headers 11 lines)--- [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:14065 handle_request: **** Received INVITE (5) - Command in SIP INVITE Sending to 192.168.0.200 : 5060 (no NAT) Found RTP audio format 0 Found RTP audio format 8 Found RTP audio format 18 Found RTP audio format 101 Peer audio RTP is at port 0.0.0.0:23922 Found description format PCMU for ID 0 Found description format PCMA for ID 8 Found description format G729 for ID 18 Found description format telephone-event for ID 101 Got unsupported a:fmtp in SDP offer [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:4877 process_sdp: T38 state changed to 0 on channel SIP/5706-09541108 Capabilities: us - 0x404 (ulaw|ilbc), peer - audio=0x10c (ulaw|alaw|g729)/video=0x0 (nothing), combined - 0x4 (ulaw) Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) Peer audio RTP is at port 0.0.0.0:23922 [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:4947 process_sdp: We're settling with these formats: 0x4 (ulaw) [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:4954 process_sdp: We have an owner, now see if we need to change this call [Sep 14 09:34:57] DEBUG[15727]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/5706 [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:12921 handle_request_invite: Got a SIP re-invite for call 00078599-3d3d001d-129a6fe0-34d614d5@192.168.0.200 [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:13010 handle_request_invite: SIP/5706-09541108: This call is UP.... [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:5847 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:5848 add_sdp: ** Our prefcodec: 0x0 (nothing) Audio is at 90.0.0.62 port 16170 Adding codec 0x4 (ulaw) to SDP Adding non-codec 0x1 (telephone-event) to SDP [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:6000 add_sdp: -- Done with adding codecs to SDP [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:6039 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw) Reliably Transmitting (no NAT) to 192.168.0.200:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.0.200:5060;branch=z9hG4bK4addaddd;received=192.168.0.200 From: "5706" ;tag=000785993d3d0036156163f1-07501bb1 To: ;tag=as52f5986f Call-ID: 00078599-3d3d001d-129a6fe0-34d614d5@192.168.0.200 CSeq: 103 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 222 v=0 o=root 15662 15663 IN IP4 90.0.0.62 s=session c=IN IP4 90.0.0.62 t=0 0 m=audio 16170 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=sendrecv --- [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:1909 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #1974 -- Started music on hold, class 'default', on SIP/5710-09544fe8 [Sep 14 09:34:57] DEBUG[23096]: channel.c:1845 ast_settimeout: Scheduling timer at 160 sample intervals [Sep 14 09:34:57] DEBUG[15718]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5706 [Sep 14 09:34:57] DEBUG[15718]: chan_sip.c:14652 sip_devicestate: Checking device state for peer 5706 [Sep 14 09:34:57] DEBUG[15718]: devicestate.c:287 do_state_change: Changing state for SIP/5706 - state 8 (On Hold) [Sep 14 09:34:57] DEBUG[23102]: app_queue.c:535 changethread: Device 'SIP/5706' changed to state '8' (On Hold) but we don't care because they're not a member of any queue. [Sep 14 09:34:57] DEBUG[23096]: channel.c:2162 __ast_read: Generator got voice, switching to phase locked mode [Sep 14 09:34:57] DEBUG[23096]: channel.c:1845 ast_settimeout: Scheduling timer at 0 sample intervals [Sep 14 09:34:57] DEBUG[23096]: res_musiconhold.c:252 ast_moh_files_next: SIP/5710-09544fe8 Opened file 8 '/var/lib/asterisk/sounds/custom/moh/track12' [Sep 14 09:34:57] DEBUG[23096]: rtp.c:2417 ast_rtp_raw_write: Difference is 896, ms is 132 foxtrot*CLI> <-- SIP read from 192.168.0.200:50628: ACK sip:5709@90.0.0.62:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.0.200:5060;branch=z9hG4bK687c6b05 From: "5706" ;tag=000785993d3d0036156163f1-07501bb1 To: ;tag=as52f5986f Call-ID: 00078599-3d3d001d-129a6fe0-34d614d5@192.168.0.200 Date: Thu, 14 Sep 2006 08:34:55 GMT CSeq: 103 ACK User-Agent: CSCO/7 Proxy-Authorization: Digest username="5706",realm="asterisk",uri="sip:90.0.0.62",response="936cf75f69b6c64b3d725b6255417ef8",nonce="64128275",algorithm=MD5 Content-Length: 0 [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 0: ACK sip:5709@90.0.0.62:5060 SIP/2.0 (35) [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.0.200:5060;branch=z9hG4bK687c6b05 (58) [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 2: From: "5706" ;tag=000785993d3d0036156163f1-07501bb1 (71) [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 3: To: ;tag=as52f5986f (39) [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 4: Call-ID: 00078599-3d3d001d-129a6fe0-34d614d5@192.168.0.200 (58) [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 5: Date: Thu, 14 Sep 2006 08:34:55 GMT (35) [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 6: CSeq: 103 ACK (13) [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 7: User-Agent: CSCO/7 (18) [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 8: Proxy-Authorization: Digest username="5706",realm="asterisk",uri="sip:90.0.0.62",response="936cf75f69b6c64b3d725b6255417ef8",nonce="64128275",algorithm=MD5 (155) [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 9: Content-Length: 0 (17) [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 10: (0) --- (10 headers 0 lines)--- [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:14065 handle_request: **** Received ACK (6) - Command in SIP ACK [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:2002 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #1974 [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:2012 __sip_ack: Stopping retransmission on '00078599-3d3d001d-129a6fe0-34d614d5@192.168.0.200' of Response 103: Match Not Found foxtrot*CLI> <-- SIP read from 192.168.0.200:50628: REFER sip:07803034440@90.0.0.62:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.0.200:5060;branch=z9hG4bK13d18cae From: ;tag=000785993d3d00351b424905-04a45e44 To: "07803034440" ;tag=as7d0cfcef Call-ID: 660ba5b156e7b87838cb44e973401a18@90.0.0.62 Date: Thu, 14 Sep 2006 08:34:56 GMT CSeq: 102 REFER User-Agent: CSCO/7 Contact: Content-Length: 0 Remote-Party-ID: "5706" ;party=calling;id-type=subscriber;privacy=off;screen=no Refer-To: Referred-By: [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 0: REFER sip:07803034440@90.0.0.62:5060 SIP/2.0 (44) [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.0.200:5060;branch=z9hG4bK13d18cae (58) [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 2: From: ;tag=000785993d3d00351b424905-04a45e44 (73) [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 3: To: "07803034440" ;tag=as7d0cfcef (60) [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 4: Call-ID: 660ba5b156e7b87838cb44e973401a18@90.0.0.62 (51) [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 5: Date: Thu, 14 Sep 2006 08:34:56 GMT (35) [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 6: CSeq: 102 REFER (15) [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 7: User-Agent: CSCO/7 (18) [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 8: Contact: (38) [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 9: Content-Length: 0 (17) [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 10: Remote-Party-ID: "5706" ;party=calling;id-type=subscriber;privacy=off;screen=no (103) [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 11: Refer-To: (165) [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 12: Referred-By: (42) [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 13: (0) --- (13 headers 0 lines)--- [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:14065 handle_request: **** Received REFER (9) - Command in SIP REFER Call 660ba5b156e7b87838cb44e973401a18@90.0.0.62 got a SIP call transfer from callee: (REFER)! [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:8350 get_refer_info: Attended transfer: Will use Replace-Call-ID : 00078599-3d3d001d-129a6fe0-34d614d5@192.168.0.200 (No check of from/to tags) SIP transfer to extension 5709@from-sip by 5706@192.168.0.200:5060 [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:13411 handle_request_refer: SIP attended transfer: Transferer channel SIP/5706-0951ae00, transferee channel Zap/1-1 [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:13427 handle_request_refer: Got SIP transfer, applying to bridged peer 'Zap/1-1' [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:8206 get_sip_pvt_byid_locked: Looking for callid 00078599-3d3d001d-129a6fe0-34d614d5@192.168.0.200 (fromtag 000785993d3d0036156163f1-07501bb1 totag as52f5986f) [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:8230 get_sip_pvt_byid_locked: Matched INCOMING call - their tag is 000785993d3d0036156163f1-07501bb1 Our tag is as52f5986f Transmitting (no NAT) to 192.168.0.200:5060: SIP/2.0 202 Accepted Via: SIP/2.0/UDP 192.168.0.200:5060;branch=z9hG4bK13d18cae;received=192.168.0.200 From: ;tag=000785993d3d00351b424905-04a45e44 To: "07803034440" ;tag=as7d0cfcef Call-ID: 660ba5b156e7b87838cb44e973401a18@90.0.0.62 CSeq: 102 REFER User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 --- [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:13183 local_attended_transfer: SIP attended transfer: trying to bridge SIP/5706-09541108 and Zap/1-1 [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:12223 attempt_transfer: Sip transfer:-------------------- [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:12225 attempt_transfer: -- Transferer to PBX channel: SIP/5706-0951ae00 State Up [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:12229 attempt_transfer: -- Transferer to PBX second channel (target): SIP/5706-09541108 State Up [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:12233 attempt_transfer: -- Bridged call to transferee: Zap/1-1 State Up [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:12237 attempt_transfer: -- Bridged call to transfer target: Local/5710@from-sip-928e,1 State Up [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:12240 attempt_transfer: -- END Sip transfer:-------------------- [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:12248 attempt_transfer: SIP transfer: Four channels to handle -- Stopped music on hold on Zap/1-1 [Sep 14 09:34:57] DEBUG[15727]: channel.c:2638 set_format: Set channel Zap/1-1 to write format alaw [Sep 14 09:34:57] DEBUG[15727]: channel.c:1845 ast_settimeout: Scheduling timer at 0 sample intervals [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:12279 attempt_transfer: SIP transfer: trying to masquerade Zap/1-1 into SIP/5706-09541108 [Sep 14 09:34:57] DEBUG[15727]: channel.c:3037 ast_channel_masquerade: Planning to masquerade channel Zap/1-1 into the structure of SIP/5706-09541108 [Sep 14 09:34:57] DEBUG[15727]: channel.c:3050 ast_channel_masquerade: Done planning to masquerade channel Zap/1-1 into the structure of SIP/5706-09541108 [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:12284 attempt_transfer: SIP transfer: Succeeded to masquerade channels. [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:5378 reqprep: Strict routing enforced for session 660ba5b156e7b87838cb44e973401a18@90.0.0.62 set_destination: Parsing for address/port to send to set_destination: set destination to 192.168.0.200, port 5060 Reliably Transmitting (no NAT) to 192.168.0.200:5060: NOTIFY sip:5706@192.168.0.200:5060 SIP/2.0 Via: SIP/2.0/UDP 90.0.0.62:5060;branch=z9hG4bK1b14b285;rport From: "07803034440" ;tag=as7d0cfcef To: ;tag=000785993d3d00351b424905-04a45e44 Contact: Call-ID: 660ba5b156e7b87838cb44e973401a18@90.0.0.62 CSeq: 103 NOTIFY User-Agent: Asterisk PBX Max-Forwards: 70 Event: refer;id=102 Subscription-state: terminated;reason=noresource Content-Type: message/sipfrag;version=2.0 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 16 SIP/2.0 200 OK --- [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:1909 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #1975 [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:13210 local_attended_transfer: SIP attended transfer: Unlocking channel SIP/5706-09541108 [Sep 14 09:34:57] DEBUG[23084]: chan_zap.c:4976 zt_indicate: Requested indication 17 on channel Zap/1-1 [Sep 14 09:34:57] DEBUG[23092]: channel.c:3167 ast_do_masquerade: Actually Masquerading Zap/1-1(6) into the structure of SIP/5706-09541108(6) [Sep 14 09:34:57] DEBUG[23092]: channel.c:3179 ast_do_masquerade: Got clone lock for masquerade on 'Zap/1-1' at 0x94b6e40 [Sep 14 09:34:57] DEBUG[23092]: chan_sip.c:3452 sip_fixup: SIP Fixup: New owner for dialogue 00078599-3d3d001d-129a6fe0-34d614d5@192.168.0.200: Zap/1-1 (Old parent: Zap/1-1) [Sep 14 09:34:57] DEBUG[23092]: chan_sip.c:3180 sip_hangup: Hangup call Zap/1-1, SIP callid 00078599-3d3d001d-129a6fe0-34d614d5@192.168.0.200) [Sep 14 09:34:57] DEBUG[23092]: chan_sip.c:3188 sip_hangup: update_call_counter(5706) - decrement call limit counter on hangup [Sep 14 09:34:57] DEBUG[23092]: chan_sip.c:2879 update_call_counter: Updating call counter for incoming call Scheduling destruction of SIP dialog '00078599-3d3d001d-129a6fe0-34d614d5@192.168.0.200' in 32000 ms (Method: ACK) [Sep 14 09:34:57] DEBUG[23092]: chan_sip.c:5378 reqprep: Strict routing enforced for session 00078599-3d3d001d-129a6fe0-34d614d5@192.168.0.200 set_destination: Parsing for address/port to send to set_destination: set destination to 192.168.0.200, port 5060 Reliably Transmitting (no NAT) to 192.168.0.200:5060: BYE sip:5706@192.168.0.200:5060 SIP/2.0 Via: SIP/2.0/UDP 90.0.0.62:5060;branch=z9hG4bK77df1b38;rport From: ;tag=as52f5986f To: "5706" ;tag=000785993d3d0036156163f1-07501bb1 Contact: Call-ID: 00078599-3d3d001d-129a6fe0-34d614d5@192.168.0.200 CSeq: 102 BYE User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- [Sep 14 09:34:57] DEBUG[23092]: chan_sip.c:1909 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #1977 [Sep 14 09:34:57] DEBUG[23092]: channel.c:2638 set_format: Set channel Zap/1-1 to write format ulaw [Sep 14 09:34:57] DEBUG[23092]: channel.c:2638 set_format: Set channel Zap/1-1 to read format ulaw [Sep 14 09:34:57] DEBUG[23092]: channel.c:3374 ast_do_masquerade: Putting channel Zap/1-1 in 4/4 formats [Sep 14 09:34:57] DEBUG[23092]: chan_zap.c:3425 zt_fixup: New owner for channel 1 is Zap/1-1 [Sep 14 09:34:57] DEBUG[23092]: chan_zap.c:1424 update_conf: Updated conferencing on 1, with 0 conference users [Sep 14 09:34:57] DEBUG[23092]: chan_zap.c:1424 update_conf: Updated conferencing on 1, with 0 conference users [Sep 14 09:34:57] DEBUG[23092]: channel.c:3409 ast_do_masquerade: Released clone lock on 'SIP/5706-09541108' [Sep 14 09:34:57] DEBUG[23092]: channel.c:3419 ast_do_masquerade: Done Masquerading Zap/1-1 (6) [Sep 14 09:34:57] DEBUG[23084]: channel.c:3596 ast_generic_bridge: Didn't get a frame from channel: SIP/5706-09541108 [Sep 14 09:34:57] DEBUG[23084]: channel.c:3895 ast_channel_bridge: Bridge stops bridging channels SIP/5706-09541108 and SIP/5706-0951ae00 [Sep 14 09:34:57] DEBUG[23084]: channel.c:1543 ast_hangup: Hanging up channel 'SIP/5706-0951ae00' [Sep 14 09:34:57] DEBUG[23084]: chan_sip.c:3166 sip_hangup: SIP Transfer: Not hanging up right now... Rescheduling hangup for 660ba5b156e7b87838cb44e973401a18@90.0.0.62. Scheduling destruction of SIP dialog '660ba5b156e7b87838cb44e973401a18@90.0.0.62' in 32000 ms (Method: REFER) [Sep 14 09:34:57] DEBUG[23084]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/5706-0951ae00 [Sep 14 09:34:57] DEBUG[23084]: rtp.c:1409 ast_rtp_early_bridge: Channel '' has no RTP, not doing anything [Sep 14 09:34:57] DEBUG[15718]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5706 [Sep 14 09:34:57] DEBUG[23084]: app_dial.c:1631 dial_exec_full: Exiting with DIALSTATUS=ANSWER. [Sep 14 09:34:57] DEBUG[23092]: channel.c:2638 set_format: Set channel Local/5710@from-sip-928e,1 to read format alaw [Sep 14 09:34:57] DEBUG[15718]: chan_sip.c:14652 sip_devicestate: Checking device state for peer 5706 [Sep 14 09:34:57] DEBUG[23084]: pbx.c:2280 __ast_pbx_run: Spawn extension (isdn10,444606,3) exited non-zero on 'SIP/5706-09541108' [Sep 14 09:34:57] DEBUG[23092]: channel.c:2638 set_format: Set channel Zap/1-1 to write format alaw [Sep 14 09:34:57] DEBUG[23084]: channel.c:1548 ast_hangup: Hanging up zombie 'SIP/5706-09541108' [Sep 14 09:34:57] DEBUG[15718]: devicestate.c:287 do_state_change: Changing state for SIP/5706 - state 8 (On Hold) [Sep 14 09:34:57] DEBUG[23084]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/5706-09541108 [Sep 14 09:34:57] DEBUG[23103]: app_queue.c:535 changethread: Device 'SIP/5706' changed to state '8' (On Hold) but we don't care because they're not a member of any queue. [Sep 14 09:34:57] DEBUG[15718]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5706 [Sep 14 09:34:57] DEBUG[15718]: chan_sip.c:14652 sip_devicestate: Checking device state for peer 5706 [Sep 14 09:34:57] DEBUG[15718]: devicestate.c:287 do_state_change: Changing state for SIP/5706 - state 8 (On Hold) [Sep 14 09:34:57] DEBUG[23104]: app_queue.c:535 changethread: Device 'SIP/5706' changed to state '8' (On Hold) but we don't care because they're not a member of any queue. [Sep 14 09:34:57] DEBUG[23092]: chan_zap.c:4871 my_zt_write: Write returned -1 (Resource temporarily unavailable) on channel 1 foxtrot*CLI> <-- SIP read from 192.168.0.200:50637: SIP/2.0 200 OK Via: SIP/2.0/UDP 90.0.0.62:5060;branch=z9hG4bK1b14b285;rport From: "07803034440" ;tag=as7d0cfcef To: ;tag=000785993d3d00351b424905-04a45e44 Call-ID: 660ba5b156e7b87838cb44e973401a18@90.0.0.62 Date: Thu, 14 Sep 2006 08:34:56 GMT CSeq: 103 NOTIFY Content-Length: 0 [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 0: SIP/2.0 200 OK (14) [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 1: Via: SIP/2.0/UDP 90.0.0.62:5060;branch=z9hG4bK1b14b285;rport (60) [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 2: From: "07803034440" ;tag=as7d0cfcef (62) [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 3: To: ;tag=000785993d3d00351b424905-04a45e44 (71) [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 4: Call-ID: 660ba5b156e7b87838cb44e973401a18@90.0.0.62 (51) [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 5: Date: Thu, 14 Sep 2006 08:34:56 GMT (35) [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 6: CSeq: 103 NOTIFY (16) [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 7: Content-Length: 0 (17) [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 8: (0) --- (8 headers 0 lines)--- [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:2002 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #1975 [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:2012 __sip_ack: Stopping retransmission on '660ba5b156e7b87838cb44e973401a18@90.0.0.62' of Request 103: Match Not Found Really destroying SIP dialog '660ba5b156e7b87838cb44e973401a18@90.0.0.62' Method: REFER foxtrot*CLI> <-- SIP read from 192.168.0.200:50628: SIP/2.0 200 OK Via: SIP/2.0/UDP 90.0.0.62:5060;branch=z9hG4bK77df1b38;rport From: ;tag=as52f5986f To: "5706" ;tag=000785993d3d0036156163f1-07501bb1 Call-ID: 00078599-3d3d001d-129a6fe0-34d614d5@192.168.0.200 Date: Thu, 14 Sep 2006 08:34:56 GMT CSeq: 102 BYE Server: CSCO/7 Content-Length: 0 [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 0: SIP/2.0 200 OK (14) [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 1: Via: SIP/2.0/UDP 90.0.0.62:5060;branch=z9hG4bK77df1b38;rport (60) [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 2: From: ;tag=as52f5986f (41) [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 3: To: "5706" ;tag=000785993d3d0036156163f1-07501bb1 (69) [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 4: Call-ID: 00078599-3d3d001d-129a6fe0-34d614d5@192.168.0.200 (58) [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 5: Date: Thu, 14 Sep 2006 08:34:56 GMT (35) [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 6: CSeq: 102 BYE (13) [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 7: Server: CSCO/7 (14) [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 8: Content-Length: 0 (17) [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 9: (0) --- (9 headers 0 lines)--- [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:2002 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #1977 [Sep 14 09:34:57] DEBUG[15727]: chan_sip.c:2012 __sip_ack: Stopping retransmission on '00078599-3d3d001d-129a6fe0-34d614d5@192.168.0.200' of Request 102: Match Not Found SIP Response message for INCOMING dialog BYE arrived Really destroying SIP dialog '00078599-3d3d001d-129a6fe0-34d614d5@192.168.0.200' Method: ACK foxtrot*CLI> <-- SIP read from 192.168.0.200:50628: BYE sip:07803034440@90.0.0.62:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.0.200:5060;branch=z9hG4bK55c80e1f From: ;tag=000785993d3d00351b424905-04a45e44 To: "07803034440" ;tag=as7d0cfcef Call-ID: 660ba5b156e7b87838cb44e973401a18@90.0.0.62 Date: Thu, 14 Sep 2006 08:34:56 GMT CSeq: 103 BYE User-Agent: CSCO/7 Content-Length: 0 [Sep 14 09:34:58] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 0: BYE sip:07803034440@90.0.0.62:5060 SIP/2.0 (42) [Sep 14 09:34:58] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.0.200:5060;branch=z9hG4bK55c80e1f (58) [Sep 14 09:34:58] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 2: From: ;tag=000785993d3d00351b424905-04a45e44 (73) [Sep 14 09:34:58] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 3: To: "07803034440" ;tag=as7d0cfcef (60) [Sep 14 09:34:58] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 4: Call-ID: 660ba5b156e7b87838cb44e973401a18@90.0.0.62 (51) [Sep 14 09:34:58] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 5: Date: Thu, 14 Sep 2006 08:34:56 GMT (35) [Sep 14 09:34:58] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 6: CSeq: 103 BYE (13) [Sep 14 09:34:58] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 7: User-Agent: CSCO/7 (18) [Sep 14 09:34:58] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 8: Content-Length: 0 (17) [Sep 14 09:34:58] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 9: (0) --- (9 headers 0 lines)--- [Sep 14 09:34:58] DEBUG[15727]: chan_sip.c:4152 sip_alloc: Allocating new SIP dialog for 660ba5b156e7b87838cb44e973401a18@90.0.0.62 - BYE (No RTP) [Sep 14 09:34:58] DEBUG[15727]: chan_sip.c:14065 handle_request: **** Received BYE (8) - Command in SIP BYE Sending to 192.168.0.200 : 5060 (no NAT) Scheduling destruction of SIP dialog '660ba5b156e7b87838cb44e973401a18@90.0.0.62' in 32000 ms (Method: BYE) [Sep 14 09:34:58] DEBUG[15727]: chan_sip.c:13674 handle_request_bye: Received bye, no owner, selfdestruct soon. .Transmitting (no NAT) to 192.168.0.200:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.0.200:5060;branch=z9hG4bK55c80e1f;received=192.168.0.200 From: ;tag=000785993d3d00351b424905-04a45e44 To: "07803034440" ;tag=as7d0cfcef Call-ID: 660ba5b156e7b87838cb44e973401a18@90.0.0.62 CSeq: 103 BYE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 --- foxtrot*CLI> <-- SIP read from 192.168.0.12:33918: [Sep 14 09:34:58] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 0: (0) [Sep 14 09:34:58] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: (0) --- (0 headers 1 lines)--- [Sep 14 09:34:58] DEBUG[23092]: chan_zap.c:4871 my_zt_write: Write returned -1 (Resource temporarily unavailable) on channel 1 [Sep 14 09:34:58] DEBUG[23092]: chan_zap.c:4871 my_zt_write: Write returned -1 (Resource temporarily unavailable) on channel 1 [Sep 14 09:34:58] DEBUG[23096]: rtp.c:801 ast_rtcp_read: Got RTCP report of 176 bytes [Sep 14 09:35:01] DEBUG[23096]: rtp.c:801 ast_rtcp_read: Got RTCP report of 176 bytes [Sep 14 09:35:05] DEBUG[23096]: rtp.c:801 ast_rtcp_read: Got RTCP report of 176 bytes [Sep 14 09:35:07] DEBUG[23096]: rtp.c:801 ast_rtcp_read: Got RTCP report of 160 bytes [Sep 14 09:35:08] DEBUG[23092]: channel.c:1436 queue_frame_to_spies: Triggering queue flush for spy 'MixMonitor' on 'Zap/1-1' foxtrot*CLI> <-- SIP read from 192.168.0.12:33918: BYE sip:Extension5706@90.0.0.62 SIP/2.0 Via: SIP/2.0/UDP 192.168.0.12:33918;branch=z9hG4bK-d87543-3a22833e3d7a3a46-1--d87543-;rport Max-Forwards: 70 Contact: To: "5706";tag=as4b6fea46 From: ;tag=4261f323 Call-ID: 7b8bb499037201f0301f283665868c49@90.0.0.62 CSeq: 2 BYE User-Agent: X-Lite release 1002tx stamp 29712 Reason: SIP;description="User Hung Up" Content-Length: 0 [Sep 14 09:35:08] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 0: BYE sip:Extension5706@90.0.0.62 SIP/2.0 (39) [Sep 14 09:35:08] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.0.12:33918;branch=z9hG4bK-d87543-3a22833e3d7a3a46-1--d87543-;rport (91) [Sep 14 09:35:08] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 2: Max-Forwards: 70 (16) [Sep 14 09:35:08] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 3: Contact: (65) [Sep 14 09:35:08] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 4: To: "5706";tag=as4b6fea46 (54) [Sep 14 09:35:08] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 5: From: ;tag=4261f323 (75) [Sep 14 09:35:08] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 6: Call-ID: 7b8bb499037201f0301f283665868c49@90.0.0.62 (51) [Sep 14 09:35:08] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 7: CSeq: 2 BYE (11) [Sep 14 09:35:08] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 8: User-Agent: X-Lite release 1002tx stamp 29712 (45) [Sep 14 09:35:08] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 9: Reason: SIP;description="User Hung Up" (38) [Sep 14 09:35:08] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 10: Content-Length: 0 (17) [Sep 14 09:35:08] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 11: (0) --- (11 headers 0 lines)--- [Sep 14 09:35:08] DEBUG[15727]: chan_sip.c:14065 handle_request: **** Received BYE (8) - Command in SIP BYE Sending to 192.168.0.12 : 33918 (NAT) [Sep 14 09:35:08] DEBUG[15727]: chan_sip.c:13670 handle_request_bye: Received bye, issuing owner hangup .Transmitting (NAT) to 192.168.0.12:33918: SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.0.12:33918;branch=z9hG4bK-d87543-3a22833e3d7a3a46-1--d87543-;received=192.168.0.12;rport=33918 From: ;tag=4261f323 To: "5706";tag=as4b6fea46 Call-ID: 7b8bb499037201f0301f283665868c49@90.0.0.62 CSeq: 2 BYE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 --- -- Stopped music on hold on SIP/5710-09544fe8 [Sep 14 09:35:08] DEBUG[23096]: channel.c:1845 ast_settimeout: Scheduling timer at 0 sample intervals [Sep 14 09:35:08] DEBUG[23096]: channel.c:3596 ast_generic_bridge: Didn't get a frame from channel: SIP/5710-09544fe8 [Sep 14 09:35:08] DEBUG[23096]: channel.c:3895 ast_channel_bridge: Bridge stops bridging channels Local/5710@from-sip-928e,2 and SIP/5710-09544fe8 [Sep 14 09:35:08] DEBUG[23096]: channel.c:1543 ast_hangup: Hanging up channel 'SIP/5710-09544fe8' [Sep 14 09:35:08] DEBUG[23096]: chan_sip.c:3180 sip_hangup: Hangup call SIP/5710-09544fe8, SIP callid 7b8bb499037201f0301f283665868c49@90.0.0.62) [Sep 14 09:35:08] DEBUG[23096]: chan_sip.c:3188 sip_hangup: update_call_counter(5710) - decrement call limit counter on hangup [Sep 14 09:35:08] DEBUG[23096]: chan_sip.c:2879 update_call_counter: Updating call counter for outgoing call [Sep 14 09:35:08] DEBUG[23096]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/5710-09544fe8 [Sep 14 09:35:08] DEBUG[23096]: rtp.c:1401 ast_rtp_early_bridge: Channel 'Local/5710@from-sip-928e,2' has no RTP, not doing anything [Sep 14 09:35:08] DEBUG[23096]: app_dial.c:1631 dial_exec_full: Exiting with DIALSTATUS=ANSWER. [Sep 14 09:35:08] DEBUG[23096]: pbx.c:1684 pbx_extension_helper: Launching 'Set' -- Executing [5710@from-sip:4] Set("Local/5710@from-sip-928e,2", "VMOPT=sb") in new stack [Sep 14 09:35:08] DEBUG[23096]: pbx.c:1605 pbx_substitute_variables_helper_full: Expression result is '0' [Sep 14 09:35:08] DEBUG[23096]: pbx.c:1684 pbx_extension_helper: Launching 'GotoIf' -- Executing [5710@from-sip:5] GotoIf("Local/5710@from-sip-928e,2", "0?CheckVM") in new stack [Sep 14 09:35:08] DEBUG[23096]: pbx.c:5622 pbx_builtin_gotoif: Not taking any branch [Sep 14 09:35:08] DEBUG[23096]: pbx.c:1684 pbx_extension_helper: Launching 'Set' -- Executing [5710@from-sip:6] Set("Local/5710@from-sip-928e,2", "VMOPT=su") in new stack [Sep 14 09:35:08] DEBUG[23096]: pbx.c:1605 pbx_substitute_variables_helper_full: Expression result is '0' [Sep 14 09:35:08] DEBUG[23096]: pbx.c:1684 pbx_extension_helper: Launching 'GotoIf' -- Executing [5710@from-sip:7] GotoIf("Local/5710@from-sip-928e,2", "0?CheckVM") in new stack [Sep 14 09:35:08] DEBUG[23096]: pbx.c:5622 pbx_builtin_gotoif: Not taking any branch [Sep 14 09:35:08] DEBUG[23096]: pbx.c:1684 pbx_extension_helper: Launching 'Hangup' -- Executing [5710@from-sip:8] Hangup("Local/5710@from-sip-928e,2", "") in new stack [Sep 14 09:35:08] DEBUG[23096]: pbx.c:2280 __ast_pbx_run: Spawn extension (from-sip,5710,8) exited non-zero on 'Local/5710@from-sip-928e,2' [Sep 14 09:35:08] DEBUG[23096]: pbx.c:1684 pbx_extension_helper: Launching 'NoOp' -- Executing [h@from-sip:1] NoOp("Local/5710@from-sip-928e,2", "++++ HANGUP FROM-SIP ++++ [ANSWER/16]") in new stack [Sep 14 09:35:08] DEBUG[23096]: pbx.c:1605 pbx_substitute_variables_helper_full: Expression result is '1' [Sep 14 09:35:08] DEBUG[23096]: pbx.c:1684 pbx_extension_helper: Launching 'GotoIf' -- Executing [h@from-sip:2] GotoIf("Local/5710@from-sip-928e,2", "1?end") in new stack -- Goto (from-sip,h,6) [Sep 14 09:35:08] DEBUG[23096]: pbx.c:1684 pbx_extension_helper: Launching 'NoOp' -- Executing [h@from-sip:6] NoOp("Local/5710@from-sip-928e,2", "EndOfCall") in new stack [Sep 14 09:35:08] DEBUG[23096]: channel.c:1236 spy_detach: Spy MixMonitor removed from channel Local/5710@from-sip-928e,2 == End MixMonitor Recording Local/5710@from-sip-928e,2 [Sep 14 09:35:08] DEBUG[15718]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5710 [Sep 14 09:35:08] DEBUG[15718]: chan_sip.c:14652 sip_devicestate: Checking device state for peer 5710 [Sep 14 09:35:08] DEBUG[15718]: devicestate.c:287 do_state_change: Changing state for SIP/5710 - state 1 (Not in use) [Sep 14 09:35:08] DEBUG[23112]: app_queue.c:535 changethread: Device 'SIP/5710' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Sep 14 09:35:08] DEBUG[23096]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is '"5706" ' [Sep 14 09:35:08] DEBUG[23096]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is 'Extension5706' [Sep 14 09:35:08] DEBUG[23096]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is 'h' [Sep 14 09:35:08] DEBUG[23096]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is 'from-sip' [Sep 14 09:35:08] DEBUG[23096]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is 'Local/5710@from-sip-928e,2' [Sep 14 09:35:08] DEBUG[23096]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is 'SIP/5710-09544fe8' [Sep 14 09:35:08] DEBUG[23096]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is 'NoOp' [Sep 14 09:35:08] DEBUG[23096]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is 'EndOfCall' [Sep 14 09:35:08] DEBUG[23096]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is '2006-09-14 09:34:41' [Sep 14 09:35:08] DEBUG[23096]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is '2006-09-14 09:34:41' [Sep 14 09:35:08] DEBUG[23096]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is '2006-09-14 09:35:08' [Sep 14 09:35:08] DEBUG[23096]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is '27' [Sep 14 09:35:08] DEBUG[23096]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is '27' [Sep 14 09:35:08] DEBUG[23096]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is 'ANSWERED' [Sep 14 09:35:08] DEBUG[23096]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' [Sep 14 09:35:08] DEBUG[23096]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is '' [Sep 14 09:35:08] DEBUG[23096]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is '1158222881.12' [Sep 14 09:35:08] DEBUG[23096]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is '' [Sep 14 09:35:08] DEBUG[23096]: channel.c:1543 ast_hangup: Hanging up channel 'Local/5710@from-sip-928e,2' [Sep 14 09:35:08] DEBUG[23096]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Local/5710@from-sip-928e,2 [Sep 14 09:35:08] DEBUG[23092]: channel.c:3596 ast_generic_bridge: Didn't get a frame from channel: Local/5710@from-sip-928e,1 [Sep 14 09:35:08] DEBUG[23092]: channel.c:3895 ast_channel_bridge: Bridge stops bridging channels Zap/1-1 and Local/5710@from-sip-928e,1 [Sep 14 09:35:08] DEBUG[23092]: channel.c:1543 ast_hangup: Hanging up channel 'Local/5710@from-sip-928e,1' [Sep 14 09:35:08] DEBUG[23092]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Local/5710@from-sip-928e,1 [Sep 14 09:35:08] DEBUG[23092]: rtp.c:1401 ast_rtp_early_bridge: Channel 'Zap/1-1' has no RTP, not doing anything [Sep 14 09:35:08] DEBUG[23092]: app_dial.c:1631 dial_exec_full: Exiting with DIALSTATUS=ANSWER. [Sep 14 09:35:08] DEBUG[23092]: pbx.c:2280 __ast_pbx_run: Spawn extension (from-sip,5709,2) exited non-zero on 'Zap/1-1' [Sep 14 09:35:08] DEBUG[23092]: pbx.c:1684 pbx_extension_helper: Launching 'NoOp' -- Executing [h@from-sip:1] NoOp("Zap/1-1", "++++ HANGUP FROM-SIP ++++ [ANSWER/16]") in new stack [Sep 14 09:35:08] DEBUG[23092]: pbx.c:1605 pbx_substitute_variables_helper_full: Expression result is '1' [Sep 14 09:35:08] DEBUG[23092]: pbx.c:1684 pbx_extension_helper: Launching 'GotoIf' -- Executing [h@from-sip:2] GotoIf("Zap/1-1", "1?end") in new stack -- Goto (from-sip,h,6) [Sep 14 09:35:08] DEBUG[23092]: pbx.c:1684 pbx_extension_helper: Launching 'NoOp' -- Executing [h@from-sip:6] NoOp("Zap/1-1", "EndOfCall") in new stack [Sep 14 09:35:08] DEBUG[23092]: channel.c:1236 spy_detach: Spy MixMonitor removed from channel Zap/1-1 == End MixMonitor Recording Zap/1-1 [Sep 14 09:35:08] DEBUG[15718]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for Local - 5710@from-sip [Sep 14 09:35:08] DEBUG[15718]: chan_local.c:141 local_devicestate: Checking if extension 5710@from-sip exists (devicestate) [Sep 14 09:35:08] DEBUG[15718]: devicestate.c:287 do_state_change: Changing state for Local/5710@from-sip - state 1 (Not in use) [Sep 14 09:35:08] DEBUG[23113]: app_queue.c:535 changethread: Device 'Local/5710@from-sip' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Sep 14 09:35:08] DEBUG[15718]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for Local - 5710@from-sip [Sep 14 09:35:08] DEBUG[15718]: chan_local.c:141 local_devicestate: Checking if extension 5710@from-sip exists (devicestate) [Sep 14 09:35:08] DEBUG[15718]: devicestate.c:287 do_state_change: Changing state for Local/5710@from-sip - state 1 (Not in use) [Sep 14 09:35:08] DEBUG[23114]: app_queue.c:535 changethread: Device 'Local/5710@from-sip' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Sep 14 09:35:08] DEBUG[23092]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is '07803034440' [Sep 14 09:35:08] DEBUG[23092]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is '07803034440' [Sep 14 09:35:08] DEBUG[23092]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is 'h' [Sep 14 09:35:08] DEBUG[23092]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is 'from-sip' [Sep 14 09:35:08] DEBUG[23092]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is 'SIP/5706-09541108' [Sep 14 09:35:08] DEBUG[23092]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is 'Local/5710@from-sip-928e,1' [Sep 14 09:35:08] DEBUG[23092]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is 'NoOp' [Sep 14 09:35:08] DEBUG[23092]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is 'EndOfCall' [Sep 14 09:35:08] DEBUG[23092]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is '2006-09-14 09:34:41' [Sep 14 09:35:08] DEBUG[23092]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is '2006-09-14 09:34:41' [Sep 14 09:35:08] DEBUG[23092]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is '2006-09-14 09:35:08' [Sep 14 09:35:08] DEBUG[23092]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is '27' [Sep 14 09:35:08] DEBUG[23092]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is '27' [Sep 14 09:35:08] DEBUG[23092]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is 'ANSWERED' [Sep 14 09:35:08] DEBUG[23092]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' [Sep 14 09:35:08] DEBUG[23092]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is '' [Sep 14 09:35:08] DEBUG[23092]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is '1158222881.10' [Sep 14 09:35:08] DEBUG[23092]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is '' [Sep 14 09:35:08] DEBUG[23092]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is '07803034440' [Sep 14 09:35:08] DEBUG[23092]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is '07803034440' [Sep 14 09:35:08] DEBUG[23092]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is 'h' [Sep 14 09:35:08] DEBUG[23092]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is 'from-sip' [Sep 14 09:35:08] DEBUG[23092]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is 'Zap/1-1' [Sep 14 09:35:08] DEBUG[23092]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is 'SIP/5706-0951ae00' [Sep 14 09:35:08] DEBUG[23092]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is 'NoOp' [Sep 14 09:35:08] DEBUG[23092]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is 'EndOfCall' [Sep 14 09:35:08] DEBUG[23092]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is '2006-09-14 09:34:30' [Sep 14 09:35:08] DEBUG[23092]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is '2006-09-14 09:34:30' [Sep 14 09:35:08] DEBUG[23092]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is '2006-09-14 09:35:08' [Sep 14 09:35:08] DEBUG[23092]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is '38' [Sep 14 09:35:08] DEBUG[23092]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is '38' [Sep 14 09:35:08] DEBUG[23092]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is 'ANSWERED' [Sep 14 09:35:08] DEBUG[23092]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' [Sep 14 09:35:08] DEBUG[23092]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is '' [Sep 14 09:35:08] DEBUG[23092]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is '1158222870.8' [Sep 14 09:35:08] DEBUG[23092]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is '' [Sep 14 09:35:08] DEBUG[23092]: channel.c:1543 ast_hangup: Hanging up channel 'Zap/1-1' [Sep 14 09:35:08] DEBUG[23092]: chan_zap.c:2413 zt_hangup: zt_hangup(Zap/1-1) [Sep 14 09:35:08] DEBUG[23092]: chan_zap.c:2957 zt_setoption: Set option AUDIO MODE, value: ON(1) on Zap/1-1 [Sep 14 09:35:08] DEBUG[23092]: chan_zap.c:2446 zt_hangup: Hangup: channel: 1 index = 0, normal = 13, callwait = -1, thirdcall = -1 [Sep 14 09:35:08] DEBUG[23092]: chan_zap.c:2600 zt_hangup: Not yet hungup... Calling hangup once with icause, and clearing call [Sep 14 09:35:08] DEBUG[23092]: chan_zap.c:1487 zt_disable_ec: disabled echo cancellation on channel 1 [Sep 14 09:35:08] DEBUG[23092]: chan_zap.c:2874 zt_setoption: Set option TDD MODE, value: OFF(0) on Zap/1-1 [Sep 14 09:35:08] DEBUG[23092]: chan_zap.c:1424 update_conf: Updated conferencing on 1, with 0 conference users [Sep 14 09:35:08] DEBUG[23092]: chan_zap.c:2953 zt_setoption: Set option AUDIO MODE, value: OFF(0) on Zap/1-1 [Sep 14 09:35:08] DEBUG[23092]: chan_zap.c:1487 zt_disable_ec: disabled echo cancellation on channel 1 -- Hungup 'Zap/1-1' [Sep 14 09:35:08] DEBUG[23092]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Zap/1-1 [Sep 14 09:35:08] DEBUG[15718]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for Zap - 1 [Sep 14 09:35:08] DEBUG[15718]: devicestate.c:287 do_state_change: Changing state for Zap/1 - state 0 (Unknown) [Sep 14 09:35:08] DEBUG[23115]: app_queue.c:535 changethread: Device 'Zap/1' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. Really destroying SIP dialog '7b8bb499037201f0301f283665868c49@90.0.0.62' Method: BYE foxtrot*CLI>