<-- SIP read from 192.168.0.12:33918: [Sep 14 09:29:27] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 0: (0) [Sep 14 09:29:27] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: (0) --- (0 headers 1 lines)--- [Sep 14 09:29:28] 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:29:28] DEBUG[15718]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for Zap - 1 [Sep 14 09:29:28] DEBUG[15718]: devicestate.c:287 do_state_change: Changing state for Zap/1 - state 2 (In use) [Sep 14 09:29:28] DEBUG[15724]: chan_zap.c:1455 zt_enable_ec: Enabled echo cancellation on channel 1 [Sep 14 09:29:28] DEBUG[23029]: pbx.c:1684 pbx_extension_helper: Launching 'Answer' -- Executing [444606@isdn10:1] Answer("Zap/1-1", "") in new stack [Sep 14 09:29:28] DEBUG[23030]: 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:29:28] DEBUG[23029]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Zap/1-1 [Sep 14 09:29:28] DEBUG[15718]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for Zap - 1 [Sep 14 09:29:28] DEBUG[15718]: channel.c:880 channel_find_locked: Avoiding initial deadlock for channel '0xb7b01a08' [Sep 14 09:29:28] DEBUG[23029]: pbx.c:1684 pbx_extension_helper: Launching 'MixMonitor' -- Executing [444606@isdn10:2] MixMonitor("Zap/1-1", "jls.gsm") in new stack [Sep 14 09:29:28] DEBUG[23029]: channel.c:1200 ast_channel_spy_add: Spy MixMonitor added to channel Zap/1-1 [Sep 14 09:29:28] DEBUG[23029]: pbx.c:1684 pbx_extension_helper: Launching 'Dial' -- Executing [444606@isdn10:3] Dial("Zap/1-1", "SIP/5706") in new stack [Sep 14 09:29:28] DEBUG[23029]: chan_sip.c:14710 sip_request_call: Asked to create a SIP channel with formats: 0x8 (alaw) [Sep 14 09:29:28] DEBUG[23029]: chan_sip.c:4152 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Sep 14 09:29:28] DEBUG[23029]: chan_sip.c:2518 create_addr_from_peer: Setting NAT on RTP to Off [Sep 14 09:29:28] DEBUG[23029]: chan_sip.c:3647 sip_new: *** Our native formats are 0x4 (ulaw) [Sep 14 09:29:28] DEBUG[23029]: chan_sip.c:3648 sip_new: *** Joint capabilities are 0x0 (nothing) [Sep 14 09:29:28] DEBUG[15718]: devicestate.c:287 do_state_change: Changing state for Zap/1 - state 2 (In use) [Sep 14 09:29:28] DEBUG[23032]: 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:29:28] DEBUG[23029]: chan_sip.c:3649 sip_new: *** Our capabilities are 0x404 (ulaw|ilbc) [Sep 14 09:29:28] DEBUG[23029]: chan_sip.c:3650 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Sep 14 09:29:28] DEBUG[23029]: chan_sip.c:3652 sip_new: *** Our preferred formats from the incoming channel are 0x8 (alaw) [Sep 14 09:29:28] DEBUG[23029]: chan_sip.c:3673 sip_new: This channel will not be able to handle video. [Sep 14 09:29:28] DEBUG[23029]: rtp.c:1477 ast_rtp_make_compatible: Channel 'Zap/1-1' has no RTP, not doing anything [Sep 14 09:29:28] DEBUG[23029]: channel.c:3103 ast_channel_inherit_variables: Not copying variable STACK-isdn10-444606-3. [Sep 14 09:29:28] DEBUG[23029]: channel.c:3103 ast_channel_inherit_variables: Not copying variable MIXMONITOR_FILENAME. [Sep 14 09:29:28] DEBUG[23029]: channel.c:3103 ast_channel_inherit_variables: Not copying variable STACK-isdn10-444606-2. [Sep 14 09:29:28] DEBUG[23029]: channel.c:3103 ast_channel_inherit_variables: Not copying variable STACK-isdn10-444606-1. [Sep 14 09:29:28] DEBUG[23029]: channel.c:3103 ast_channel_inherit_variables: Not copying variable CALLEDTON. [Sep 14 09:29:28] DEBUG[23029]: channel.c:3103 ast_channel_inherit_variables: Not copying variable ANI2. [Sep 14 09:29:28] DEBUG[23029]: channel.c:3103 ast_channel_inherit_variables: Not copying variable TRANSFERCAPABILITY. [Sep 14 09:29:28] DEBUG[23029]: chan_sip.c:2718 sip_call: Outgoing Call for 5706 [Sep 14 09:29:28] DEBUG[23029]: chan_sip.c:2879 update_call_counter: Updating call counter for outgoing call [Sep 14 09:29:28] DEBUG[23029]: chan_sip.c:2726 sip_call: Our T38 capability (0), joint T38 capability (0) [Sep 14 09:29:28] DEBUG[23029]: chan_sip.c:5847 add_sdp: ** Our capability: 0x404 (ulaw|ilbc) Video flag: False [Sep 14 09:29:28] DEBUG[23029]: chan_sip.c:5848 add_sdp: ** Our prefcodec: 0x8 (alaw) Audio is at 90.0.0.62 port 19616 Adding codec 0x4 (ulaw) to SDP Adding codec 0x400 (ilbc) to SDP Adding non-codec 0x1 (telephone-event) to SDP [Sep 14 09:29:28] DEBUG[23029]: chan_sip.c:6000 add_sdp: -- Done with adding codecs to SDP [Sep 14 09:29:28] DEBUG[23029]: chan_sip.c:6039 add_sdp: Done building SDP. Settling with this capability: 0x404 (ulaw|ilbc) [Sep 14 09:29:28] DEBUG[23029]: chan_sip.c:4372 parse_request: Header 0: INVITE sip:5706@192.168.0.200:5060 SIP/2.0 (42) [Sep 14 09:29:28] DEBUG[23029]: chan_sip.c:4372 parse_request: Header 1: Via: SIP/2.0/UDP 90.0.0.62:5060;branch=z9hG4bK5497c0d4;rport (60) [Sep 14 09:29:28] DEBUG[23029]: chan_sip.c:4372 parse_request: Header 2: From: "07803034440" ;tag=as2a834511 (62) [Sep 14 09:29:28] DEBUG[23029]: chan_sip.c:4372 parse_request: Header 3: To: (33) [Sep 14 09:29:28] DEBUG[23029]: chan_sip.c:4372 parse_request: Header 4: Contact: (36) [Sep 14 09:29:28] DEBUG[23029]: chan_sip.c:4372 parse_request: Header 5: Call-ID: 7ae8c639765f3aa24b51d17c55736f3a@90.0.0.62 (51) [Sep 14 09:29:28] DEBUG[23029]: chan_sip.c:4372 parse_request: Header 6: CSeq: 102 INVITE (16) [Sep 14 09:29:28] DEBUG[23029]: chan_sip.c:4372 parse_request: Header 7: User-Agent: Asterisk PBX (24) [Sep 14 09:29:28] DEBUG[23029]: chan_sip.c:4372 parse_request: Header 8: Max-Forwards: 70 (16) [Sep 14 09:29:28] DEBUG[23029]: chan_sip.c:4372 parse_request: Header 9: Date: Thu, 14 Sep 2006 08:29:28 GMT (35) [Sep 14 09:29:28] DEBUG[23029]: chan_sip.c:4372 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Sep 14 09:29:28] DEBUG[23029]: chan_sip.c:4372 parse_request: Header 11: Supported: replaces (19) [Sep 14 09:29:28] DEBUG[23029]: chan_sip.c:4372 parse_request: Header 12: Content-Type: application/sdp (29) [Sep 14 09:29:28] DEBUG[23029]: chan_sip.c:4372 parse_request: Header 13: Content-Length: 267 (19) [Sep 14 09:29:28] DEBUG[23029]: chan_sip.c:4372 parse_request: Header 14: (0) [Sep 14 09:29:28] DEBUG[23029]: chan_sip.c:4404 parse_request: Line: v=0 (3) == Begin MixMonitor Recording Zap/1-1 [Sep 14 09:29:28] DEBUG[23029]: chan_sip.c:4404 parse_request: Line: o=root 15662 15662 IN IP4 90.0.0.62 (35) [Sep 14 09:29:28] DEBUG[23029]: chan_sip.c:4404 parse_request: Line: s=session (9) [Sep 14 09:29:28] DEBUG[23029]: chan_sip.c:4404 parse_request: Line: c=IN IP4 90.0.0.62 (18) [Sep 14 09:29:28] DEBUG[23029]: chan_sip.c:4404 parse_request: Line: t=0 0 (5) [Sep 14 09:29:28] DEBUG[23029]: chan_sip.c:4404 parse_request: Line: m=audio 19616 RTP/AVP 0 97 101 (30) [Sep 14 09:29:28] DEBUG[23029]: chan_sip.c:4404 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Sep 14 09:29:28] DEBUG[23029]: chan_sip.c:4404 parse_request: Line: a=rtpmap:97 iLBC/8000 (21) [Sep 14 09:29:28] DEBUG[23029]: chan_sip.c:4404 parse_request: Line: a=fmtp:97 mode=20 (17) [Sep 14 09:29:28] DEBUG[23029]: chan_sip.c:4404 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Sep 14 09:29:28] DEBUG[23029]: chan_sip.c:4404 parse_request: Line: a=fmtp:101 0-16 (15) [Sep 14 09:29:28] DEBUG[23029]: chan_sip.c:4404 parse_request: Line: a=silenceSupp:off - - - - (25) [Sep 14 09:29:28] DEBUG[23029]: 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=z9hG4bK5497c0d4;rport From: "07803034440" ;tag=as2a834511 To: Contact: Call-ID: 7ae8c639765f3aa24b51d17c55736f3a@90.0.0.62 CSeq: 102 INVITE User-Agent: Asterisk PBX Max-Forwards: 70 Date: Thu, 14 Sep 2006 08:29:28 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 19616 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:29:28] DEBUG[23029]: chan_sip.c:1909 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #1935 -- Called 5706 [Sep 14 09:29:28] DEBUG[23029]: channel.c:2638 set_format: Set channel SIP/5706-094930e0 to read format alaw [Sep 14 09:29:28] DEBUG[23029]: channel.c:2638 set_format: Set channel Zap/1-1 to read format ulaw [Sep 14 09:29:28] DEBUG[23029]: channel.c:1381 queue_frame_to_spies: Building translator from alaw to SLINEAR for spies on channel Zap/1-1 [Sep 14 09:29:28] DEBUG[23029]: 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=z9hG4bK5497c0d4;rport From: "07803034440" ;tag=as2a834511 To: Call-ID: 7ae8c639765f3aa24b51d17c55736f3a@90.0.0.62 Date: Thu, 14 Sep 2006 08:29:27 GMT CSeq: 102 INVITE Server: CSCO/7 Contact: Content-Length: 0 [Sep 14 09:29:28] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 0: SIP/2.0 100 Trying (18) [Sep 14 09:29:28] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 1: Via: SIP/2.0/UDP 90.0.0.62:5060;branch=z9hG4bK5497c0d4;rport (60) [Sep 14 09:29:28] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 2: From: "07803034440" ;tag=as2a834511 (62) [Sep 14 09:29:28] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 3: To: (33) [Sep 14 09:29:28] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 4: Call-ID: 7ae8c639765f3aa24b51d17c55736f3a@90.0.0.62 (51) [Sep 14 09:29:28] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 5: Date: Thu, 14 Sep 2006 08:29:27 GMT (35) [Sep 14 09:29:28] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 6: CSeq: 102 INVITE (16) [Sep 14 09:29:28] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 7: Server: CSCO/7 (14) [Sep 14 09:29:28] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 8: Contact: (38) [Sep 14 09:29:28] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 9: Content-Length: 0 (17) [Sep 14 09:29:28] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 10: (0) --- (10 headers 0 lines)--- [Sep 14 09:29:28] DEBUG[15727]: chan_sip.c:2045 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #1935 - INVITE (got response) [Sep 14 09:29:28] DEBUG[15727]: chan_sip.c:2054 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '7ae8c639765f3aa24b51d17c55736f3a@90.0.0.62' Request 102: Found [Sep 14 09:29:28] 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=z9hG4bK5497c0d4;rport From: "07803034440" ;tag=as2a834511 To: ;tag=000785993d3d003329d8f4ca-5afd0f5f Call-ID: 7ae8c639765f3aa24b51d17c55736f3a@90.0.0.62 Date: Thu, 14 Sep 2006 08:29:27 GMT CSeq: 102 INVITE Server: CSCO/7 Contact: Content-Length: 0 [Sep 14 09:29:28] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 0: SIP/2.0 180 Ringing (19) [Sep 14 09:29:28] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 1: Via: SIP/2.0/UDP 90.0.0.62:5060;branch=z9hG4bK5497c0d4;rport (60) [Sep 14 09:29:28] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 2: From: "07803034440" ;tag=as2a834511 (62) [Sep 14 09:29:28] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 3: To: ;tag=000785993d3d003329d8f4ca-5afd0f5f (71) [Sep 14 09:29:28] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 4: Call-ID: 7ae8c639765f3aa24b51d17c55736f3a@90.0.0.62 (51) [Sep 14 09:29:28] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 5: Date: Thu, 14 Sep 2006 08:29:27 GMT (35) [Sep 14 09:29:28] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 6: CSeq: 102 INVITE (16) [Sep 14 09:29:28] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 7: Server: CSCO/7 (14) [Sep 14 09:29:28] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 8: Contact: (38) [Sep 14 09:29:28] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 9: Content-Length: 0 (17) [Sep 14 09:29:28] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 10: (0) --- (10 headers 0 lines)--- [Sep 14 09:29:28] DEBUG[15727]: chan_sip.c:2054 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '7ae8c639765f3aa24b51d17c55736f3a@90.0.0.62' Request 102: Found [Sep 14 09:29:28] DEBUG[15727]: chan_sip.c:11221 handle_response_invite: SIP response 180 to standard invite [Sep 14 09:29:28] DEBUG[15727]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/5706-094930e0 [Sep 14 09:29:28] DEBUG[15718]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5706 [Sep 14 09:29:28] DEBUG[15718]: chan_sip.c:14652 sip_devicestate: Checking device state for peer 5706 [Sep 14 09:29:28] DEBUG[15718]: devicestate.c:287 do_state_change: Changing state for SIP/5706 - state 1 (Not in use) -- SIP/5706-094930e0 is ringing [Sep 14 09:29:28] DEBUG[23029]: rtp.c:1401 ast_rtp_early_bridge: Channel 'Zap/1-1' has no RTP, not doing anything [Sep 14 09:29:28] DEBUG[23029]: chan_zap.c:4976 zt_indicate: Requested indication 3 on channel Zap/1-1 [Sep 14 09:29:28] DEBUG[23033]: app_queue.c:535 changethread: Device 'SIP/5706' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Sep 14 09:29:29] DEBUG[23029]: channel.c:1436 queue_frame_to_spies: Triggering queue flush for spy 'MixMonitor' on 'Zap/1-1' [Sep 14 09:29:29] DEBUG[23029]: channel.c:1436 queue_frame_to_spies: Triggering queue flush for spy 'MixMonitor' on 'Zap/1-1' [Sep 14 09:29:30] DEBUG[23029]: channel.c:1436 queue_frame_to_spies: Triggering queue flush for spy 'MixMonitor' on 'Zap/1-1' [Sep 14 09:29:30] DEBUG[23029]: 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=z9hG4bK5497c0d4;rport From: "07803034440" ;tag=as2a834511 To: ;tag=000785993d3d003329d8f4ca-5afd0f5f Call-ID: 7ae8c639765f3aa24b51d17c55736f3a@90.0.0.62 Date: Thu, 14 Sep 2006 08:29:29 GMT CSeq: 102 INVITE Server: CSCO/7 Contact: Content-Type: application/sdp Content-Length: 197 v=0 o=Cisco-SIPUA 3237 7257 IN IP4 192.168.0.200 s=SIP Call c=IN IP4 192.168.0.200 t=0 0 m=audio 23916 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 [Sep 14 09:29:30] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 0: SIP/2.0 200 OK (14) [Sep 14 09:29:30] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 1: Via: SIP/2.0/UDP 90.0.0.62:5060;branch=z9hG4bK5497c0d4;rport (60) [Sep 14 09:29:30] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 2: From: "07803034440" ;tag=as2a834511 (62) [Sep 14 09:29:30] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 3: To: ;tag=000785993d3d003329d8f4ca-5afd0f5f (71) [Sep 14 09:29:30] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 4: Call-ID: 7ae8c639765f3aa24b51d17c55736f3a@90.0.0.62 (51) [Sep 14 09:29:30] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 5: Date: Thu, 14 Sep 2006 08:29:29 GMT (35) [Sep 14 09:29:30] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 6: CSeq: 102 INVITE (16) [Sep 14 09:29:30] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 7: Server: CSCO/7 (14) [Sep 14 09:29:30] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 8: Contact: (38) [Sep 14 09:29:30] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 9: Content-Type: application/sdp (29) [Sep 14 09:29:30] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 10: Content-Length: 197 (19) [Sep 14 09:29:30] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 11: (0) [Sep 14 09:29:30] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: v=0 (3) [Sep 14 09:29:30] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: o=Cisco-SIPUA 3237 7257 IN IP4 192.168.0.200 (44) [Sep 14 09:29:30] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: s=SIP Call (10) [Sep 14 09:29:30] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: c=IN IP4 192.168.0.200 (22) [Sep 14 09:29:30] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: t=0 0 (5) [Sep 14 09:29:30] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: m=audio 23916 RTP/AVP 0 101 (27) [Sep 14 09:29:30] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Sep 14 09:29:30] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Sep 14 09:29:30] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: a=fmtp:101 0-15 (15) --- (11 headers 9 lines)--- [Sep 14 09:29:30] DEBUG[15727]: chan_sip.c:1994 __sip_ack: Acked pending invite 102 [Sep 14 09:29:30] DEBUG[15727]: chan_sip.c:2012 __sip_ack: Stopping retransmission on '7ae8c639765f3aa24b51d17c55736f3a@90.0.0.62' of Request 102: Match Not Found [Sep 14 09:29:30] 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:23916 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:29:30] DEBUG[15727]: chan_sip.c:4877 process_sdp: T38 state changed to 0 on channel SIP/5706-094930e0 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:23916 [Sep 14 09:29:30] DEBUG[15727]: chan_sip.c:4947 process_sdp: We're settling with these formats: 0x4 (ulaw) [Sep 14 09:29:30] DEBUG[15727]: chan_sip.c:4954 process_sdp: We have an owner, now see if we need to change this call [Sep 14 09:29:30] DEBUG[15727]: chan_sip.c:2879 update_call_counter: Updating call counter for outgoing call [Sep 14 09:29:30] DEBUG[15727]: chan_sip.c:7631 build_route: build_route: Contact hop: list_route: hop: [Sep 14 09:29:30] DEBUG[15727]: chan_sip.c:5378 reqprep: Strict routing enforced for session 7ae8c639765f3aa24b51d17c55736f3a@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=z9hG4bK1e9c3aca;rport From: "07803034440" ;tag=as2a834511 To: ;tag=000785993d3d003329d8f4ca-5afd0f5f Contact: Call-ID: 7ae8c639765f3aa24b51d17c55736f3a@90.0.0.62 CSeq: 102 ACK User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- [Sep 14 09:29:30] DEBUG[23029]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/5706-094930e0 -- SIP/5706-094930e0 answered Zap/1-1 [Sep 14 09:29:30] DEBUG[15718]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5706 [Sep 14 09:29:30] DEBUG[15718]: chan_sip.c:14652 sip_devicestate: Checking device state for peer 5706 [Sep 14 09:29:30] DEBUG[23029]: rtp.c:1401 ast_rtp_early_bridge: Channel 'Zap/1-1' has no RTP, not doing anything [Sep 14 09:29:30] DEBUG[15718]: devicestate.c:287 do_state_change: Changing state for SIP/5706 - state 1 (Not in use) [Sep 14 09:29:30] DEBUG[23029]: chan_zap.c:4976 zt_indicate: Requested indication -1 on channel Zap/1-1 [Sep 14 09:29:30] DEBUG[23034]: app_queue.c:535 changethread: Device 'SIP/5706' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Sep 14 09:29:30] DEBUG[23029]: rtp.c:2518 ast_rtp_write: Ooh, format changed from unknown to ulaw [Sep 14 09:29:31] DEBUG[23029]: channel.c:1381 queue_frame_to_spies: Building translator from alaw to SLINEAR for spies on channel Zap/1-1 [Sep 14 09:29:31] DEBUG[23029]: 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:50628: INVITE sip:07803034440@90.0.0.62:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.0.200:5060;branch=z9hG4bK6207c30b From: ;tag=000785993d3d003329d8f4ca-5afd0f5f To: "07803034440" ;tag=as2a834511 Call-ID: 7ae8c639765f3aa24b51d17c55736f3a@90.0.0.62 Date: Thu, 14 Sep 2006 08:29:39 GMT CSeq: 101 INVITE User-Agent: CSCO/7 Contact: Content-Type: application/sdp Content-Length: 193 Remote-Party-ID: "5706" ;party=calling;id-type=subscriber;privacy=off;screen=no v=0 o=Cisco-SIPUA 21796 22000 IN IP4 192.168.0.200 s=SIP Call c=IN IP4 0.0.0.0 t=0 0 m=audio 23916 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 [Sep 14 09:29:40] 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:29:40] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.0.200:5060;branch=z9hG4bK6207c30b (58) [Sep 14 09:29:40] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 2: From: ;tag=000785993d3d003329d8f4ca-5afd0f5f (73) [Sep 14 09:29:40] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 3: To: "07803034440" ;tag=as2a834511 (60) [Sep 14 09:29:40] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 4: Call-ID: 7ae8c639765f3aa24b51d17c55736f3a@90.0.0.62 (51) [Sep 14 09:29:40] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 5: Date: Thu, 14 Sep 2006 08:29:39 GMT (35) [Sep 14 09:29:40] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 6: CSeq: 101 INVITE (16) [Sep 14 09:29:40] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 7: User-Agent: CSCO/7 (18) [Sep 14 09:29:40] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 8: Contact: (38) [Sep 14 09:29:40] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 9: Content-Type: application/sdp (29) [Sep 14 09:29:40] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 10: Content-Length: 193 (19) [Sep 14 09:29:40] 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:29:40] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 12: (0) [Sep 14 09:29:40] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: v=0 (3) [Sep 14 09:29:40] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: o=Cisco-SIPUA 21796 22000 IN IP4 192.168.0.200 (46) [Sep 14 09:29:40] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: s=SIP Call (10) [Sep 14 09:29:40] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: c=IN IP4 0.0.0.0 (16) [Sep 14 09:29:40] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: t=0 0 (5) [Sep 14 09:29:40] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: m=audio 23916 RTP/AVP 0 101 (27) [Sep 14 09:29:40] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Sep 14 09:29:40] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Sep 14 09:29:40] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: a=fmtp:101 0-15 (15) --- (12 headers 9 lines)--- [Sep 14 09:29:40] 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:23916 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:29:40] DEBUG[15727]: chan_sip.c:4877 process_sdp: T38 state changed to 0 on channel SIP/5706-094930e0 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:23916 [Sep 14 09:29:40] DEBUG[15727]: chan_sip.c:4947 process_sdp: We're settling with these formats: 0x4 (ulaw) [Sep 14 09:29:40] DEBUG[15727]: chan_sip.c:4954 process_sdp: We have an owner, now see if we need to change this call [Sep 14 09:29:40] 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:29:40] DEBUG[15727]: chan_sip.c:12921 handle_request_invite: Got a SIP re-invite for call 7ae8c639765f3aa24b51d17c55736f3a@90.0.0.62 [Sep 14 09:29:40] DEBUG[15718]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5706 [Sep 14 09:29:40] DEBUG[15718]: chan_sip.c:14652 sip_devicestate: Checking device state for peer 5706 [Sep 14 09:29:40] DEBUG[15718]: devicestate.c:287 do_state_change: Changing state for SIP/5706 - state 8 (On Hold) [Sep 14 09:29:40] DEBUG[15727]: chan_sip.c:13010 handle_request_invite: SIP/5706-094930e0: This call is UP.... [Sep 14 09:29:40] DEBUG[15727]: chan_sip.c:5847 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True [Sep 14 09:29:40] DEBUG[15727]: chan_sip.c:5848 add_sdp: ** Our prefcodec: 0x8 (alaw) Audio is at 90.0.0.62 port 19616 Adding codec 0x4 (ulaw) to SDP Adding non-codec 0x1 (telephone-event) to SDP [Sep 14 09:29:40] DEBUG[15727]: chan_sip.c:6000 add_sdp: -- Done with adding codecs to SDP [Sep 14 09:29:40] 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=z9hG4bK6207c30b;received=192.168.0.200 From: ;tag=000785993d3d003329d8f4ca-5afd0f5f To: "07803034440" ;tag=as2a834511 Call-ID: 7ae8c639765f3aa24b51d17c55736f3a@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 19616 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:29:40] DEBUG[15727]: chan_sip.c:1909 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #1938 [Sep 14 09:29:40] DEBUG[23029]: 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:29:40] DEBUG[23035]: 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:29:40] DEBUG[23029]: channel.c:1845 ast_settimeout: Scheduling timer at 160 sample intervals [Sep 14 09:29:40] DEBUG[23029]: channel.c:2162 __ast_read: Generator got voice, switching to phase locked mode [Sep 14 09:29:40] DEBUG[23029]: channel.c:1845 ast_settimeout: Scheduling timer at 0 sample intervals [Sep 14 09:29:40] DEBUG[23029]: channel.c:2638 set_format: Set channel Zap/1-1 to write format ulaw [Sep 14 09:29:40] DEBUG[23029]: res_musiconhold.c:252 ast_moh_files_next: Zap/1-1 Opened file 7 '/var/lib/asterisk/sounds/custom/moh/track18' 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=z9hG4bK79fbdb76 From: ;tag=000785993d3d003329d8f4ca-5afd0f5f To: "07803034440" ;tag=as2a834511 Call-ID: 7ae8c639765f3aa24b51d17c55736f3a@90.0.0.62 Date: Thu, 14 Sep 2006 08:29:39 GMT CSeq: 101 ACK User-Agent: CSCO/7 Content-Length: 0 [Sep 14 09:29:40] 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:29:40] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.0.200:5060;branch=z9hG4bK79fbdb76 (58) [Sep 14 09:29:40] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 2: From: ;tag=000785993d3d003329d8f4ca-5afd0f5f (73) [Sep 14 09:29:40] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 3: To: "07803034440" ;tag=as2a834511 (60) [Sep 14 09:29:40] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 4: Call-ID: 7ae8c639765f3aa24b51d17c55736f3a@90.0.0.62 (51) [Sep 14 09:29:40] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 5: Date: Thu, 14 Sep 2006 08:29:39 GMT (35) [Sep 14 09:29:40] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 6: CSeq: 101 ACK (13) [Sep 14 09:29:40] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 7: User-Agent: CSCO/7 (18) [Sep 14 09:29:40] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 8: Content-Length: 0 (17) [Sep 14 09:29:40] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 9: (0) --- (9 headers 0 lines)--- [Sep 14 09:29:40] DEBUG[15727]: chan_sip.c:14065 handle_request: **** Received ACK (6) - Command in SIP ACK [Sep 14 09:29:40] DEBUG[15727]: chan_sip.c:2002 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #1938 [Sep 14 09:29:40] DEBUG[15727]: chan_sip.c:2012 __sip_ack: Stopping retransmission on '7ae8c639765f3aa24b51d17c55736f3a@90.0.0.62' of Response 101: Match Not Found RTCP SR transmission error, rtcp halted No such file or directory [Sep 14 09:29:40] NOTICE[15727]: sched.c:283 ast_sched_del: Attempted to delete nonexistent schedule entry 1937! 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=z9hG4bK0c30642d From: "5706" ;tag=000785993d3d00341a5e8a4b-40165fe3 To: Call-ID: 00078599-3d3d001c-41be5986-411c43dc@192.168.0.200 Date: Thu, 14 Sep 2006 08:29:44 GMT CSeq: 101 INVITE User-Agent: CSCO/7 Contact: Expires: 180 Content-Type: application/sdp Content-Length: 248 Accept: application/sdp Remote-Party-ID: "5706" ;party=calling;id-type=subscriber;privacy=off;screen=no v=0 o=Cisco-SIPUA 18811 8755 IN IP4 192.168.0.200 s=SIP Call c=IN IP4 192.168.0.200 t=0 0 m=audio 23918 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:29:45] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 0: INVITE sip:5709@90.0.0.62 SIP/2.0 (33) [Sep 14 09:29:45] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.0.200:5060;branch=z9hG4bK0c30642d (58) [Sep 14 09:29:45] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 2: From: "5706" ;tag=000785993d3d00341a5e8a4b-40165fe3 (71) [Sep 14 09:29:45] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 3: To: (24) [Sep 14 09:29:45] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 4: Call-ID: 00078599-3d3d001c-41be5986-411c43dc@192.168.0.200 (58) [Sep 14 09:29:45] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 5: Date: Thu, 14 Sep 2006 08:29:44 GMT (35) [Sep 14 09:29:45] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 6: CSeq: 101 INVITE (16) [Sep 14 09:29:45] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 7: User-Agent: CSCO/7 (18) [Sep 14 09:29:45] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 8: Contact: (38) [Sep 14 09:29:45] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 9: Expires: 180 (12) [Sep 14 09:29:45] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 10: Content-Type: application/sdp (29) [Sep 14 09:29:45] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 11: Content-Length: 248 (19) [Sep 14 09:29:45] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 12: Accept: application/sdp (23) [Sep 14 09:29:45] 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:29:45] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 14: (0) [Sep 14 09:29:45] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: v=0 (3) [Sep 14 09:29:45] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: o=Cisco-SIPUA 18811 8755 IN IP4 192.168.0.200 (45) [Sep 14 09:29:45] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: s=SIP Call (10) [Sep 14 09:29:45] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: c=IN IP4 192.168.0.200 (22) [Sep 14 09:29:45] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: t=0 0 (5) [Sep 14 09:29:45] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: m=audio 23918 RTP/AVP 0 8 18 101 (32) [Sep 14 09:29:45] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Sep 14 09:29:45] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Sep 14 09:29:45] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: a=rtpmap:18 G729/8000 (21) [Sep 14 09:29:45] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Sep 14 09:29:45] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: a=fmtp:101 0-15 (15) --- (14 headers 11 lines)--- [Sep 14 09:29:45] DEBUG[15727]: chan_sip.c:4152 sip_alloc: Allocating new SIP dialog for 00078599-3d3d001c-41be5986-411c43dc@192.168.0.200 - INVITE (With RTP) [Sep 14 09:29:45] 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-3d3d001c-41be5986-411c43dc@192.168.0.200 [Sep 14 09:29:45] 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=z9hG4bK0c30642d;received=192.168.0.200 From: "5706" ;tag=000785993d3d00341a5e8a4b-40165fe3 To: ;tag=as4b71600c Call-ID: 00078599-3d3d001c-41be5986-411c43dc@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="55ca09d5" Content-Length: 0 --- [Sep 14 09:29:45] DEBUG[15727]: chan_sip.c:1909 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #1939 Scheduling destruction of SIP dialog '00078599-3d3d001c-41be5986-411c43dc@192.168.0.200' in 32000 ms (Method: INVITE) Found user '5706' foxtrot*CLI> <-- SIP read from 192.168.0.200:50634: ACK sip:5709@90.0.0.62 SIP/2.0 Via: SIP/2.0/UDP 192.168.0.200:5060;branch=z9hG4bK0c30642d From: "5706" ;tag=000785993d3d00341a5e8a4b-40165fe3 To: ;tag=as4b71600c Call-ID: 00078599-3d3d001c-41be5986-411c43dc@192.168.0.200 Date: Thu, 14 Sep 2006 08:29:44 GMT CSeq: 101 ACK Content-Length: 0 [Sep 14 09:29:45] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 0: ACK sip:5709@90.0.0.62 SIP/2.0 (30) [Sep 14 09:29:45] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.0.200:5060;branch=z9hG4bK0c30642d (58) [Sep 14 09:29:45] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 2: From: "5706" ;tag=000785993d3d00341a5e8a4b-40165fe3 (71) [Sep 14 09:29:45] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 3: To: ;tag=as4b71600c (39) [Sep 14 09:29:45] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 4: Call-ID: 00078599-3d3d001c-41be5986-411c43dc@192.168.0.200 (58) [Sep 14 09:29:45] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 5: Date: Thu, 14 Sep 2006 08:29:44 GMT (35) [Sep 14 09:29:45] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 6: CSeq: 101 ACK (13) [Sep 14 09:29:45] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 7: Content-Length: 0 (17) [Sep 14 09:29:45] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 8: (0) --- (8 headers 0 lines)--- [Sep 14 09:29:45] DEBUG[15727]: chan_sip.c:14065 handle_request: **** Received ACK (6) - Command in SIP ACK [Sep 14 09:29:45] DEBUG[15727]: chan_sip.c:2002 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #1939 [Sep 14 09:29:45] DEBUG[15727]: chan_sip.c:2012 __sip_ack: Stopping retransmission on '00078599-3d3d001c-41be5986-411c43dc@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=z9hG4bK1aa34b6f From: "5706" ;tag=000785993d3d00341a5e8a4b-40165fe3 To: Call-ID: 00078599-3d3d001c-41be5986-411c43dc@192.168.0.200 Date: Thu, 14 Sep 2006 08:29:44 GMT CSeq: 102 INVITE User-Agent: CSCO/7 Contact: Proxy-Authorization: Digest username="5706",realm="asterisk",uri="sip:90.0.0.62",response="320f4a17a2294bb2ca1335c35b57780d",nonce="55ca09d5",algorithm=MD5 Expires: 180 Content-Type: application/sdp Content-Length: 248 Remote-Party-ID: "5706" ;party=calling;id-type=subscriber;privacy=off;screen=no v=0 o=Cisco-SIPUA 18811 8755 IN IP4 192.168.0.200 s=SIP Call c=IN IP4 192.168.0.200 t=0 0 m=audio 23918 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:29:46] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 0: INVITE sip:5709@90.0.0.62 SIP/2.0 (33) [Sep 14 09:29:46] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.0.200:5060;branch=z9hG4bK1aa34b6f (58) [Sep 14 09:29:46] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 2: From: "5706" ;tag=000785993d3d00341a5e8a4b-40165fe3 (71) [Sep 14 09:29:46] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 3: To: (24) [Sep 14 09:29:46] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 4: Call-ID: 00078599-3d3d001c-41be5986-411c43dc@192.168.0.200 (58) [Sep 14 09:29:46] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 5: Date: Thu, 14 Sep 2006 08:29:44 GMT (35) [Sep 14 09:29:46] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 6: CSeq: 102 INVITE (16) [Sep 14 09:29:46] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 7: User-Agent: CSCO/7 (18) [Sep 14 09:29:46] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 8: Contact: (38) [Sep 14 09:29:46] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 9: Proxy-Authorization: Digest username="5706",realm="asterisk",uri="sip:90.0.0.62",response="320f4a17a2294bb2ca1335c35b57780d",nonce="55ca09d5",algorithm=MD5 (155) [Sep 14 09:29:46] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 10: Expires: 180 (12) [Sep 14 09:29:46] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 11: Content-Type: application/sdp (29) [Sep 14 09:29:46] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 12: Content-Length: 248 (19) [Sep 14 09:29:46] 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:29:46] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 14: (0) [Sep 14 09:29:46] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: v=0 (3) [Sep 14 09:29:46] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: o=Cisco-SIPUA 18811 8755 IN IP4 192.168.0.200 (45) [Sep 14 09:29:46] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: s=SIP Call (10) [Sep 14 09:29:46] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: c=IN IP4 192.168.0.200 (22) [Sep 14 09:29:46] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: t=0 0 (5) [Sep 14 09:29:46] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: m=audio 23918 RTP/AVP 0 8 18 101 (32) [Sep 14 09:29:46] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Sep 14 09:29:46] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Sep 14 09:29:46] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: a=rtpmap:18 G729/8000 (21) [Sep 14 09:29:46] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Sep 14 09:29:46] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: a=fmtp:101 0-15 (15) --- (14 headers 11 lines)--- [Sep 14 09:29:46] 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-3d3d001c-41be5986-411c43dc@192.168.0.200 [Sep 14 09:29:46] 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:23918 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:29:46] 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:23918 [Sep 14 09:29:46] DEBUG[15727]: chan_sip.c:4947 process_sdp: We're settling with these formats: 0x4 (ulaw) [Sep 14 09:29:46] DEBUG[15727]: chan_sip.c:12872 handle_request_invite: Checking SIP call limits for device 5706 [Sep 14 09:29:46] 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:29:46] DEBUG[15727]: chan_sip.c:3647 sip_new: *** Our native formats are 0x4 (ulaw) [Sep 14 09:29:46] DEBUG[15727]: chan_sip.c:3648 sip_new: *** Joint capabilities are 0x4 (ulaw) [Sep 14 09:29:46] DEBUG[15727]: chan_sip.c:3649 sip_new: *** Our capabilities are 0x404 (ulaw|ilbc) [Sep 14 09:29:46] DEBUG[15727]: chan_sip.c:3650 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Sep 14 09:29:46] DEBUG[15727]: chan_sip.c:3673 sip_new: This channel will not be able to handle video. [Sep 14 09:29:46] DEBUG[15727]: chan_sip.c:7631 build_route: build_route: Contact hop: list_route: hop: [Sep 14 09:29:46] DEBUG[15727]: chan_sip.c:12943 handle_request_invite: SIP/5706-0953cc70: 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=z9hG4bK1aa34b6f;received=192.168.0.200 From: "5706" ;tag=000785993d3d00341a5e8a4b-40165fe3 To: Call-ID: 00078599-3d3d001c-41be5986-411c43dc@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:29:46] DEBUG[15727]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/5706-0953cc70 [Sep 14 09:29:46] DEBUG[15718]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5706 [Sep 14 09:29:46] DEBUG[15718]: chan_sip.c:14652 sip_devicestate: Checking device state for peer 5706 [Sep 14 09:29:46] DEBUG[15718]: devicestate.c:287 do_state_change: Changing state for SIP/5706 - state 8 (On Hold) [Sep 14 09:29:46] DEBUG[23036]: pbx.c:1684 pbx_extension_helper: Launching 'Answer' -- Executing [5709@from-sip:1] Answer("SIP/5706-0953cc70", "") in new stack [Sep 14 09:29:46] DEBUG[23036]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/5706-0953cc70 [Sep 14 09:29:46] DEBUG[15718]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5706 [Sep 14 09:29:46] DEBUG[15718]: chan_sip.c:14652 sip_devicestate: Checking device state for peer 5706 [Sep 14 09:29:46] DEBUG[15718]: devicestate.c:287 do_state_change: Changing state for SIP/5706 - state 8 (On Hold) [Sep 14 09:29:46] DEBUG[23036]: chan_sip.c:3328 sip_answer: SIP answering channel: SIP/5706-0953cc70 [Sep 14 09:29:46] DEBUG[23036]: chan_sip.c:5847 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True [Sep 14 09:29:46] DEBUG[23036]: chan_sip.c:5848 add_sdp: ** Our prefcodec: 0x0 (nothing) Audio is at 90.0.0.62 port 13938 Adding codec 0x4 (ulaw) to SDP Adding non-codec 0x1 (telephone-event) to SDP [Sep 14 09:29:46] DEBUG[23036]: chan_sip.c:6000 add_sdp: -- Done with adding codecs to SDP [Sep 14 09:29:46] DEBUG[23036]: 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=z9hG4bK1aa34b6f;received=192.168.0.200 From: "5706" ;tag=000785993d3d00341a5e8a4b-40165fe3 To: ;tag=as6798c182 Call-ID: 00078599-3d3d001c-41be5986-411c43dc@192.168.0.200 CSeq: 102 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 15662 IN IP4 90.0.0.62 s=session c=IN IP4 90.0.0.62 t=0 0 m=audio 13938 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:29:46] DEBUG[23036]: chan_sip.c:1909 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #1941 [Sep 14 09:29:46] DEBUG[23036]: pbx.c:1684 pbx_extension_helper: Launching 'Dial' -- Executing [5709@from-sip:2] Dial("SIP/5706-0953cc70", "Local/5710@from-sip") in new stack [Sep 14 09:29:46] DEBUG[23036]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Local/5710@from-sip-d305,2 [Sep 14 09:29:46] DEBUG[15718]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for Local - 5710@from-sip [Sep 14 09:29:46] DEBUG[15718]: chan_local.c:141 local_devicestate: Checking if extension 5710@from-sip exists (devicestate) [Sep 14 09:29:46] DEBUG[15718]: devicestate.c:287 do_state_change: Changing state for Local/5710@from-sip - state 2 (In use) [Sep 14 09:29:46] DEBUG[23037]: 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:29:46] DEBUG[23036]: rtp.c:1470 ast_rtp_make_compatible: Channel 'Local/5710@from-sip-d305,1' has no RTP, not doing anything [Sep 14 09:29:46] DEBUG[23038]: 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:29:46] DEBUG[23039]: 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:29:46] DEBUG[23036]: channel.c:3103 ast_channel_inherit_variables: Not copying variable STACK-from-sip-5709-2. [Sep 14 09:29:46] DEBUG[23036]: channel.c:3103 ast_channel_inherit_variables: Not copying variable STACK-from-sip-5709-1. [Sep 14 09:29:46] DEBUG[23036]: channel.c:3103 ast_channel_inherit_variables: Not copying variable SIPCALLID. [Sep 14 09:29:46] DEBUG[23036]: channel.c:3103 ast_channel_inherit_variables: Not copying variable SIPUSERAGENT. [Sep 14 09:29:46] DEBUG[23036]: channel.c:3103 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [Sep 14 09:29:46] DEBUG[23036]: channel.c:3103 ast_channel_inherit_variables: Not copying variable SIPURI. -- Called 5710@from-sip [Sep 14 09:29:46] DEBUG[23040]: pbx.c:1684 pbx_extension_helper: Launching 'Answer' -- Executing [5710@from-sip:1] Answer("Local/5710@from-sip-d305,2", "") in new stack [Sep 14 09:29:46] DEBUG[23036]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Local/5710@from-sip-d305,1 [Sep 14 09:29:46] DEBUG[23040]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Local/5710@from-sip-d305,2 -- Local/5710@from-sip-d305,1 answered SIP/5706-0953cc70 [Sep 14 09:29:46] DEBUG[15718]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for Local - 5710@from-sip [Sep 14 09:29:46] DEBUG[15718]: chan_local.c:141 local_devicestate: Checking if extension 5710@from-sip exists (devicestate) [Sep 14 09:29:46] DEBUG[23040]: pbx.c:1684 pbx_extension_helper: Launching 'MixMonitor' -- Executing [5710@from-sip:2] MixMonitor("Local/5710@from-sip-d305,2", "1158222586.6.gsm") in new stack [Sep 14 09:29:46] DEBUG[15718]: devicestate.c:287 do_state_change: Changing state for Local/5710@from-sip - state 2 (In use) [Sep 14 09:29:46] DEBUG[15718]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for Local - 5710@from-sip [Sep 14 09:29:46] DEBUG[15718]: chan_local.c:141 local_devicestate: Checking if extension 5710@from-sip exists (devicestate) [Sep 14 09:29:46] DEBUG[23040]: channel.c:1200 ast_channel_spy_add: Spy MixMonitor added to channel Local/5710@from-sip-d305,2 [Sep 14 09:29:46] DEBUG[15718]: channel.c:880 channel_find_locked: Avoiding initial deadlock for channel '0x9541e90' == Begin MixMonitor Recording Local/5710@from-sip-d305,2 [Sep 14 09:29:46] DEBUG[23036]: rtp.c:1409 ast_rtp_early_bridge: Channel 'Local/5710@from-sip-d305,1' has no RTP, not doing anything [Sep 14 09:29:46] DEBUG[23041]: 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:29:46] DEBUG[23040]: pbx.c:1684 pbx_extension_helper: Launching 'Dial' -- Executing [5710@from-sip:3] Dial("Local/5710@from-sip-d305,2", "SIP/5710|120|g") in new stack [Sep 14 09:29:46] DEBUG[23040]: chan_sip.c:14710 sip_request_call: Asked to create a SIP channel with formats: 0x4 (ulaw) [Sep 14 09:29:46] DEBUG[23040]: chan_sip.c:4152 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Sep 14 09:29:46] DEBUG[23040]: chan_sip.c:2518 create_addr_from_peer: Setting NAT on RTP to Off [Sep 14 09:29:46] DEBUG[23040]: chan_sip.c:3647 sip_new: *** Our native formats are 0x4 (ulaw) [Sep 14 09:29:46] DEBUG[23040]: chan_sip.c:3648 sip_new: *** Joint capabilities are 0x0 (nothing) [Sep 14 09:29:46] DEBUG[23040]: chan_sip.c:3649 sip_new: *** Our capabilities are 0x404 (ulaw|ilbc) [Sep 14 09:29:46] DEBUG[23040]: chan_sip.c:3650 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Sep 14 09:29:46] DEBUG[23040]: chan_sip.c:3652 sip_new: *** Our preferred formats from the incoming channel are 0x4 (ulaw) [Sep 14 09:29:46] DEBUG[23040]: chan_sip.c:3673 sip_new: This channel will not be able to handle video. [Sep 14 09:29:46] DEBUG[23040]: rtp.c:1477 ast_rtp_make_compatible: Channel 'Local/5710@from-sip-d305,2' has no RTP, not doing anything [Sep 14 09:29:46] DEBUG[15718]: channel.c:880 channel_find_locked: Avoiding initial deadlock for channel '0x9541e90' [Sep 14 09:29:46] DEBUG[23040]: channel.c:3103 ast_channel_inherit_variables: Not copying variable STACK-from-sip-5710-3. [Sep 14 09:29:46] DEBUG[23040]: channel.c:3103 ast_channel_inherit_variables: Not copying variable MIXMONITOR_FILENAME. [Sep 14 09:29:46] DEBUG[23040]: channel.c:3103 ast_channel_inherit_variables: Not copying variable STACK-from-sip-5710-2. [Sep 14 09:29:46] DEBUG[23040]: channel.c:3103 ast_channel_inherit_variables: Not copying variable STACK-from-sip-5710-1. [Sep 14 09:29:46] DEBUG[23040]: channel.c:3103 ast_channel_inherit_variables: Not copying variable DIALEDPEERNUMBER. [Sep 14 09:29:46] DEBUG[23040]: chan_sip.c:2718 sip_call: Outgoing Call for 5710 [Sep 14 09:29:46] DEBUG[23040]: chan_sip.c:2879 update_call_counter: Updating call counter for outgoing call [Sep 14 09:29:46] DEBUG[23040]: chan_sip.c:2726 sip_call: Our T38 capability (0), joint T38 capability (0) [Sep 14 09:29:46] DEBUG[23040]: chan_sip.c:5847 add_sdp: ** Our capability: 0x404 (ulaw|ilbc) Video flag: False [Sep 14 09:29:46] DEBUG[23040]: chan_sip.c:5848 add_sdp: ** Our prefcodec: 0x4 (ulaw) Audio is at 90.0.0.62 port 11464 Adding codec 0x4 (ulaw) to SDP Adding codec 0x400 (ilbc) to SDP Adding non-codec 0x1 (telephone-event) to SDP [Sep 14 09:29:46] DEBUG[23040]: chan_sip.c:6000 add_sdp: -- Done with adding codecs to SDP [Sep 14 09:29:46] DEBUG[23040]: chan_sip.c:6039 add_sdp: Done building SDP. Settling with this capability: 0x404 (ulaw|ilbc) [Sep 14 09:29:46] DEBUG[23040]: 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:29:46] DEBUG[23040]: chan_sip.c:4372 parse_request: Header 1: Via: SIP/2.0/UDP 90.0.0.62:5060;branch=z9hG4bK56ddfc1c;rport (60) [Sep 14 09:29:46] DEBUG[23040]: chan_sip.c:4372 parse_request: Header 2: From: "5706" ;tag=as07e64d56 (57) [Sep 14 09:29:46] DEBUG[23040]: chan_sip.c:4372 parse_request: Header 3: To: (60) [Sep 14 09:29:46] DEBUG[23040]: chan_sip.c:4372 parse_request: Header 4: Contact: (38) [Sep 14 09:29:46] DEBUG[23040]: chan_sip.c:4372 parse_request: Header 5: Call-ID: 6b20c5883f43556055c24c6f0af4e2f3@90.0.0.62 (51) [Sep 14 09:29:46] DEBUG[23040]: chan_sip.c:4372 parse_request: Header 6: CSeq: 102 INVITE (16) [Sep 14 09:29:46] DEBUG[23040]: chan_sip.c:4372 parse_request: Header 7: User-Agent: Asterisk PBX (24) [Sep 14 09:29:46] DEBUG[23040]: chan_sip.c:4372 parse_request: Header 8: Max-Forwards: 70 (16) [Sep 14 09:29:46] DEBUG[15718]: devicestate.c:287 do_state_change: Changing state for Local/5710@from-sip - state 2 (In use) [Sep 14 09:29:46] DEBUG[23040]: chan_sip.c:4372 parse_request: Header 9: Date: Thu, 14 Sep 2006 08:29:46 GMT (35) [Sep 14 09:29:46] DEBUG[23040]: chan_sip.c:4372 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Sep 14 09:29:46] DEBUG[23043]: 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:29:46] DEBUG[23040]: chan_sip.c:4372 parse_request: Header 11: Supported: replaces (19) [Sep 14 09:29:46] DEBUG[23040]: chan_sip.c:4372 parse_request: Header 12: Content-Type: application/sdp (29) [Sep 14 09:29:46] DEBUG[23040]: chan_sip.c:4372 parse_request: Header 13: Content-Length: 267 (19) [Sep 14 09:29:46] DEBUG[23040]: chan_sip.c:4372 parse_request: Header 14: (0) [Sep 14 09:29:46] DEBUG[23040]: chan_sip.c:4404 parse_request: Line: v=0 (3) [Sep 14 09:29:46] DEBUG[23040]: chan_sip.c:4404 parse_request: Line: o=root 15662 15662 IN IP4 90.0.0.62 (35) [Sep 14 09:29:46] DEBUG[23040]: chan_sip.c:4404 parse_request: Line: s=session (9) [Sep 14 09:29:46] DEBUG[23040]: chan_sip.c:4404 parse_request: Line: c=IN IP4 90.0.0.62 (18) [Sep 14 09:29:46] DEBUG[23040]: chan_sip.c:4404 parse_request: Line: t=0 0 (5) [Sep 14 09:29:46] DEBUG[23040]: chan_sip.c:4404 parse_request: Line: m=audio 11464 RTP/AVP 0 97 101 (30) [Sep 14 09:29:46] DEBUG[23040]: chan_sip.c:4404 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Sep 14 09:29:46] DEBUG[23040]: chan_sip.c:4404 parse_request: Line: a=rtpmap:97 iLBC/8000 (21) [Sep 14 09:29:46] DEBUG[23040]: chan_sip.c:4404 parse_request: Line: a=fmtp:97 mode=20 (17) [Sep 14 09:29:46] DEBUG[23040]: chan_sip.c:4404 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Sep 14 09:29:46] DEBUG[23040]: chan_sip.c:4404 parse_request: Line: a=fmtp:101 0-16 (15) [Sep 14 09:29:46] DEBUG[23040]: chan_sip.c:4404 parse_request: Line: a=silenceSupp:off - - - - (25) [Sep 14 09:29:46] DEBUG[23040]: 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=z9hG4bK56ddfc1c;rport From: "5706" ;tag=as07e64d56 To: Contact: Call-ID: 6b20c5883f43556055c24c6f0af4e2f3@90.0.0.62 CSeq: 102 INVITE User-Agent: Asterisk PBX Max-Forwards: 70 Date: Thu, 14 Sep 2006 08:29:46 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 11464 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:29:46] DEBUG[23040]: chan_sip.c:1909 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #1942 -- Called 5710 [Sep 14 09:29:46] DEBUG[23036]: rtp.c:659 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4) [Sep 14 09:29:46] DEBUG[23036]: rtp.c:659 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4) [Sep 14 09:29:46] DEBUG[23036]: rtp.c:659 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4) [Sep 14 09:29:46] DEBUG[23040]: channel.c:1381 queue_frame_to_spies: Building translator from ulaw to SLINEAR for spies on channel Local/5710@from-sip-d305,2 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=z9hG4bK3c4fb2a8 From: "5706" ;tag=000785993d3d00341a5e8a4b-40165fe3 To: ;tag=as6798c182 Call-ID: 00078599-3d3d001c-41be5986-411c43dc@192.168.0.200 Date: Thu, 14 Sep 2006 08:29:45 GMT CSeq: 102 ACK User-Agent: CSCO/7 Proxy-Authorization: Digest username="5706",realm="asterisk",uri="sip:90.0.0.62",response="320f4a17a2294bb2ca1335c35b57780d",nonce="55ca09d5",algorithm=MD5 Content-Length: 0 [Sep 14 09:29:46] 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:29:46] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.0.200:5060;branch=z9hG4bK3c4fb2a8 (58) [Sep 14 09:29:46] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 2: From: "5706" ;tag=000785993d3d00341a5e8a4b-40165fe3 (71) [Sep 14 09:29:46] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 3: To: ;tag=as6798c182 (39) [Sep 14 09:29:46] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 4: Call-ID: 00078599-3d3d001c-41be5986-411c43dc@192.168.0.200 (58) [Sep 14 09:29:46] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 5: Date: Thu, 14 Sep 2006 08:29:45 GMT (35) [Sep 14 09:29:46] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 6: CSeq: 102 ACK (13) [Sep 14 09:29:46] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 7: User-Agent: CSCO/7 (18) [Sep 14 09:29:46] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 8: Proxy-Authorization: Digest username="5706",realm="asterisk",uri="sip:90.0.0.62",response="320f4a17a2294bb2ca1335c35b57780d",nonce="55ca09d5",algorithm=MD5 (155) [Sep 14 09:29:46] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 9: Content-Length: 0 (17) [Sep 14 09:29:46] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 10: (0) --- (10 headers 0 lines)--- [Sep 14 09:29:46] DEBUG[15727]: chan_sip.c:14065 handle_request: **** Received ACK (6) - Command in SIP ACK [Sep 14 09:29:46] DEBUG[15727]: chan_sip.c:2002 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #1941 [Sep 14 09:29:46] DEBUG[15727]: chan_sip.c:2012 __sip_ack: Stopping retransmission on '00078599-3d3d001c-41be5986-411c43dc@192.168.0.200' of Response 102: Match Not Found 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=z9hG4bK56ddfc1c;rport=5060 Contact: To: ;tag=1e3b554a From: "5706";tag=as07e64d56 Call-ID: 6b20c5883f43556055c24c6f0af4e2f3@90.0.0.62 CSeq: 102 INVITE User-Agent: X-Lite release 1002tx stamp 29712 Content-Length: 0 [Sep 14 09:29:47] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 0: SIP/2.0 180 Ringing (19) [Sep 14 09:29:47] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 1: Via: SIP/2.0/UDP 90.0.0.62:5060;branch=z9hG4bK56ddfc1c;rport=5060 (65) [Sep 14 09:29:47] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 2: Contact: (65) [Sep 14 09:29:47] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 3: To: ;tag=1e3b554a (73) [Sep 14 09:29:47] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 4: From: "5706";tag=as07e64d56 (56) [Sep 14 09:29:47] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 5: Call-ID: 6b20c5883f43556055c24c6f0af4e2f3@90.0.0.62 (51) [Sep 14 09:29:47] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 6: CSeq: 102 INVITE (16) [Sep 14 09:29:47] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 7: User-Agent: X-Lite release 1002tx stamp 29712 (45) [Sep 14 09:29:47] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 8: Content-Length: 0 (17) [Sep 14 09:29:47] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 9: (0) --- (9 headers 0 lines)--- [Sep 14 09:29:47] DEBUG[15727]: chan_sip.c:2045 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #1942 - INVITE (got response) [Sep 14 09:29:47] DEBUG[15727]: chan_sip.c:2054 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '6b20c5883f43556055c24c6f0af4e2f3@90.0.0.62' Request 102: Found [Sep 14 09:29:47] DEBUG[15727]: chan_sip.c:11221 handle_response_invite: SIP response 180 to standard invite [Sep 14 09:29:47] DEBUG[15727]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/5710-09542610 -- SIP/5710-09542610 is ringing [Sep 14 09:29:47] DEBUG[15718]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5710 [Sep 14 09:29:47] DEBUG[23040]: rtp.c:1401 ast_rtp_early_bridge: Channel 'Local/5710@from-sip-d305,2' has no RTP, not doing anything [Sep 14 09:29:47] DEBUG[23036]: channel.c:3618 ast_generic_bridge: Got a FRAME_CONTROL (3) frame on channel Local/5710@from-sip-d305,1 [Sep 14 09:29:47] DEBUG[23036]: channel.c:3895 ast_channel_bridge: Bridge stops bridging channels SIP/5706-0953cc70 and Local/5710@from-sip-d305,1 [Sep 14 09:29:47] DEBUG[23036]: channel.c:2264 ast_indicate_data: Driver for channel 'SIP/5706-0953cc70' does not support indication 3, emulating it [Sep 14 09:29:47] DEBUG[23036]: channel.c:2638 set_format: Set channel SIP/5706-0953cc70 to write format slin [Sep 14 09:29:47] DEBUG[23036]: channel.c:1845 ast_settimeout: Scheduling timer at 160 sample intervals [Sep 14 09:29:47] DEBUG[15718]: chan_sip.c:14652 sip_devicestate: Checking device state for peer 5710 [Sep 14 09:29:47] DEBUG[15718]: devicestate.c:287 do_state_change: Changing state for SIP/5710 - state 1 (Not in use) [Sep 14 09:29:47] DEBUG[23044]: 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:29:47] DEBUG[23036]: channel.c:2162 __ast_read: Generator got voice, switching to phase locked mode [Sep 14 09:29:47] DEBUG[23036]: channel.c:1845 ast_settimeout: Scheduling timer at 0 sample intervals [Sep 14 09:29:47] DEBUG[23036]: rtp.c:2518 ast_rtp_write: Ooh, format changed from unknown to ulaw [Sep 14 09:29:47] DEBUG[23040]: channel.c:1436 queue_frame_to_spies: Triggering queue flush for spy 'MixMonitor' on 'Local/5710@from-sip-d305,2' [Sep 14 09:29:47] DEBUG[23040]: channel.c:1436 queue_frame_to_spies: Triggering queue flush for spy 'MixMonitor' on 'Local/5710@from-sip-d305,2' [Sep 14 09:29:48] DEBUG[23040]: channel.c:1436 queue_frame_to_spies: Triggering queue flush for spy 'MixMonitor' on 'Local/5710@from-sip-d305,2' [Sep 14 09:29:48] DEBUG[23040]: channel.c:1436 queue_frame_to_spies: Triggering queue flush for spy 'MixMonitor' on 'Local/5710@from-sip-d305,2' [Sep 14 09:29:49] DEBUG[23040]: channel.c:1436 queue_frame_to_spies: Triggering queue flush for spy 'MixMonitor' on 'Local/5710@from-sip-d305,2' [Sep 14 09:29:49] DEBUG[23040]: channel.c:1436 queue_frame_to_spies: Triggering queue flush for spy 'MixMonitor' on 'Local/5710@from-sip-d305,2' [Sep 14 09:29:50] DEBUG[23040]: channel.c:1436 queue_frame_to_spies: Triggering queue flush for spy 'MixMonitor' on 'Local/5710@from-sip-d305,2' [Sep 14 09:29:50] DEBUG[23040]: channel.c:1436 queue_frame_to_spies: Triggering queue flush for spy 'MixMonitor' on 'Local/5710@from-sip-d305,2' [Sep 14 09:29:50] DEBUG[23040]: 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=z9hG4bK56ddfc1c;rport=5060 Contact: To: ;tag=1e3b554a From: "5706";tag=as07e64d56 Call-ID: 6b20c5883f43556055c24c6f0af4e2f3@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=- 2 2 IN IP4 192.168.0.12 s= c=IN IP4 192.168.0.12 t=0 0 m=audio 36228 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:7E3226E0A7D849C890D37C4A85C4F280 [Sep 14 09:29:50] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 0: SIP/2.0 200 OK (14) [Sep 14 09:29:50] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 1: Via: SIP/2.0/UDP 90.0.0.62:5060;branch=z9hG4bK56ddfc1c;rport=5060 (65) [Sep 14 09:29:50] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 2: Contact: (65) [Sep 14 09:29:50] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 3: To: ;tag=1e3b554a (73) [Sep 14 09:29:50] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 4: From: "5706";tag=as07e64d56 (56) [Sep 14 09:29:50] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 5: Call-ID: 6b20c5883f43556055c24c6f0af4e2f3@90.0.0.62 (51) [Sep 14 09:29:50] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 6: CSeq: 102 INVITE (16) [Sep 14 09:29:50] 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:29:50] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 8: Content-Type: application/sdp (29) [Sep 14 09:29:50] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 9: User-Agent: X-Lite release 1002tx stamp 29712 (45) [Sep 14 09:29:50] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 10: Content-Length: 265 (19) [Sep 14 09:29:50] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 11: (0) [Sep 14 09:29:50] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: v=0 (3) [Sep 14 09:29:50] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: o=- 2 2 IN IP4 192.168.0.12 (27) [Sep 14 09:29:50] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: s= (27) [Sep 14 09:29:50] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: c=IN IP4 192.168.0.12 (21) [Sep 14 09:29:50] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: t=0 0 (5) [Sep 14 09:29:50] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: m=audio 36228 RTP/AVP 0 97 101 (30) [Sep 14 09:29:50] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: a=fmtp:101 0-15 (15) [Sep 14 09:29:50] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: a=rtpmap:97 iLBC/8000 (21) [Sep 14 09:29:50] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Sep 14 09:29:50] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: a=sendrecv (10) [Sep 14 09:29:50] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: a=x-rtp-session-id:7E3226E0A7D849C890D37C4A85C4F280 (51) --- (11 headers 11 lines)--- [Sep 14 09:29:50] DEBUG[15727]: chan_sip.c:1994 __sip_ack: Acked pending invite 102 [Sep 14 09:29:50] DEBUG[15727]: chan_sip.c:2012 __sip_ack: Stopping retransmission on '6b20c5883f43556055c24c6f0af4e2f3@90.0.0.62' of Request 102: Match Not Found [Sep 14 09:29:50] 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:36228 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:29:50] DEBUG[15727]: chan_sip.c:4877 process_sdp: T38 state changed to 0 on channel SIP/5710-09542610 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:36228 [Sep 14 09:29:50] DEBUG[15727]: chan_sip.c:4947 process_sdp: We're settling with these formats: 0x404 (ulaw|ilbc) [Sep 14 09:29:50] DEBUG[15727]: chan_sip.c:4954 process_sdp: We have an owner, now see if we need to change this call [Sep 14 09:29:50] DEBUG[15727]: chan_sip.c:2879 update_call_counter: Updating call counter for outgoing call [Sep 14 09:29:50] DEBUG[15727]: chan_sip.c:7631 build_route: build_route: Contact hop: list_route: hop: [Sep 14 09:29:50] DEBUG[15727]: chan_sip.c:5378 reqprep: Strict routing enforced for session 6b20c5883f43556055c24c6f0af4e2f3@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=z9hG4bK2b2c20d0;rport From: "5706" ;tag=as07e64d56 To: ;tag=1e3b554a Contact: Call-ID: 6b20c5883f43556055c24c6f0af4e2f3@90.0.0.62 CSeq: 102 ACK User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- [Sep 14 09:29:50] DEBUG[23040]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/5710-09542610 -- SIP/5710-09542610 answered Local/5710@from-sip-d305,2 [Sep 14 09:29:50] DEBUG[23040]: rtp.c:1401 ast_rtp_early_bridge: Channel 'Local/5710@from-sip-d305,2' has no RTP, not doing anything [Sep 14 09:29:50] DEBUG[23036]: channel.c:3618 ast_generic_bridge: Got a FRAME_CONTROL (-1) frame on channel Local/5710@from-sip-d305,1 [Sep 14 09:29:50] DEBUG[23036]: channel.c:3895 ast_channel_bridge: Bridge stops bridging channels SIP/5706-0953cc70 and Local/5710@from-sip-d305,1 [Sep 14 09:29:50] DEBUG[23036]: channel.c:2638 set_format: Set channel SIP/5706-0953cc70 to write format ulaw [Sep 14 09:29:50] DEBUG[23036]: channel.c:1845 ast_settimeout: Scheduling timer at 0 sample intervals [Sep 14 09:29:50] DEBUG[15718]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5710 [Sep 14 09:29:50] DEBUG[15718]: chan_sip.c:14652 sip_devicestate: Checking device state for peer 5710 [Sep 14 09:29:50] DEBUG[15718]: devicestate.c:287 do_state_change: Changing state for SIP/5710 - state 1 (Not in use) [Sep 14 09:29:50] DEBUG[23045]: 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:29:50] DEBUG[23040]: rtp.c:2518 ast_rtp_write: Ooh, format changed from unknown to ulaw [Sep 14 09:29:50] DEBUG[23040]: channel.c:1381 queue_frame_to_spies: Building translator from ulaw to SLINEAR for spies on channel Local/5710@from-sip-d305,2 [Sep 14 09:29:50] DEBUG[23040]: channel.c:3037 ast_channel_masquerade: Planning to masquerade channel SIP/5710-09542610 into the structure of Local/5710@from-sip-d305,1 [Sep 14 09:29:50] DEBUG[23040]: channel.c:3050 ast_channel_masquerade: Done planning to masquerade channel SIP/5710-09542610 into the structure of Local/5710@from-sip-d305,1 [Sep 14 09:29:50] DEBUG[23040]: chan_local.c:284 local_write: Not posting to queue since already masked on 'Local/5710@from-sip-d305,2' [Sep 14 09:29:50] DEBUG[23036]: channel.c:3167 ast_do_masquerade: Actually Masquerading SIP/5710-09542610(6) into the structure of Local/5710@from-sip-d305,1(6) [Sep 14 09:29:50] DEBUG[23036]: channel.c:3179 ast_do_masquerade: Got clone lock for masquerade on 'SIP/5710-09542610' at 0x9546908 [Sep 14 09:29:50] DEBUG[23036]: channel.c:3374 ast_do_masquerade: Putting channel SIP/5710-09542610 in 4/4 formats [Sep 14 09:29:50] DEBUG[23036]: chan_sip.c:3452 sip_fixup: SIP Fixup: New owner for dialogue 6b20c5883f43556055c24c6f0af4e2f3@90.0.0.62: SIP/5710-09542610 (Old parent: Local/5710@from-sip-d305,1) [Sep 14 09:29:50] DEBUG[23036]: channel.c:3409 ast_do_masquerade: Released clone lock on 'Local/5710@from-sip-d305,1' [Sep 14 09:29:50] DEBUG[23036]: channel.c:3419 ast_do_masquerade: Done Masquerading SIP/5710-09542610 (6) -- Packet2Packet bridging SIP/5706-0953cc70 and SIP/5710-09542610 [Sep 14 09:29:50] DEBUG[23040]: channel.c:3596 ast_generic_bridge: Didn't get a frame from channel: Local/5710@from-sip-d305,1 [Sep 14 09:29:50] DEBUG[23040]: channel.c:3895 ast_channel_bridge: Bridge stops bridging channels Local/5710@from-sip-d305,2 and Local/5710@from-sip-d305,1 [Sep 14 09:29:50] DEBUG[23040]: channel.c:1548 ast_hangup: Hanging up zombie 'Local/5710@from-sip-d305,1' [Sep 14 09:29:50] DEBUG[23040]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Local/5710@from-sip-d305,1 [Sep 14 09:29:50] DEBUG[23040]: rtp.c:1401 ast_rtp_early_bridge: Channel 'Local/5710@from-sip-d305,2' has no RTP, not doing anything [Sep 14 09:29:50] DEBUG[23040]: app_dial.c:1631 dial_exec_full: Exiting with DIALSTATUS=ANSWER. [Sep 14 09:29:50] DEBUG[23040]: pbx.c:1684 pbx_extension_helper: Launching 'Set' -- Executing [5710@from-sip:4] Set("Local/5710@from-sip-d305,2", "VMOPT=sb") in new stack [Sep 14 09:29:50] DEBUG[23040]: pbx.c:1605 pbx_substitute_variables_helper_full: Expression result is '0' [Sep 14 09:29:50] DEBUG[23040]: pbx.c:1684 pbx_extension_helper: Launching 'GotoIf' -- Executing [5710@from-sip:5] GotoIf("Local/5710@from-sip-d305,2", "0?CheckVM") in new stack [Sep 14 09:29:50] DEBUG[23040]: pbx.c:5622 pbx_builtin_gotoif: Not taking any branch [Sep 14 09:29:50] DEBUG[23040]: pbx.c:1684 pbx_extension_helper: Launching 'Set' -- Executing [5710@from-sip:6] Set("Local/5710@from-sip-d305,2", "VMOPT=su") in new stack [Sep 14 09:29:50] DEBUG[23040]: pbx.c:1605 pbx_substitute_variables_helper_full: Expression result is '0' [Sep 14 09:29:50] DEBUG[23040]: pbx.c:1684 pbx_extension_helper: Launching 'GotoIf' -- Executing [5710@from-sip:7] GotoIf("Local/5710@from-sip-d305,2", "0?CheckVM") in new stack [Sep 14 09:29:50] DEBUG[23040]: pbx.c:5622 pbx_builtin_gotoif: Not taking any branch [Sep 14 09:29:50] DEBUG[23040]: pbx.c:1684 pbx_extension_helper: Launching 'Hangup' -- Executing [5710@from-sip:8] Hangup("Local/5710@from-sip-d305,2", "") in new stack [Sep 14 09:29:50] DEBUG[23040]: pbx.c:2280 __ast_pbx_run: Spawn extension (from-sip,5710,8) exited non-zero on 'Local/5710@from-sip-d305,2' [Sep 14 09:29:50] DEBUG[23040]: pbx.c:1684 pbx_extension_helper: Launching 'NoOp' -- Executing [h@from-sip:1] NoOp("Local/5710@from-sip-d305,2", "++++ HANGUP FROM-SIP ++++ [ANSWER/16]") in new stack [Sep 14 09:29:50] DEBUG[23040]: pbx.c:1605 pbx_substitute_variables_helper_full: Expression result is '1' [Sep 14 09:29:50] DEBUG[23040]: pbx.c:1684 pbx_extension_helper: Launching 'GotoIf' -- Executing [h@from-sip:2] GotoIf("Local/5710@from-sip-d305,2", "1?end") in new stack -- Goto (from-sip,h,6) [Sep 14 09:29:50] DEBUG[15718]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for Local - 5710@from-sip [Sep 14 09:29:50] DEBUG[15718]: chan_local.c:141 local_devicestate: Checking if extension 5710@from-sip exists (devicestate) [Sep 14 09:29:50] DEBUG[15718]: devicestate.c:287 do_state_change: Changing state for Local/5710@from-sip - state 2 (In use) [Sep 14 09:29:50] DEBUG[23040]: pbx.c:1684 pbx_extension_helper: Launching 'NoOp' -- Executing [h@from-sip:6] NoOp("Local/5710@from-sip-d305,2", "EndOfCall") in new stack [Sep 14 09:29:50] DEBUG[23040]: channel.c:1236 spy_detach: Spy MixMonitor removed from channel Local/5710@from-sip-d305,2 == End MixMonitor Recording Local/5710@from-sip-d305,2 [Sep 14 09:29:50] DEBUG[23046]: 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:29:50] DEBUG[23040]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is '"5706" ' [Sep 14 09:29:50] DEBUG[23040]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is 'Extension5706' [Sep 14 09:29:50] DEBUG[23040]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is 'h' [Sep 14 09:29:50] DEBUG[23040]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is 'from-sip' [Sep 14 09:29:50] DEBUG[23040]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is 'Local/5710@from-sip-d305,2' [Sep 14 09:29:50] DEBUG[23040]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is 'SIP/5710-09542610' [Sep 14 09:29:50] DEBUG[23040]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is 'NoOp' [Sep 14 09:29:50] DEBUG[23040]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is 'EndOfCall' [Sep 14 09:29:50] DEBUG[23040]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is '2006-09-14 09:29:46' [Sep 14 09:29:50] DEBUG[23040]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is '2006-09-14 09:29:46' [Sep 14 09:29:50] DEBUG[23040]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is '2006-09-14 09:29:50' [Sep 14 09:29:50] DEBUG[23040]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is '4' [Sep 14 09:29:50] DEBUG[23040]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is '4' [Sep 14 09:29:50] DEBUG[23040]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is 'ANSWERED' [Sep 14 09:29:50] DEBUG[23040]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' [Sep 14 09:29:50] DEBUG[23040]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is '' [Sep 14 09:29:50] DEBUG[23040]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is '1158222586.6' [Sep 14 09:29:50] DEBUG[23040]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is '' [Sep 14 09:29:50] DEBUG[23040]: channel.c:1543 ast_hangup: Hanging up channel 'Local/5710@from-sip-d305,2' [Sep 14 09:29:50] DEBUG[23040]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Local/5710@from-sip-d305,2 [Sep 14 09:29:50] DEBUG[15718]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for Local - 5710@from-sip [Sep 14 09:29:50] DEBUG[15718]: chan_local.c:141 local_devicestate: Checking if extension 5710@from-sip exists (devicestate) [Sep 14 09:29:50] DEBUG[15718]: devicestate.c:287 do_state_change: Changing state for Local/5710@from-sip - state 1 (Not in use) [Sep 14 09:29:50] DEBUG[23047]: 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. foxtrot*CLI> <-- SIP read from 192.168.0.12:33918: [Sep 14 09:29:57] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 0: (0) [Sep 14 09:29:57] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: (0) --- (0 headers 1 lines)--- 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=z9hG4bK669e17ff From: "5706" ;tag=000785993d3d00341a5e8a4b-40165fe3 To: ;tag=as6798c182 Call-ID: 00078599-3d3d001c-41be5986-411c43dc@192.168.0.200 Date: Thu, 14 Sep 2006 08:29:56 GMT CSeq: 103 INVITE User-Agent: CSCO/7 Contact: Content-Type: application/sdp Content-Length: 241 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="320f4a17a2294bb2ca1335c35b57780d",nonce="55ca09d5",algorithm=MD5 v=0 o=Cisco-SIPUA 9614 3732 IN IP4 192.168.0.200 s=SIP Call c=IN IP4 0.0.0.0 t=0 0 m=audio 23918 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:29:58] 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:29:58] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.0.200:5060;branch=z9hG4bK669e17ff (58) [Sep 14 09:29:58] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 2: From: "5706" ;tag=000785993d3d00341a5e8a4b-40165fe3 (71) [Sep 14 09:29:58] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 3: To: ;tag=as6798c182 (39) [Sep 14 09:29:58] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 4: Call-ID: 00078599-3d3d001c-41be5986-411c43dc@192.168.0.200 (58) [Sep 14 09:29:58] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 5: Date: Thu, 14 Sep 2006 08:29:56 GMT (35) [Sep 14 09:29:58] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 6: CSeq: 103 INVITE (16) [Sep 14 09:29:58] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 7: User-Agent: CSCO/7 (18) [Sep 14 09:29:58] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 8: Contact: (38) [Sep 14 09:29:58] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 9: Content-Type: application/sdp (29) [Sep 14 09:29:58] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 10: Content-Length: 241 (19) [Sep 14 09:29:58] 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:29:58] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 12: Proxy-Authorization: Digest username="5706",realm="asterisk",uri="sip:90.0.0.62",response="320f4a17a2294bb2ca1335c35b57780d",nonce="55ca09d5",algorithm=MD5 (155) [Sep 14 09:29:58] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 13: (0) [Sep 14 09:29:58] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: v=0 (3) [Sep 14 09:29:58] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: o=Cisco-SIPUA 9614 3732 IN IP4 192.168.0.200 (44) [Sep 14 09:29:58] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: s=SIP Call (10) [Sep 14 09:29:58] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: c=IN IP4 0.0.0.0 (16) [Sep 14 09:29:58] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: t=0 0 (5) [Sep 14 09:29:58] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: m=audio 23918 RTP/AVP 0 8 18 101 (32) [Sep 14 09:29:58] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Sep 14 09:29:58] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Sep 14 09:29:58] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: a=rtpmap:18 G729/8000 (21) [Sep 14 09:29:58] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Sep 14 09:29:58] DEBUG[15727]: chan_sip.c:4404 parse_request: Line: a=fmtp:101 0-15 (15) --- (13 headers 11 lines)--- [Sep 14 09:29:58] 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:23918 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:29:58] DEBUG[15727]: chan_sip.c:4877 process_sdp: T38 state changed to 0 on channel SIP/5706-0953cc70 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:23918 [Sep 14 09:29:58] DEBUG[15727]: chan_sip.c:4947 process_sdp: We're settling with these formats: 0x4 (ulaw) [Sep 14 09:29:58] DEBUG[15727]: chan_sip.c:4954 process_sdp: We have an owner, now see if we need to change this call [Sep 14 09:29:58] 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:29:58] DEBUG[15727]: chan_sip.c:12921 handle_request_invite: Got a SIP re-invite for call 00078599-3d3d001c-41be5986-411c43dc@192.168.0.200 [Sep 14 09:29:58] DEBUG[15718]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5706 [Sep 14 09:29:58] DEBUG[15727]: chan_sip.c:13010 handle_request_invite: SIP/5706-0953cc70: This call is UP.... [Sep 14 09:29:58] DEBUG[15727]: chan_sip.c:5847 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True [Sep 14 09:29:58] DEBUG[15727]: chan_sip.c:5848 add_sdp: ** Our prefcodec: 0x0 (nothing) Audio is at 90.0.0.62 port 13938 Adding codec 0x4 (ulaw) to SDP Adding non-codec 0x1 (telephone-event) to SDP [Sep 14 09:29:58] DEBUG[15727]: chan_sip.c:6000 add_sdp: -- Done with adding codecs to SDP [Sep 14 09:29:58] 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=z9hG4bK669e17ff;received=192.168.0.200 From: "5706" ;tag=000785993d3d00341a5e8a4b-40165fe3 To: ;tag=as6798c182 Call-ID: 00078599-3d3d001c-41be5986-411c43dc@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 13938 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:29:58] DEBUG[15727]: chan_sip.c:1909 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #1946 -- Started music on hold, class 'default', on SIP/5710-09542610 [Sep 14 09:29:58] DEBUG[23036]: channel.c:1845 ast_settimeout: Scheduling timer at 160 sample intervals [Sep 14 09:29:58] DEBUG[15718]: chan_sip.c:14652 sip_devicestate: Checking device state for peer 5706 [Sep 14 09:29:58] DEBUG[15718]: devicestate.c:287 do_state_change: Changing state for SIP/5706 - state 8 (On Hold) [Sep 14 09:29:58] DEBUG[23048]: 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:29:58] DEBUG[23036]: channel.c:2162 __ast_read: Generator got voice, switching to phase locked mode [Sep 14 09:29:58] DEBUG[23036]: channel.c:1845 ast_settimeout: Scheduling timer at 0 sample intervals [Sep 14 09:29:58] DEBUG[23036]: res_musiconhold.c:252 ast_moh_files_next: SIP/5710-09542610 Opened file 4 '/var/lib/asterisk/sounds/custom/moh/track03' [Sep 14 09:29:58] DEBUG[23036]: rtp.c:2417 ast_rtp_raw_write: Difference is 59592, ms is 7469 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=z9hG4bK2b68cbf7 From: "5706" ;tag=000785993d3d00341a5e8a4b-40165fe3 To: ;tag=as6798c182 Call-ID: 00078599-3d3d001c-41be5986-411c43dc@192.168.0.200 Date: Thu, 14 Sep 2006 08:29:57 GMT CSeq: 103 ACK User-Agent: CSCO/7 Proxy-Authorization: Digest username="5706",realm="asterisk",uri="sip:90.0.0.62",response="320f4a17a2294bb2ca1335c35b57780d",nonce="55ca09d5",algorithm=MD5 Content-Length: 0 [Sep 14 09:29:58] 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:29:58] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.0.200:5060;branch=z9hG4bK2b68cbf7 (58) [Sep 14 09:29:58] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 2: From: "5706" ;tag=000785993d3d00341a5e8a4b-40165fe3 (71) [Sep 14 09:29:58] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 3: To: ;tag=as6798c182 (39) [Sep 14 09:29:58] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 4: Call-ID: 00078599-3d3d001c-41be5986-411c43dc@192.168.0.200 (58) [Sep 14 09:29:58] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 5: Date: Thu, 14 Sep 2006 08:29:57 GMT (35) [Sep 14 09:29:58] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 6: CSeq: 103 ACK (13) [Sep 14 09:29:58] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 7: User-Agent: CSCO/7 (18) [Sep 14 09:29:58] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 8: Proxy-Authorization: Digest username="5706",realm="asterisk",uri="sip:90.0.0.62",response="320f4a17a2294bb2ca1335c35b57780d",nonce="55ca09d5",algorithm=MD5 (155) [Sep 14 09:29:58] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 9: Content-Length: 0 (17) [Sep 14 09:29:58] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 10: (0) --- (10 headers 0 lines)--- [Sep 14 09:29:58] DEBUG[15727]: chan_sip.c:14065 handle_request: **** Received ACK (6) - Command in SIP ACK [Sep 14 09:29:58] DEBUG[15727]: chan_sip.c:2002 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #1946 [Sep 14 09:29:58] DEBUG[15727]: chan_sip.c:2012 __sip_ack: Stopping retransmission on '00078599-3d3d001c-41be5986-411c43dc@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=z9hG4bK44410ce0 From: ;tag=000785993d3d003329d8f4ca-5afd0f5f To: "07803034440" ;tag=as2a834511 Call-ID: 7ae8c639765f3aa24b51d17c55736f3a@90.0.0.62 Date: Thu, 14 Sep 2006 08:29:57 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:29:58] 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:29:58] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.0.200:5060;branch=z9hG4bK44410ce0 (58) [Sep 14 09:29:58] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 2: From: ;tag=000785993d3d003329d8f4ca-5afd0f5f (73) [Sep 14 09:29:58] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 3: To: "07803034440" ;tag=as2a834511 (60) [Sep 14 09:29:58] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 4: Call-ID: 7ae8c639765f3aa24b51d17c55736f3a@90.0.0.62 (51) [Sep 14 09:29:58] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 5: Date: Thu, 14 Sep 2006 08:29:57 GMT (35) [Sep 14 09:29:58] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 6: CSeq: 102 REFER (15) [Sep 14 09:29:58] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 7: User-Agent: CSCO/7 (18) [Sep 14 09:29:58] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 8: Contact: (38) [Sep 14 09:29:58] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 9: Content-Length: 0 (17) [Sep 14 09:29:58] 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:29:58] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 11: Refer-To: (165) [Sep 14 09:29:58] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 12: Referred-By: (42) [Sep 14 09:29:58] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 13: (0) --- (13 headers 0 lines)--- [Sep 14 09:29:58] DEBUG[15727]: chan_sip.c:14065 handle_request: **** Received REFER (9) - Command in SIP REFER Call 7ae8c639765f3aa24b51d17c55736f3a@90.0.0.62 got a SIP call transfer from callee: (REFER)! [Sep 14 09:29:58] DEBUG[15727]: chan_sip.c:8350 get_refer_info: Attended transfer: Will use Replace-Call-ID : 00078599-3d3d001c-41be5986-411c43dc@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:29:58] DEBUG[15727]: chan_sip.c:13411 handle_request_refer: SIP attended transfer: Transferer channel SIP/5706-094930e0, transferee channel Zap/1-1 [Sep 14 09:29:58] DEBUG[15727]: chan_sip.c:13427 handle_request_refer: Got SIP transfer, applying to bridged peer 'Zap/1-1' [Sep 14 09:29:58] DEBUG[15727]: chan_sip.c:8206 get_sip_pvt_byid_locked: Looking for callid 00078599-3d3d001c-41be5986-411c43dc@192.168.0.200 (fromtag 000785993d3d00341a5e8a4b-40165fe3 totag as6798c182) [Sep 14 09:29:58] DEBUG[15727]: chan_sip.c:8230 get_sip_pvt_byid_locked: Matched INCOMING call - their tag is 000785993d3d00341a5e8a4b-40165fe3 Our tag is as6798c182 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=z9hG4bK44410ce0;received=192.168.0.200 From: ;tag=000785993d3d003329d8f4ca-5afd0f5f To: "07803034440" ;tag=as2a834511 Call-ID: 7ae8c639765f3aa24b51d17c55736f3a@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:29:58] DEBUG[15727]: chan_sip.c:13183 local_attended_transfer: SIP attended transfer: trying to bridge SIP/5706-0953cc70 and Zap/1-1 [Sep 14 09:29:58] DEBUG[15727]: chan_sip.c:12223 attempt_transfer: Sip transfer:-------------------- [Sep 14 09:29:58] DEBUG[15727]: chan_sip.c:12225 attempt_transfer: -- Transferer to PBX channel: SIP/5706-094930e0 State Up [Sep 14 09:29:58] DEBUG[15727]: chan_sip.c:12229 attempt_transfer: -- Transferer to PBX second channel (target): SIP/5706-0953cc70 State Up [Sep 14 09:29:58] DEBUG[15727]: chan_sip.c:12233 attempt_transfer: -- Bridged call to transferee: Zap/1-1 State Up [Sep 14 09:29:58] DEBUG[15727]: chan_sip.c:12237 attempt_transfer: -- Bridged call to transfer target: SIP/5710-09542610 State Up [Sep 14 09:29:58] DEBUG[15727]: chan_sip.c:12240 attempt_transfer: -- END Sip transfer:-------------------- [Sep 14 09:29:58] 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:29:58] DEBUG[15727]: channel.c:2638 set_format: Set channel Zap/1-1 to write format alaw [Sep 14 09:29:58] DEBUG[15727]: channel.c:1845 ast_settimeout: Scheduling timer at 0 sample intervals -- Stopped music on hold on SIP/5710-09542610 [Sep 14 09:29:58] DEBUG[15727]: channel.c:1845 ast_settimeout: Scheduling timer at 0 sample intervals [Sep 14 09:29:58] DEBUG[15727]: chan_sip.c:12279 attempt_transfer: SIP transfer: trying to masquerade Zap/1-1 into SIP/5706-0953cc70 [Sep 14 09:29:58] DEBUG[15727]: channel.c:3037 ast_channel_masquerade: Planning to masquerade channel Zap/1-1 into the structure of SIP/5706-0953cc70 [Sep 14 09:29:58] DEBUG[15727]: channel.c:3050 ast_channel_masquerade: Done planning to masquerade channel Zap/1-1 into the structure of SIP/5706-0953cc70 [Sep 14 09:29:58] DEBUG[15727]: chan_sip.c:12284 attempt_transfer: SIP transfer: Succeeded to masquerade channels. [Sep 14 09:29:58] DEBUG[15727]: chan_sip.c:5378 reqprep: Strict routing enforced for session 7ae8c639765f3aa24b51d17c55736f3a@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=z9hG4bK208c5114;rport From: "07803034440" ;tag=as2a834511 To: ;tag=000785993d3d003329d8f4ca-5afd0f5f Contact: Call-ID: 7ae8c639765f3aa24b51d17c55736f3a@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:29:58] DEBUG[15727]: chan_sip.c:1909 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #1947 [Sep 14 09:29:58] DEBUG[15727]: chan_sip.c:13210 local_attended_transfer: SIP attended transfer: Unlocking channel SIP/5706-0953cc70 [Sep 14 09:29:58] DEBUG[23029]: chan_zap.c:4976 zt_indicate: Requested indication 17 on channel Zap/1-1 [Sep 14 09:29:58] DEBUG[23036]: channel.c:3167 ast_do_masquerade: Actually Masquerading Zap/1-1(6) into the structure of SIP/5706-0953cc70(6) [Sep 14 09:29:58] DEBUG[23036]: channel.c:3179 ast_do_masquerade: Got clone lock for masquerade on 'Zap/1-1' at 0xb7b01a80 [Sep 14 09:29:58] DEBUG[23036]: chan_sip.c:3452 sip_fixup: SIP Fixup: New owner for dialogue 00078599-3d3d001c-41be5986-411c43dc@192.168.0.200: Zap/1-1 (Old parent: Zap/1-1) [Sep 14 09:29:58] DEBUG[23036]: chan_sip.c:3180 sip_hangup: Hangup call Zap/1-1, SIP callid 00078599-3d3d001c-41be5986-411c43dc@192.168.0.200) [Sep 14 09:29:58] DEBUG[23036]: chan_sip.c:3188 sip_hangup: update_call_counter(5706) - decrement call limit counter on hangup [Sep 14 09:29:58] DEBUG[23036]: chan_sip.c:2879 update_call_counter: Updating call counter for incoming call Scheduling destruction of SIP dialog '00078599-3d3d001c-41be5986-411c43dc@192.168.0.200' in 32000 ms (Method: ACK) [Sep 14 09:29:58] DEBUG[23036]: chan_sip.c:5378 reqprep: Strict routing enforced for session 00078599-3d3d001c-41be5986-411c43dc@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=z9hG4bK191e15e5;rport From: ;tag=as6798c182 To: "5706" ;tag=000785993d3d00341a5e8a4b-40165fe3 Contact: Call-ID: 00078599-3d3d001c-41be5986-411c43dc@192.168.0.200 CSeq: 102 BYE User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- [Sep 14 09:29:58] DEBUG[23036]: chan_sip.c:1909 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #1949 [Sep 14 09:29:58] DEBUG[23036]: channel.c:2638 set_format: Set channel Zap/1-1 to write format ulaw [Sep 14 09:29:58] DEBUG[23036]: channel.c:2638 set_format: Set channel Zap/1-1 to read format ulaw [Sep 14 09:29:58] DEBUG[23036]: channel.c:3374 ast_do_masquerade: Putting channel Zap/1-1 in 4/4 formats [Sep 14 09:29:58] DEBUG[23036]: chan_zap.c:3425 zt_fixup: New owner for channel 1 is Zap/1-1 [Sep 14 09:29:58] DEBUG[23036]: chan_zap.c:1424 update_conf: Updated conferencing on 1, with 0 conference users [Sep 14 09:29:58] DEBUG[23036]: chan_zap.c:1424 update_conf: Updated conferencing on 1, with 0 conference users [Sep 14 09:29:58] DEBUG[23036]: channel.c:3409 ast_do_masquerade: Released clone lock on 'SIP/5706-0953cc70' [Sep 14 09:29:58] DEBUG[23036]: channel.c:3419 ast_do_masquerade: Done Masquerading Zap/1-1 (6) [Sep 14 09:29:58] DEBUG[23036]: rtp.c:2949 bridge_p2p_loop: Oooh, something is weird, backing out [Sep 14 09:29:58] DEBUG[23036]: channel.c:2638 set_format: Set channel SIP/5710-09542610 to read format alaw [Sep 14 09:29:58] DEBUG[23036]: channel.c:2638 set_format: Set channel Zap/1-1 to write format alaw [Sep 14 09:29:58] DEBUG[23029]: channel.c:3596 ast_generic_bridge: Didn't get a frame from channel: SIP/5706-0953cc70 [Sep 14 09:29:58] DEBUG[23029]: channel.c:3895 ast_channel_bridge: Bridge stops bridging channels SIP/5706-0953cc70 and SIP/5706-094930e0 [Sep 14 09:29:58] DEBUG[23029]: channel.c:1543 ast_hangup: Hanging up channel 'SIP/5706-094930e0' [Sep 14 09:29:58] DEBUG[23029]: chan_sip.c:3166 sip_hangup: SIP Transfer: Not hanging up right now... Rescheduling hangup for 7ae8c639765f3aa24b51d17c55736f3a@90.0.0.62. Scheduling destruction of SIP dialog '7ae8c639765f3aa24b51d17c55736f3a@90.0.0.62' in 32000 ms (Method: REFER) [Sep 14 09:29:58] DEBUG[23029]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/5706-094930e0 [Sep 14 09:29:58] DEBUG[15718]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5706 [Sep 14 09:29:58] DEBUG[15718]: chan_sip.c:14652 sip_devicestate: Checking device state for peer 5706 [Sep 14 09:29:58] DEBUG[15718]: devicestate.c:287 do_state_change: Changing state for SIP/5706 - state 8 (On Hold) [Sep 14 09:29:58] DEBUG[23029]: rtp.c:1409 ast_rtp_early_bridge: Channel '' has no RTP, not doing anything [Sep 14 09:29:58] DEBUG[23049]: 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:29:58] DEBUG[23029]: app_dial.c:1631 dial_exec_full: Exiting with DIALSTATUS=ANSWER. [Sep 14 09:29:58] DEBUG[23029]: pbx.c:2280 __ast_pbx_run: Spawn extension (isdn10,444606,3) exited non-zero on 'SIP/5706-0953cc70' [Sep 14 09:29:58] DEBUG[23029]: channel.c:1548 ast_hangup: Hanging up zombie 'SIP/5706-0953cc70' [Sep 14 09:29:58] DEBUG[23029]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/5706-0953cc70 [Sep 14 09:29:58] DEBUG[15718]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5706 [Sep 14 09:29:58] DEBUG[15718]: chan_sip.c:14652 sip_devicestate: Checking device state for peer 5706 [Sep 14 09:29:58] DEBUG[15718]: devicestate.c:287 do_state_change: Changing state for SIP/5706 - state 8 (On Hold) [Sep 14 09:29:58] DEBUG[23050]: 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:29:58] DEBUG[23036]: chan_zap.c:4871 my_zt_write: Write returned -1 (Resource temporarily unavailable) on channel 1 [Sep 14 09:29:58] DEBUG[23036]: 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:50635: SIP/2.0 200 OK Via: SIP/2.0/UDP 90.0.0.62:5060;branch=z9hG4bK208c5114;rport From: "07803034440" ;tag=as2a834511 To: ;tag=000785993d3d003329d8f4ca-5afd0f5f Call-ID: 7ae8c639765f3aa24b51d17c55736f3a@90.0.0.62 Date: Thu, 14 Sep 2006 08:29:57 GMT CSeq: 103 NOTIFY Content-Length: 0 [Sep 14 09:29:59] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 0: SIP/2.0 200 OK (14) [Sep 14 09:29:59] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 1: Via: SIP/2.0/UDP 90.0.0.62:5060;branch=z9hG4bK208c5114;rport (60) [Sep 14 09:29:59] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 2: From: "07803034440" ;tag=as2a834511 (62) [Sep 14 09:29:59] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 3: To: ;tag=000785993d3d003329d8f4ca-5afd0f5f (71) [Sep 14 09:29:59] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 4: Call-ID: 7ae8c639765f3aa24b51d17c55736f3a@90.0.0.62 (51) [Sep 14 09:29:59] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 5: Date: Thu, 14 Sep 2006 08:29:57 GMT (35) [Sep 14 09:29:59] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 6: CSeq: 103 NOTIFY (16) [Sep 14 09:29:59] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 7: Content-Length: 0 (17) [Sep 14 09:29:59] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 8: (0) --- (8 headers 0 lines)--- [Sep 14 09:29:59] DEBUG[15727]: chan_sip.c:2002 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #1947 [Sep 14 09:29:59] DEBUG[15727]: chan_sip.c:2012 __sip_ack: Stopping retransmission on '7ae8c639765f3aa24b51d17c55736f3a@90.0.0.62' of Request 103: Match Not Found Really destroying SIP dialog '7ae8c639765f3aa24b51d17c55736f3a@90.0.0.62' Method: REFER [Sep 14 09:29:59] DEBUG[23036]: 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=z9hG4bK191e15e5;rport From: ;tag=as6798c182 To: "5706" ;tag=000785993d3d00341a5e8a4b-40165fe3 Call-ID: 00078599-3d3d001c-41be5986-411c43dc@192.168.0.200 Date: Thu, 14 Sep 2006 08:29:57 GMT CSeq: 102 BYE Server: CSCO/7 Content-Length: 0 [Sep 14 09:29:59] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 0: SIP/2.0 200 OK (14) [Sep 14 09:29:59] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 1: Via: SIP/2.0/UDP 90.0.0.62:5060;branch=z9hG4bK191e15e5;rport (60) [Sep 14 09:29:59] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 2: From: ;tag=as6798c182 (41) [Sep 14 09:29:59] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 3: To: "5706" ;tag=000785993d3d00341a5e8a4b-40165fe3 (69) [Sep 14 09:29:59] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 4: Call-ID: 00078599-3d3d001c-41be5986-411c43dc@192.168.0.200 (58) [Sep 14 09:29:59] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 5: Date: Thu, 14 Sep 2006 08:29:57 GMT (35) [Sep 14 09:29:59] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 6: CSeq: 102 BYE (13) [Sep 14 09:29:59] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 7: Server: CSCO/7 (14) [Sep 14 09:29:59] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 8: Content-Length: 0 (17) [Sep 14 09:29:59] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 9: (0) --- (9 headers 0 lines)--- [Sep 14 09:29:59] DEBUG[15727]: chan_sip.c:2002 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #1949 [Sep 14 09:29:59] DEBUG[15727]: chan_sip.c:2012 __sip_ack: Stopping retransmission on '00078599-3d3d001c-41be5986-411c43dc@192.168.0.200' of Request 102: Match Not Found SIP Response message for INCOMING dialog BYE arrived Really destroying SIP dialog '00078599-3d3d001c-41be5986-411c43dc@192.168.0.200' Method: ACK [Sep 14 09:29:59] DEBUG[23036]: 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:50628: BYE sip:07803034440@90.0.0.62:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.0.200:5060;branch=z9hG4bK6aa71bcc From: ;tag=000785993d3d003329d8f4ca-5afd0f5f To: "07803034440" ;tag=as2a834511 Call-ID: 7ae8c639765f3aa24b51d17c55736f3a@90.0.0.62 Date: Thu, 14 Sep 2006 08:29:57 GMT CSeq: 103 BYE User-Agent: CSCO/7 Content-Length: 0 [Sep 14 09:29:59] 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:29:59] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.0.200:5060;branch=z9hG4bK6aa71bcc (58) [Sep 14 09:29:59] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 2: From: ;tag=000785993d3d003329d8f4ca-5afd0f5f (73) [Sep 14 09:29:59] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 3: To: "07803034440" ;tag=as2a834511 (60) [Sep 14 09:29:59] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 4: Call-ID: 7ae8c639765f3aa24b51d17c55736f3a@90.0.0.62 (51) [Sep 14 09:29:59] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 5: Date: Thu, 14 Sep 2006 08:29:57 GMT (35) [Sep 14 09:29:59] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 6: CSeq: 103 BYE (13) [Sep 14 09:29:59] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 7: User-Agent: CSCO/7 (18) [Sep 14 09:29:59] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 8: Content-Length: 0 (17) [Sep 14 09:29:59] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 9: (0) --- (9 headers 0 lines)--- [Sep 14 09:29:59] DEBUG[15727]: chan_sip.c:4152 sip_alloc: Allocating new SIP dialog for 7ae8c639765f3aa24b51d17c55736f3a@90.0.0.62 - BYE (No RTP) [Sep 14 09:29:59] 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 '7ae8c639765f3aa24b51d17c55736f3a@90.0.0.62' in 32000 ms (Method: BYE) [Sep 14 09:29:59] 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=z9hG4bK6aa71bcc;received=192.168.0.200 From: ;tag=000785993d3d003329d8f4ca-5afd0f5f To: "07803034440" ;tag=as2a834511 Call-ID: 7ae8c639765f3aa24b51d17c55736f3a@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 --- [Sep 14 09:29:59] DEBUG[23036]: chan_zap.c:4871 my_zt_write: Write returned -1 (Resource temporarily unavailable) on channel 1 [Sep 14 09:29:59] DEBUG[23036]: chan_zap.c:4871 my_zt_write: Write returned -1 (Resource temporarily unavailable) on channel 1 [Sep 14 09:29:59] DEBUG[23036]: chan_zap.c:4871 my_zt_write: Write returned -1 (Resource temporarily unavailable) on channel 1 [Sep 14 09:29:59] DEBUG[23036]: chan_zap.c:4871 my_zt_write: Write returned -1 (Resource temporarily unavailable) on channel 1 [Sep 14 09:29:59] DEBUG[23036]: chan_zap.c:4871 my_zt_write: Write returned -1 (Resource temporarily unavailable) on channel 1 [Sep 14 09:29:59] DEBUG[23036]: chan_zap.c:4871 my_zt_write: Write returned -1 (Resource temporarily unavailable) on channel 1 [Sep 14 09:29:59] DEBUG[23036]: chan_zap.c:4871 my_zt_write: Write returned -1 (Resource temporarily unavailable) on channel 1 [Sep 14 09:29:59] DEBUG[23036]: chan_zap.c:4871 my_zt_write: Write returned -1 (Resource temporarily unavailable) on channel 1 [Sep 14 09:29:59] DEBUG[23036]: chan_zap.c:4871 my_zt_write: Write returned -1 (Resource temporarily unavailable) on channel 1 [Sep 14 09:30:00] DEBUG[23036]: chan_sip.c:3932 sip_rtp_read: Oooh, format changed to 1024 [Sep 14 09:30:00] DEBUG[23036]: channel.c:2638 set_format: Set channel SIP/5710-09542610 to read format alaw [Sep 14 09:30:00] DEBUG[23036]: channel.c:2638 set_format: Set channel SIP/5710-09542610 to write format ulaw [Sep 14 09:30:00] DEBUG[23036]: channel.c:2638 set_format: Set channel Zap/1-1 to read format ilbc [Sep 14 09:30:00] DEBUG[23036]: channel.c:2638 set_format: Set channel SIP/5710-09542610 to write format ilbc [Sep 14 09:30:00] DEBUG[23036]: channel.c:2638 set_format: Set channel SIP/5710-09542610 to read format slin [Sep 14 09:30:00] DEBUG[23036]: channel.c:2638 set_format: Set channel Zap/1-1 to write format slin [Sep 14 09:30:00] DEBUG[23036]: rtp.c:2518 ast_rtp_write: Ooh, format changed from ulaw to ilbc [Sep 14 09:30:01] DEBUG[23036]: rtp.c:801 ast_rtcp_read: Got RTCP report of 200 bytes [Sep 14 09:30:04] DEBUG[23036]: rtp.c:801 ast_rtcp_read: Got RTCP report of 200 bytes -- Channel 0/1, span 1 got hangup request [Sep 14 09:30:04] DEBUG[23036]: channel.c:3596 ast_generic_bridge: Didn't get a frame from channel: Zap/1-1 [Sep 14 09:30:04] DEBUG[23036]: channel.c:3895 ast_channel_bridge: Bridge stops bridging channels Zap/1-1 and SIP/5710-09542610 [Sep 14 09:30:04] DEBUG[23036]: channel.c:1543 ast_hangup: Hanging up channel 'SIP/5710-09542610' [Sep 14 09:30:04] DEBUG[23036]: chan_sip.c:3180 sip_hangup: Hangup call SIP/5710-09542610, SIP callid 6b20c5883f43556055c24c6f0af4e2f3@90.0.0.62) [Sep 14 09:30:04] DEBUG[23036]: chan_sip.c:3188 sip_hangup: update_call_counter(5710) - decrement call limit counter on hangup [Sep 14 09:30:04] DEBUG[23036]: chan_sip.c:2879 update_call_counter: Updating call counter for outgoing call Scheduling destruction of SIP dialog '6b20c5883f43556055c24c6f0af4e2f3@90.0.0.62' in 32000 ms (Method: INVITE) [Sep 14 09:30:04] DEBUG[23036]: chan_sip.c:5378 reqprep: Strict routing enforced for session 6b20c5883f43556055c24c6f0af4e2f3@90.0.0.62 set_destination: Parsing for address/port to send to set_destination: set destination to 192.168.0.12, port 33918 Reliably Transmitting (no NAT) to 192.168.0.12:33918: BYE sip:5710@192.168.0.12:33918;rinstance=e4acfadb594edd00 SIP/2.0 Via: SIP/2.0/UDP 90.0.0.62:5060;branch=z9hG4bK15d80552;rport From: "5706" ;tag=as07e64d56 To: ;tag=1e3b554a Contact: Call-ID: 6b20c5883f43556055c24c6f0af4e2f3@90.0.0.62 CSeq: 103 BYE User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- [Sep 14 09:30:04] DEBUG[23036]: chan_sip.c:1909 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #1953 [Sep 14 09:30:04] DEBUG[23036]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/5710-09542610 [Sep 14 09:30:04] DEBUG[23036]: rtp.c:1401 ast_rtp_early_bridge: Channel 'Zap/1-1' has no RTP, not doing anything [Sep 14 09:30:04] DEBUG[15718]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5710 [Sep 14 09:30:04] DEBUG[15718]: chan_sip.c:14652 sip_devicestate: Checking device state for peer 5710 [Sep 14 09:30:04] DEBUG[15718]: devicestate.c:287 do_state_change: Changing state for SIP/5710 - state 1 (Not in use) [Sep 14 09:30:04] DEBUG[23036]: app_dial.c:1631 dial_exec_full: Exiting with DIALSTATUS=ANSWER. [Sep 14 09:30:04] DEBUG[23036]: pbx.c:2280 __ast_pbx_run: Spawn extension (from-sip,5709,2) exited non-zero on 'Zap/1-1' [Sep 14 09:30:04] DEBUG[23036]: 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:30:04] DEBUG[23036]: pbx.c:1605 pbx_substitute_variables_helper_full: Expression result is '1' [Sep 14 09:30:04] DEBUG[23036]: 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:30:04] DEBUG[23036]: pbx.c:1684 pbx_extension_helper: Launching 'NoOp' -- Executing [h@from-sip:6] NoOp("Zap/1-1", "EndOfCall") in new stack [Sep 14 09:30:04] DEBUG[23036]: channel.c:1236 spy_detach: Spy MixMonitor removed from channel Zap/1-1 == End MixMonitor Recording Zap/1-1 [Sep 14 09:30:04] DEBUG[23054]: 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:30:04] DEBUG[23036]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is '07803034440' [Sep 14 09:30:04] DEBUG[23036]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is '07803034440' [Sep 14 09:30:04] DEBUG[23036]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is 'h' [Sep 14 09:30:04] DEBUG[23036]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is 'from-sip' [Sep 14 09:30:04] DEBUG[23036]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is 'SIP/5706-0953cc70' [Sep 14 09:30:04] DEBUG[23036]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is 'Local/5710@from-sip-d305,1' [Sep 14 09:30:04] DEBUG[23036]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is 'NoOp' [Sep 14 09:30:04] DEBUG[23036]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is 'EndOfCall' [Sep 14 09:30:04] DEBUG[23036]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is '2006-09-14 09:29:46' [Sep 14 09:30:04] DEBUG[23036]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is '2006-09-14 09:29:46' [Sep 14 09:30:04] DEBUG[23036]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is '2006-09-14 09:30:04' [Sep 14 09:30:04] DEBUG[23036]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is '18' [Sep 14 09:30:04] DEBUG[23036]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is '18' [Sep 14 09:30:04] DEBUG[23036]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is 'ANSWERED' [Sep 14 09:30:04] DEBUG[23036]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' [Sep 14 09:30:04] DEBUG[23036]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is '' [Sep 14 09:30:04] DEBUG[23036]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is '1158222586.4' [Sep 14 09:30:04] DEBUG[23036]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is '' [Sep 14 09:30:04] DEBUG[23036]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is '07803034440' [Sep 14 09:30:04] DEBUG[23036]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is '07803034440' [Sep 14 09:30:04] DEBUG[23036]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is 'h' [Sep 14 09:30:04] DEBUG[23036]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is 'from-sip' [Sep 14 09:30:04] DEBUG[23036]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is 'Zap/1-1' [Sep 14 09:30:04] DEBUG[23036]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is 'SIP/5706-094930e0' [Sep 14 09:30:04] DEBUG[23036]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is 'NoOp' [Sep 14 09:30:04] DEBUG[23036]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is 'EndOfCall' [Sep 14 09:30:04] DEBUG[23036]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is '2006-09-14 09:29:28' [Sep 14 09:30:04] DEBUG[23036]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is '2006-09-14 09:29:28' [Sep 14 09:30:04] DEBUG[23036]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is '2006-09-14 09:30:04' [Sep 14 09:30:04] DEBUG[23036]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is '36' [Sep 14 09:30:04] DEBUG[23036]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is '36' [Sep 14 09:30:04] DEBUG[23036]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is 'ANSWERED' [Sep 14 09:30:04] DEBUG[23036]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' [Sep 14 09:30:04] DEBUG[23036]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is '' [Sep 14 09:30:04] DEBUG[23036]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is '1158222568.2' [Sep 14 09:30:04] DEBUG[23036]: pbx.c:1538 pbx_substitute_variables_helper_full: Function result is '' [Sep 14 09:30:04] DEBUG[23036]: channel.c:1543 ast_hangup: Hanging up channel 'Zap/1-1' [Sep 14 09:30:04] DEBUG[23036]: chan_zap.c:2413 zt_hangup: zt_hangup(Zap/1-1) [Sep 14 09:30:04] DEBUG[23036]: chan_zap.c:2957 zt_setoption: Set option AUDIO MODE, value: ON(1) on Zap/1-1 [Sep 14 09:30:04] DEBUG[23036]: chan_zap.c:2446 zt_hangup: Hangup: channel: 1 index = 0, normal = 13, callwait = -1, thirdcall = -1 [Sep 14 09:30:04] DEBUG[23036]: chan_zap.c:2600 zt_hangup: Not yet hungup... Calling hangup once with icause, and clearing call [Sep 14 09:30:04] DEBUG[23036]: chan_zap.c:1487 zt_disable_ec: disabled echo cancellation on channel 1 [Sep 14 09:30:04] DEBUG[23036]: chan_zap.c:2874 zt_setoption: Set option TDD MODE, value: OFF(0) on Zap/1-1 [Sep 14 09:30:04] DEBUG[23036]: chan_zap.c:1424 update_conf: Updated conferencing on 1, with 0 conference users [Sep 14 09:30:04] DEBUG[23036]: chan_zap.c:2953 zt_setoption: Set option AUDIO MODE, value: OFF(0) on Zap/1-1 [Sep 14 09:30:04] DEBUG[23036]: chan_zap.c:1487 zt_disable_ec: disabled echo cancellation on channel 1 -- Hungup 'Zap/1-1' [Sep 14 09:30:04] DEBUG[23036]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Zap/1-1 [Sep 14 09:30:04] DEBUG[15718]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for Zap - 1 [Sep 14 09:30:04] DEBUG[15718]: devicestate.c:287 do_state_change: Changing state for Zap/1 - state 0 (Unknown) [Sep 14 09:30:04] DEBUG[23055]: 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. 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=z9hG4bK15d80552;rport=5060 Contact: To: ;tag=1e3b554a From: "5706";tag=as07e64d56 Call-ID: 6b20c5883f43556055c24c6f0af4e2f3@90.0.0.62 CSeq: 103 BYE User-Agent: X-Lite release 1002tx stamp 29712 Content-Length: 0 [Sep 14 09:30:05] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 0: SIP/2.0 200 OK (14) [Sep 14 09:30:05] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 1: Via: SIP/2.0/UDP 90.0.0.62:5060;branch=z9hG4bK15d80552;rport=5060 (65) [Sep 14 09:30:05] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 2: Contact: (65) [Sep 14 09:30:05] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 3: To: ;tag=1e3b554a (73) [Sep 14 09:30:05] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 4: From: "5706";tag=as07e64d56 (56) [Sep 14 09:30:05] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 5: Call-ID: 6b20c5883f43556055c24c6f0af4e2f3@90.0.0.62 (51) [Sep 14 09:30:05] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 6: CSeq: 103 BYE (13) [Sep 14 09:30:05] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 7: User-Agent: X-Lite release 1002tx stamp 29712 (45) [Sep 14 09:30:05] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 8: Content-Length: 0 (17) [Sep 14 09:30:05] DEBUG[15727]: chan_sip.c:4372 parse_request: Header 9: (0) --- (9 headers 0 lines)--- [Sep 14 09:30:05] DEBUG[15727]: chan_sip.c:2002 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #1953 [Sep 14 09:30:05] DEBUG[15727]: chan_sip.c:2012 __sip_ack: Stopping retransmission on '6b20c5883f43556055c24c6f0af4e2f3@90.0.0.62' of Request 103: Match Not Found Really destroying SIP dialog '6b20c5883f43556055c24c6f0af4e2f3@90.0.0.62' Method: INVITE foxtrot*CLI>