[Sep 21 16:02:10] Asterisk SVN-branch-1.4-r218798, Copyright (C) 1999 - 2008 Digium, Inc. and others. [Sep 21 16:02:10] Created by Mark Spencer [Sep 21 16:02:10] Asterisk comes with ABSOLUTELY NO WARRANTY; type 'core show warranty' for details. [Sep 21 16:02:10] This is free software, with components licensed under the GNU General Public [Sep 21 16:02:10] License version 2 and other licenses; you are welcome to redistribute it under [Sep 21 16:02:10] certain conditions. Type 'core show license' for details. [Sep 21 16:02:10] ========================================================================= [Sep 21 16:02:15] Asterisk Ready. SIP Debugging enabled <--- SIP read from 10.4.127.199:5060 ---> INVITE sip:5678@10.4.119.245 SIP/2.0 Via: SIP/2.0/UDP 10.4.127.199;branch=z9hG4bK6a390f751 Content-Length: 296 To: sip:5678@10.4.119.245 From: sip:4567@10.4.119.245;tag=f6cd0ba5dded5ef Call-ID: 2a18d5e0791e956a19adf1ee11461c08@10.4.119.245 CSeq: 488449818 INVITE Supported: timer Min-SE: 1800 Session-Expires: 3600 Allow: INVITE, ACK, BYE, CANCEL, REFER, NOTIFY Content-Type: application/sdp Contact: sip:4567@10.4.127.199 Supported: replaces User-Agent: MxSipApp/5.0.25.189 v=0 o=MxSIP 1198078906162342458 394531713152601134 IN IP4 10.4.127.199 s=- c=IN IP4 10.4.127.199 t=0 0 a=sendrecv m=audio 5004 RTP/AVP 0 18 4 8 96 13 a=rtpmap:0 PCMU/8000 a=rtpmap:18 G729/8000 a=rtpmap:4 G723/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:96 telephone-event/8000 a=fmtp:96 0-15 <-------------> [Sep 21 16:02:37] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 0: INVITE sip:5678@10.4.119.245 SIP/2.0 (36) [Sep 21 16:02:37] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 1: Via: SIP/2.0/UDP 10.4.127.199;branch=z9hG4bK6a390f751 (53) [Sep 21 16:02:37] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 2: Content-Length: 296 (19) [Sep 21 16:02:37] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 3: To: sip:5678@10.4.119.245 (25) [Sep 21 16:02:37] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 4: From: sip:4567@10.4.119.245;tag=f6cd0ba5dded5ef (47) [Sep 21 16:02:37] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 5: Call-ID: 2a18d5e0791e956a19adf1ee11461c08@10.4.119.245 (54) [Sep 21 16:02:37] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 6: CSeq: 488449818 INVITE (22) [Sep 21 16:02:37] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 7: Supported: timer (16) [Sep 21 16:02:37] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 8: Min-SE: 1800 (12) [Sep 21 16:02:37] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 9: Session-Expires: 3600 (21) [Sep 21 16:02:37] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 10: Allow: INVITE, ACK, BYE, CANCEL, REFER, NOTIFY (46) [Sep 21 16:02:37] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 11: Content-Type: application/sdp (29) [Sep 21 16:02:37] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 12: Contact: sip:4567@10.4.127.199 (30) [Sep 21 16:02:37] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 13: Supported: replaces (19) [Sep 21 16:02:37] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 14: User-Agent: MxSipApp/5.0.25.189 (32) [Sep 21 16:02:37] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 15: (0) [Sep 21 16:02:37] DEBUG[30876]: chan_sip.c:5064 parse_request: Line: v=0 (3) [Sep 21 16:02:37] DEBUG[30876]: chan_sip.c:5064 parse_request: Line: o=MxSIP 1198078906162342458 394531713152601134 IN IP4 10.4.127.199 (66) [Sep 21 16:02:37] DEBUG[30876]: chan_sip.c:5064 parse_request: Line: s=- (3) [Sep 21 16:02:37] DEBUG[30876]: chan_sip.c:5064 parse_request: Line: c=IN IP4 10.4.127.199 (21) [Sep 21 16:02:37] DEBUG[30876]: chan_sip.c:5064 parse_request: Line: t=0 0 (5) [Sep 21 16:02:37] DEBUG[30876]: chan_sip.c:5064 parse_request: Line: a=sendrecv (10) [Sep 21 16:02:37] DEBUG[30876]: chan_sip.c:5064 parse_request: Line: m=audio 5004 RTP/AVP 0 18 4 8 96 13 (35) [Sep 21 16:02:37] DEBUG[30876]: chan_sip.c:5064 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Sep 21 16:02:37] DEBUG[30876]: chan_sip.c:5064 parse_request: Line: a=rtpmap:18 G729/8000 (21) [Sep 21 16:02:37] DEBUG[30876]: chan_sip.c:5064 parse_request: Line: a=rtpmap:4 G723/8000 (20) [Sep 21 16:02:37] DEBUG[30876]: chan_sip.c:5064 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Sep 21 16:02:37] DEBUG[30876]: chan_sip.c:5064 parse_request: Line: a=rtpmap:96 telephone-event/8000 (32) [Sep 21 16:02:37] DEBUG[30876]: chan_sip.c:5064 parse_request: Line: a=fmtp:96 0-15 (14) [Sep 21 16:02:37] --- (15 headers 13 lines) --- [Sep 21 16:02:37] DEBUG[30876]: chan_sip.c:4817 find_call: = No match Their Call ID: 53f82b9386d2da9f6ecafa6943caa819@10.4.119.245 Their Tag a1784163fbd5d63 Our tag: as3ad0cc96 [Sep 21 16:02:37] DEBUG[30876]: chan_sip.c:4817 find_call: = No match Their Call ID: 213609c3623fd0f952623d3115e6f5a6@10.4.119.245 Their Tag f569efee6218262 Our tag: as38f22591 [Sep 21 16:02:37] DEBUG[30876]: chan_sip.c:2881 do_setnat: Setting NAT on RTP to Off [Sep 21 16:02:37] DEBUG[30876]: chan_sip.c:2891 do_setnat: Setting NAT on UDPTL to Off [Sep 21 16:02:37] DEBUG[30876]: chan_sip.c:4761 sip_alloc: Allocating new SIP dialog for 2a18d5e0791e956a19adf1ee11461c08@10.4.119.245 - INVITE (With RTP) [Sep 21 16:02:37] DEBUG[30876]: chan_sip.c:16306 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Sep 21 16:02:37] DEBUG[30876]: chan_sip.c:1753 parse_sip_options: Begin: parsing SIP "Supported: timer" [Sep 21 16:02:37] DEBUG[30876]: chan_sip.c:1761 parse_sip_options: Found SIP option: -timer- [Sep 21 16:02:37] DEBUG[30876]: chan_sip.c:1767 parse_sip_options: Matched SIP option: timer [Sep 21 16:02:37] Sending to 10.4.127.199 : 5060 (no NAT) [Sep 21 16:02:37] Using INVITE request as basis request - 2a18d5e0791e956a19adf1ee11461c08@10.4.119.245 [Sep 21 16:02:37] DEBUG[30876]: chan_sip.c:2881 do_setnat: Setting NAT on RTP to On [Sep 21 16:02:37] DEBUG[30876]: chan_sip.c:2891 do_setnat: Setting NAT on UDPTL to On [Sep 21 16:02:37] Found user '4567' [Sep 21 16:02:37] Found RTP audio format 0 [Sep 21 16:02:37] Found RTP audio format 18 [Sep 21 16:02:37] Found RTP audio format 4 [Sep 21 16:02:37] Found RTP audio format 8 [Sep 21 16:02:37] Found RTP audio format 96 [Sep 21 16:02:37] Found RTP audio format 13 [Sep 21 16:02:37] DEBUG[30876]: chan_sip.c:5505 process_sdp: Peer doesn't provide T.38 UDPTL [Sep 21 16:02:37] Peer audio RTP is at port 10.4.127.199:5004 [Sep 21 16:02:37] Found audio description format PCMU for ID 0 [Sep 21 16:02:37] Found audio description format G729 for ID 18 [Sep 21 16:02:37] Found audio description format G723 for ID 4 [Sep 21 16:02:37] Found audio description format PCMA for ID 8 [Sep 21 16:02:37] Found audio description format telephone-event for ID 96 [Sep 21 16:02:37] Got unsupported a:fmtp in SDP offer [Sep 21 16:02:37] DEBUG[30876]: chan_sip.c:5778 process_sdp: T38 state changed to 0 on channel [Sep 21 16:02:37] Capabilities: us - 0x804 (ulaw|g726), peer - audio=0x10d (g723|ulaw|alaw|g729)/video=0x0 (nothing), combined - 0x4 (ulaw) [Sep 21 16:02:37] Non-codec capabilities (dtmf): us - 0x0 (nothing), peer - 0x3 (telephone-event|CN), combined - 0x0 (nothing) [Sep 21 16:02:37] Peer audio RTP is at port 10.4.127.199:5004 [Sep 21 16:02:37] DEBUG[30876]: chan_sip.c:5858 process_sdp: We're settling with these formats: 0x4 (ulaw) [Sep 21 16:02:37] DEBUG[30876]: chan_sip.c:14946 handle_request_invite: Checking SIP call limits for device 4567 [Sep 21 16:02:37] DEBUG[30876]: chan_sip.c:3366 update_call_counter: Updating call counter for incoming call [Sep 21 16:02:37] Looking for 5678 in default (domain 10.4.119.245) [Sep 21 16:02:37] DEBUG[30876]: chan_sip.c:4228 sip_new: *** Our native formats are 0x4 (ulaw) [Sep 21 16:02:37] DEBUG[30876]: chan_sip.c:4229 sip_new: *** Joint capabilities are 0x4 (ulaw) [Sep 21 16:02:37] DEBUG[30876]: chan_sip.c:4230 sip_new: *** Our capabilities are 0x804 (ulaw|g726) [Sep 21 16:02:37] DEBUG[30876]: chan_sip.c:4231 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Sep 21 16:02:37] DEBUG[30876]: chan_sip.c:4254 sip_new: This channel will not be able to handle video. [Sep 21 16:02:37] DEBUG[30876]: chan_sip.c:8784 build_route: build_route: Contact hop: sip:4567@10.4.127.199 [Sep 21 16:02:37] list_route: hop: [Sep 21 16:02:37] DEBUG[30876]: chan_sip.c:15045 handle_request_invite: SIP/4567-091fc8e8: New call is still down.... Trying... [Sep 21 16:02:37] <--- Transmitting (NAT) to 10.4.127.199:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.4.127.199;branch=z9hG4bK6a390f751;received=10.4.127.199 From: sip:4567@10.4.119.245;tag=f6cd0ba5dded5ef To: sip:5678@10.4.119.245 Call-ID: 2a18d5e0791e956a19adf1ee11461c08@10.4.119.245 CSeq: 488449818 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces Contact: Content-Length: 0 <------------> [Sep 21 16:02:37] DEBUG[30876]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/4567 [Sep 21 16:02:37] DEBUG[30863]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 4567 [Sep 21 16:02:37] DEBUG[30863]: chan_sip.c:17080 sip_devicestate: Checking device state for peer 4567 [Sep 21 16:02:37] DEBUG[30863]: devicestate.c:287 do_state_change: Changing state for SIP/4567 - state 1 (Not in use) [Sep 21 16:02:37] DEBUG[30875]: app_queue.c:675 handle_statechange: Device 'SIP/4567' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Sep 21 16:02:37] DEBUG[30893]: pbx.c:1843 pbx_extension_helper: Launching 'Dial' [Sep 21 16:02:37] -- Executing [5678@default:1] Dial("SIP/4567-091fc8e8", "SIP/5678|20") in new stack [Sep 21 16:02:37] DEBUG[30893]: chan_sip.c:17156 sip_request_call: Asked to create a SIP channel with formats: 0x4 (ulaw) [Sep 21 16:02:37] DEBUG[30893]: chan_sip.c:4761 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Sep 21 16:02:37] DEBUG[30893]: chan_sip.c:2927 create_addr_from_peer: Our T38 capability (3872) [Sep 21 16:02:37] DEBUG[30893]: chan_sip.c:2881 do_setnat: Setting NAT on RTP to On [Sep 21 16:02:37] DEBUG[30893]: chan_sip.c:2891 do_setnat: Setting NAT on UDPTL to On [Sep 21 16:02:37] DEBUG[30893]: chan_sip.c:4228 sip_new: *** Our native formats are 0x4 (ulaw) [Sep 21 16:02:37] DEBUG[30893]: chan_sip.c:4229 sip_new: *** Joint capabilities are 0x0 (nothing) [Sep 21 16:02:37] DEBUG[30893]: chan_sip.c:4230 sip_new: *** Our capabilities are 0x804 (ulaw|g726) [Sep 21 16:02:37] DEBUG[30893]: chan_sip.c:4231 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Sep 21 16:02:37] DEBUG[30893]: chan_sip.c:4233 sip_new: *** Our preferred formats from the incoming channel are 0x4 (ulaw) [Sep 21 16:02:37] DEBUG[30893]: chan_sip.c:4254 sip_new: This channel will not be able to handle video. [Sep 21 16:02:37] DEBUG[30893]: rtp.c:1688 ast_rtp_make_compatible: Seeded SDP of 'SIP/5678-09201800' with that of 'SIP/4567-091fc8e8' [Sep 21 16:02:37] DEBUG[30893]: channel.c:3716 ast_channel_inherit_variables: Not copying variable DIALEDTIME. [Sep 21 16:02:37] DEBUG[30893]: channel.c:3716 ast_channel_inherit_variables: Not copying variable ANSWEREDTIME. [Sep 21 16:02:37] DEBUG[30893]: channel.c:3716 ast_channel_inherit_variables: Not copying variable DIALEDPEERNAME. [Sep 21 16:02:37] DEBUG[30893]: channel.c:3716 ast_channel_inherit_variables: Not copying variable DIALEDPEERNUMBER. [Sep 21 16:02:37] DEBUG[30893]: channel.c:3716 ast_channel_inherit_variables: Not copying variable DIALSTATUS. [Sep 21 16:02:37] DEBUG[30893]: channel.c:3716 ast_channel_inherit_variables: Not copying variable SIPCALLID. [Sep 21 16:02:37] DEBUG[30893]: channel.c:3716 ast_channel_inherit_variables: Not copying variable SIPUSERAGENT. [Sep 21 16:02:37] DEBUG[30893]: channel.c:3716 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [Sep 21 16:02:37] DEBUG[30893]: channel.c:3716 ast_channel_inherit_variables: Not copying variable SIPURI. [Sep 21 16:02:37] DEBUG[30893]: chan_sip.c:3159 sip_call: Outgoing Call for 5678 [Sep 21 16:02:37] DEBUG[30893]: chan_sip.c:3366 update_call_counter: Updating call counter for outgoing call [Sep 21 16:02:37] DEBUG[30893]: chan_sip.c:3174 sip_call: Our T38 capability (3872), joint T38 capability (3872) [Sep 21 16:02:37] DEBUG[30893]: chan_sip.c:6826 add_sdp: ** Our capability: 0x804 (ulaw|g726) Video flag: False [Sep 21 16:02:37] DEBUG[30893]: chan_sip.c:6827 add_sdp: ** Our prefcodec: 0x4 (ulaw) [Sep 21 16:02:37] Audio is at 10.4.119.245 port 11974 [Sep 21 16:02:37] Adding codec 0x4 (ulaw) to SDP [Sep 21 16:02:37] Adding codec 0x800 (g726) to SDP [Sep 21 16:02:37] DEBUG[30893]: chan_sip.c:6944 add_sdp: -- Done with adding codecs to SDP [Sep 21 16:02:37] DEBUG[30893]: channel.c:2509 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Sep 21 16:02:37] DEBUG[30893]: chan_sip.c:7053 add_sdp: Done building SDP. Settling with this capability: 0x804 (ulaw|g726) [Sep 21 16:02:37] DEBUG[30893]: chan_sip.c:5028 parse_request: Header 0: INVITE sip:5678@10.4.127.199 SIP/2.0 (36) [Sep 21 16:02:37] DEBUG[30893]: chan_sip.c:5028 parse_request: Header 1: Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK5ef6f37d;rport (63) [Sep 21 16:02:37] DEBUG[30893]: chan_sip.c:5028 parse_request: Header 2: From: "4567" ;tag=as292fe2e3 (51) [Sep 21 16:02:37] DEBUG[30893]: chan_sip.c:5028 parse_request: Header 3: To: (27) [Sep 21 16:02:37] DEBUG[30893]: chan_sip.c:5028 parse_request: Header 4: Contact: (32) [Sep 21 16:02:38] DEBUG[30893]: chan_sip.c:5028 parse_request: Header 5: Call-ID: 092075a17e0d80a74dbdfbc71ad3cf4c@10.4.119.245 (54) [Sep 21 16:02:38] DEBUG[30893]: chan_sip.c:5028 parse_request: Header 6: CSeq: 102 INVITE (16) [Sep 21 16:02:38] DEBUG[30893]: chan_sip.c:5028 parse_request: Header 7: User-Agent: Asterisk PBX (24) [Sep 21 16:02:38] DEBUG[30893]: chan_sip.c:5028 parse_request: Header 8: Max-Forwards: 70 (16) [Sep 21 16:02:38] DEBUG[30893]: chan_sip.c:5028 parse_request: Header 9: Date: Mon, 21 Sep 2009 20:02:37 GMT (35) [Sep 21 16:02:38] DEBUG[30893]: chan_sip.c:5028 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO (72) [Sep 21 16:02:38] DEBUG[30893]: chan_sip.c:5028 parse_request: Header 11: Supported: replaces (19) [Sep 21 16:02:38] DEBUG[30893]: chan_sip.c:5028 parse_request: Header 12: Content-Type: application/sdp (29) [Sep 21 16:02:38] DEBUG[30893]: chan_sip.c:5028 parse_request: Header 13: Content-Length: 215 (19) [Sep 21 16:02:38] DEBUG[30893]: chan_sip.c:5028 parse_request: Header 14: (0) [Sep 21 16:02:38] DEBUG[30893]: chan_sip.c:5064 parse_request: Line: v=0 (3) [Sep 21 16:02:38] DEBUG[30893]: chan_sip.c:5064 parse_request: Line: o=root 30858 30858 IN IP4 10.4.119.245 (38) [Sep 21 16:02:38] DEBUG[30893]: chan_sip.c:5064 parse_request: Line: s=session (9) [Sep 21 16:02:38] DEBUG[30893]: chan_sip.c:5064 parse_request: Line: c=IN IP4 10.4.119.245 (21) [Sep 21 16:02:38] DEBUG[30893]: chan_sip.c:5064 parse_request: Line: t=0 0 (5) [Sep 21 16:02:38] DEBUG[30893]: chan_sip.c:5064 parse_request: Line: m=audio 11974 RTP/AVP 0 111 (27) [Sep 21 16:02:38] DEBUG[30893]: chan_sip.c:5064 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Sep 21 16:02:38] DEBUG[30893]: chan_sip.c:5064 parse_request: Line: a=rtpmap:111 G726-32/8000 (25) [Sep 21 16:02:38] DEBUG[30893]: chan_sip.c:5064 parse_request: Line: a=silenceSupp:off - - - - (25) [Sep 21 16:02:38] DEBUG[30893]: chan_sip.c:5064 parse_request: Line: a=ptime:20 (10) [Sep 21 16:02:38] DEBUG[30893]: chan_sip.c:5064 parse_request: Line: a=sendrecv (10) [Sep 21 16:02:38] Reliably Transmitting (NAT) to 10.4.127.199:5060: INVITE sip:5678@10.4.127.199 SIP/2.0 Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK5ef6f37d;rport From: "4567" ;tag=as292fe2e3 To: Contact: Call-ID: 092075a17e0d80a74dbdfbc71ad3cf4c@10.4.119.245 CSeq: 102 INVITE User-Agent: Asterisk PBX Max-Forwards: 70 Date: Mon, 21 Sep 2009 20:02:37 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces Content-Type: application/sdp Content-Length: 215 v=0 o=root 30858 30858 IN IP4 10.4.119.245 s=session c=IN IP4 10.4.119.245 t=0 0 m=audio 11974 RTP/AVP 0 111 a=rtpmap:0 PCMU/8000 a=rtpmap:111 G726-32/8000 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv --- [Sep 21 16:02:38] DEBUG[30893]: chan_sip.c:2101 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #-1 [Sep 21 16:02:38] -- Called 5678 [Sep 21 16:02:38] <--- SIP read from 10.4.127.199:5060 ---> SIP/2.0 100 Trying Call-ID: 092075a17e0d80a74dbdfbc71ad3cf4c@10.4.119.245 CSeq: 102 INVITE From: "4567" ;tag=as292fe2e3 To: ;tag=bfbf74c143c367a Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK5ef6f37d;rport Content-Length: 0 User-Agent: MxSipApp/5.0.25.189 <-------------> [Sep 21 16:02:38] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 0: SIP/2.0 100 Trying (18) [Sep 21 16:02:38] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 1: Call-ID: 092075a17e0d80a74dbdfbc71ad3cf4c@10.4.119.245 (54) [Sep 21 16:02:38] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 2: CSeq: 102 INVITE (16) [Sep 21 16:02:38] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 3: From: "4567" ;tag=as292fe2e3 (51) [Sep 21 16:02:38] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 4: To: ;tag=bfbf74c143c367a (47) [Sep 21 16:02:38] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 5: Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK5ef6f37d;rport (63) [Sep 21 16:02:38] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 6: Content-Length: 0 (17) [Sep 21 16:02:38] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 7: User-Agent: MxSipApp/5.0.25.189 (32) [Sep 21 16:02:38] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 8: (0) [Sep 21 16:02:38] --- (8 headers 0 lines) --- [Sep 21 16:02:38] DEBUG[30876]: chan_sip.c:4817 find_call: = Found Their Call ID: 092075a17e0d80a74dbdfbc71ad3cf4c@10.4.119.245 Their Tag Our tag: as292fe2e3 [Sep 21 16:02:38] DEBUG[30876]: chan_sip.c:2292 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #59 - INVITE (got response) [Sep 21 16:02:38] DEBUG[30876]: chan_sip.c:2300 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '092075a17e0d80a74dbdfbc71ad3cf4c@10.4.119.245' Request 102: Found [Sep 21 16:02:38] DEBUG[30876]: chan_sip.c:12698 handle_response_invite: SIP response 100 to standard invite [Sep 21 16:02:38] <--- SIP read from 10.4.127.199:5060 ---> SIP/2.0 180 Ringing Call-ID: 092075a17e0d80a74dbdfbc71ad3cf4c@10.4.119.245 CSeq: 102 INVITE From: "4567" ;tag=as292fe2e3 To: ;tag=bfbf74c143c367a Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK5ef6f37d;rport Content-Length: 0 Contact: sip:5678@10.4.127.199 User-Agent: MxSipApp/5.0.25.189 <-------------> [Sep 21 16:02:38] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 0: SIP/2.0 180 Ringing (19) [Sep 21 16:02:38] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 1: Call-ID: 092075a17e0d80a74dbdfbc71ad3cf4c@10.4.119.245 (54) [Sep 21 16:02:38] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 2: CSeq: 102 INVITE (16) [Sep 21 16:02:38] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 3: From: "4567" ;tag=as292fe2e3 (51) [Sep 21 16:02:38] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 4: To: ;tag=bfbf74c143c367a (47) [Sep 21 16:02:38] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 5: Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK5ef6f37d;rport (63) [Sep 21 16:02:38] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 6: Content-Length: 0 (17) [Sep 21 16:02:38] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 7: Contact: sip:5678@10.4.127.199 (30) [Sep 21 16:02:38] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 8: User-Agent: MxSipApp/5.0.25.189 (32) [Sep 21 16:02:38] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 9: (0) [Sep 21 16:02:38] --- (9 headers 0 lines) --- [Sep 21 16:02:38] DEBUG[30876]: chan_sip.c:4817 find_call: = Found Their Call ID: 092075a17e0d80a74dbdfbc71ad3cf4c@10.4.119.245 Their Tag bfbf74c143c367a Our tag: as292fe2e3 [Sep 21 16:02:38] DEBUG[30876]: chan_sip.c:2300 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '092075a17e0d80a74dbdfbc71ad3cf4c@10.4.119.245' Request 102: Found [Sep 21 16:02:38] DEBUG[30876]: chan_sip.c:12698 handle_response_invite: SIP response 180 to standard invite [Sep 21 16:02:38] DEBUG[30876]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/5678 [Sep 21 16:02:38] -- SIP/5678-09201800 is ringing [Sep 21 16:02:38] DEBUG[30893]: rtp.c:1617 ast_rtp_early_bridge: Setting early bridge SDP of 'SIP/4567-091fc8e8' with that of 'SIP/5678-09201800' [Sep 21 16:02:38] <--- Transmitting (NAT) to 10.4.127.199:5060 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 10.4.127.199;branch=z9hG4bK6a390f751;received=10.4.127.199 From: sip:4567@10.4.119.245;tag=f6cd0ba5dded5ef To: sip:5678@10.4.119.245;tag=as23d9cdf5 Call-ID: 2a18d5e0791e956a19adf1ee11461c08@10.4.119.245 CSeq: 488449818 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces Contact: Content-Length: 0 <------------> [Sep 21 16:02:38] DEBUG[30863]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5678 [Sep 21 16:02:38] DEBUG[30863]: chan_sip.c:17080 sip_devicestate: Checking device state for peer 5678 [Sep 21 16:02:38] DEBUG[30863]: devicestate.c:287 do_state_change: Changing state for SIP/5678 - state 1 (Not in use) [Sep 21 16:02:38] DEBUG[30875]: app_queue.c:675 handle_statechange: Device 'SIP/5678' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Sep 21 16:02:39] <--- SIP read from 10.4.127.199:5060 ---> SIP/2.0 200 OK Call-ID: 092075a17e0d80a74dbdfbc71ad3cf4c@10.4.119.245 CSeq: 102 INVITE From: "4567" ;tag=as292fe2e3 To: ;tag=bfbf74c143c367a Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK5ef6f37d;rport Content-Length: 166 Session-Expires: 3600;refresher=uas Allow: INVITE, ACK, BYE, CANCEL, REFER, NOTIFY Content-Type: application/sdp Supported: replaces Contact: sip:5678@10.4.127.199 User-Agent: MxSipApp/5.0.25.189 v=0 o=MxSIP 2043881467134172207 323961897138394746 IN IP4 10.4.127.199 s=- c=IN IP4 10.4.127.199 t=0 0 a=sendrecv m=audio 5006 RTP/AVP 0 a=rtpmap:0 PCMU/8000 <-------------> [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 0: SIP/2.0 200 OK (14) [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 1: Call-ID: 092075a17e0d80a74dbdfbc71ad3cf4c@10.4.119.245 (54) [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 2: CSeq: 102 INVITE (16) [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 3: From: "4567" ;tag=as292fe2e3 (51) [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 4: To: ;tag=bfbf74c143c367a (47) [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 5: Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK5ef6f37d;rport (63) [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 6: Content-Length: 166 (19) [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 7: Session-Expires: 3600;refresher=uas (35) [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 8: Allow: INVITE, ACK, BYE, CANCEL, REFER, NOTIFY (46) [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 9: Content-Type: application/sdp (29) [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 10: Supported: replaces (19) [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 11: Contact: sip:5678@10.4.127.199 (30) [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 12: User-Agent: MxSipApp/5.0.25.189 (32) [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 13: (0) [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:5064 parse_request: Line: v=0 (3) [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:5064 parse_request: Line: o=MxSIP 2043881467134172207 323961897138394746 IN IP4 10.4.127.199 (66) [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:5064 parse_request: Line: s=- (3) [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:5064 parse_request: Line: c=IN IP4 10.4.127.199 (21) [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:5064 parse_request: Line: t=0 0 (5) [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:5064 parse_request: Line: a=sendrecv (10) [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:5064 parse_request: Line: m=audio 5006 RTP/AVP 0 (22) [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:5064 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Sep 21 16:02:39] --- (13 headers 8 lines) --- [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:4817 find_call: = Found Their Call ID: 092075a17e0d80a74dbdfbc71ad3cf4c@10.4.119.245 Their Tag bfbf74c143c367a Our tag: as292fe2e3 [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:2226 __sip_ack: Acked pending invite 102 [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:2258 __sip_ack: Stopping retransmission on '092075a17e0d80a74dbdfbc71ad3cf4c@10.4.119.245' of Request 102: Match Found [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:12698 handle_response_invite: SIP response 200 to standard invite [Sep 21 16:02:39] Found RTP audio format 0 [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:5505 process_sdp: Peer doesn't provide T.38 UDPTL [Sep 21 16:02:39] Peer audio RTP is at port 10.4.127.199:5006 [Sep 21 16:02:39] Found audio description format PCMU for ID 0 [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:5778 process_sdp: T38 state changed to 0 on channel SIP/5678-09201800 [Sep 21 16:02:39] Capabilities: us - 0x804 (ulaw|g726), peer - audio=0x4 (ulaw)/video=0x0 (nothing), combined - 0x4 (ulaw) [Sep 21 16:02:39] Non-codec capabilities (dtmf): us - 0x0 (nothing), peer - 0x0 (nothing), combined - 0x0 (nothing) [Sep 21 16:02:39] Peer audio RTP is at port 10.4.127.199:5006 [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:5858 process_sdp: We're settling with these formats: 0x4 (ulaw) [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:5865 process_sdp: We have an owner, now see if we need to change this call [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:3366 update_call_counter: Updating call counter for outgoing call [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:8784 build_route: build_route: Contact hop: sip:5678@10.4.127.199 [Sep 21 16:02:39] list_route: hop: [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:6335 reqprep: Strict routing enforced for session 092075a17e0d80a74dbdfbc71ad3cf4c@10.4.119.245 [Sep 21 16:02:39] set_destination: Parsing for address/port to send to [Sep 21 16:02:39] set_destination: set destination to 10.4.127.199, port 5060 [Sep 21 16:02:39] Transmitting (NAT) to 10.4.127.199:5060: ACK sip:5678@10.4.127.199 SIP/2.0 Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK1acb3126;rport From: "4567" ;tag=as292fe2e3 To: ;tag=bfbf74c143c367a Contact: Call-ID: 092075a17e0d80a74dbdfbc71ad3cf4c@10.4.119.245 CSeq: 102 ACK User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- [Sep 21 16:02:39] DEBUG[30893]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/5678 [Sep 21 16:02:39] -- SIP/5678-09201800 answered SIP/4567-091fc8e8 [Sep 21 16:02:39] DEBUG[30893]: rtp.c:1617 ast_rtp_early_bridge: Setting early bridge SDP of 'SIP/4567-091fc8e8' with that of 'SIP/5678-09201800' [Sep 21 16:02:39] DEBUG[30893]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/4567 [Sep 21 16:02:39] DEBUG[30893]: chan_sip.c:3856 sip_answer: SIP answering channel: SIP/4567-091fc8e8 [Sep 21 16:02:39] DEBUG[30893]: chan_sip.c:7111 transmit_response_with_sdp: Setting framing from config on incoming call [Sep 21 16:02:39] DEBUG[30893]: chan_sip.c:6826 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True [Sep 21 16:02:39] DEBUG[30893]: chan_sip.c:6827 add_sdp: ** Our prefcodec: 0x0 (nothing) [Sep 21 16:02:39] Audio is at 10.4.119.245 port 19168 [Sep 21 16:02:39] Adding codec 0x4 (ulaw) to SDP [Sep 21 16:02:39] DEBUG[30893]: chan_sip.c:6944 add_sdp: -- Done with adding codecs to SDP [Sep 21 16:02:39] DEBUG[30893]: channel.c:2509 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Sep 21 16:02:39] DEBUG[30893]: chan_sip.c:7053 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw) [Sep 21 16:02:39] <--- Reliably Transmitting (NAT) to 10.4.127.199:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.4.127.199;branch=z9hG4bK6a390f751;received=10.4.127.199 From: sip:4567@10.4.119.245;tag=f6cd0ba5dded5ef To: sip:5678@10.4.119.245;tag=as23d9cdf5 Call-ID: 2a18d5e0791e956a19adf1ee11461c08@10.4.119.245 CSeq: 488449818 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces Contact: Content-Type: application/sdp Content-Length: 184 v=0 o=root 30858 30858 IN IP4 10.4.119.245 s=session c=IN IP4 10.4.119.245 t=0 0 m=audio 19168 RTP/AVP 0 a=rtpmap:0 PCMU/8000 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv <------------> [Sep 21 16:02:39] DEBUG[30893]: chan_sip.c:2101 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #-1 [Sep 21 16:02:39] -- Native bridging SIP/4567-091fc8e8 and SIP/5678-09201800 [Sep 21 16:02:39] DEBUG[30893]: chan_sip.c:18889 sip_set_rtp_peer: Deferring reinvite on SIP '2a18d5e0791e956a19adf1ee11461c08@10.4.119.245' - It's audio will be redirected to IP 10.4.127.199 [Sep 21 16:02:39] DEBUG[30893]: chan_sip.c:18884 sip_set_rtp_peer: Sending reinvite on SIP '092075a17e0d80a74dbdfbc71ad3cf4c@10.4.119.245' - It's audio soon redirected to IP 10.4.127.199 [Sep 21 16:02:39] DEBUG[30893]: chan_sip.c:6335 reqprep: Strict routing enforced for session 092075a17e0d80a74dbdfbc71ad3cf4c@10.4.119.245 [Sep 21 16:02:39] set_destination: Parsing for address/port to send to [Sep 21 16:02:39] set_destination: set destination to 10.4.127.199, port 5060 [Sep 21 16:02:39] DEBUG[30893]: chan_sip.c:6826 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True [Sep 21 16:02:39] DEBUG[30893]: chan_sip.c:6827 add_sdp: ** Our prefcodec: 0x4 (ulaw) [Sep 21 16:02:39] Audio is at 10.4.119.245 port 11974 [Sep 21 16:02:39] Adding codec 0x4 (ulaw) to SDP [Sep 21 16:02:39] DEBUG[30893]: chan_sip.c:6944 add_sdp: -- Done with adding codecs to SDP [Sep 21 16:02:39] DEBUG[30893]: channel.c:2509 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Sep 21 16:02:39] DEBUG[30893]: chan_sip.c:7053 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw) [Sep 21 16:02:39] DEBUG[30893]: chan_sip.c:1694 initialize_initreq: Initializing already initialized SIP dialog 092075a17e0d80a74dbdfbc71ad3cf4c@10.4.119.245 (presumably reinvite) [Sep 21 16:02:39] DEBUG[30893]: chan_sip.c:5028 parse_request: Header 0: INVITE sip:5678@10.4.127.199 SIP/2.0 (36) [Sep 21 16:02:39] DEBUG[30893]: chan_sip.c:5028 parse_request: Header 1: Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK583479fb;rport (63) [Sep 21 16:02:39] DEBUG[30893]: chan_sip.c:5028 parse_request: Header 2: From: "4567" ;tag=as292fe2e3 (51) [Sep 21 16:02:39] DEBUG[30893]: chan_sip.c:5028 parse_request: Header 3: To: ;tag=bfbf74c143c367a (47) [Sep 21 16:02:39] DEBUG[30893]: chan_sip.c:5028 parse_request: Header 4: Contact: (32) [Sep 21 16:02:39] DEBUG[30893]: chan_sip.c:5028 parse_request: Header 5: Call-ID: 092075a17e0d80a74dbdfbc71ad3cf4c@10.4.119.245 (54) [Sep 21 16:02:39] DEBUG[30893]: chan_sip.c:5028 parse_request: Header 6: CSeq: 103 INVITE (16) [Sep 21 16:02:39] DEBUG[30893]: chan_sip.c:5028 parse_request: Header 7: User-Agent: Asterisk PBX (24) [Sep 21 16:02:39] DEBUG[30893]: chan_sip.c:5028 parse_request: Header 8: Max-Forwards: 70 (16) [Sep 21 16:02:39] DEBUG[30893]: chan_sip.c:5028 parse_request: Header 9: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO (72) [Sep 21 16:02:39] DEBUG[30893]: chan_sip.c:5028 parse_request: Header 10: Supported: replaces (19) [Sep 21 16:02:39] DEBUG[30893]: chan_sip.c:5028 parse_request: Header 11: X-asterisk-Info: SIP re-invite (External RTP bridge) (52) [Sep 21 16:02:39] DEBUG[30893]: chan_sip.c:5028 parse_request: Header 12: Content-Type: application/sdp (29) [Sep 21 16:02:39] DEBUG[30893]: chan_sip.c:5028 parse_request: Header 13: Content-Length: 183 (19) [Sep 21 16:02:39] DEBUG[30893]: chan_sip.c:5028 parse_request: Header 14: (0) [Sep 21 16:02:39] DEBUG[30893]: chan_sip.c:5064 parse_request: Line: v=0 (3) [Sep 21 16:02:39] DEBUG[30893]: chan_sip.c:5064 parse_request: Line: o=root 30858 30859 IN IP4 10.4.127.199 (38) [Sep 21 16:02:39] DEBUG[30893]: chan_sip.c:5064 parse_request: Line: s=session (9) [Sep 21 16:02:39] DEBUG[30893]: chan_sip.c:5064 parse_request: Line: c=IN IP4 10.4.127.199 (21) [Sep 21 16:02:39] DEBUG[30893]: chan_sip.c:5064 parse_request: Line: t=0 0 (5) [Sep 21 16:02:39] DEBUG[30893]: chan_sip.c:5064 parse_request: Line: m=audio 5004 RTP/AVP 0 (22) [Sep 21 16:02:39] DEBUG[30893]: chan_sip.c:5064 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Sep 21 16:02:39] DEBUG[30893]: chan_sip.c:5064 parse_request: Line: a=silenceSupp:off - - - - (25) [Sep 21 16:02:39] DEBUG[30893]: chan_sip.c:5064 parse_request: Line: a=ptime:20 (10) [Sep 21 16:02:39] DEBUG[30893]: chan_sip.c:5064 parse_request: Line: a=sendrecv (10) [Sep 21 16:02:39] Reliably Transmitting (NAT) to 10.4.127.199:5060: INVITE sip:5678@10.4.127.199 SIP/2.0 Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK583479fb;rport From: "4567" ;tag=as292fe2e3 To: ;tag=bfbf74c143c367a Contact: Call-ID: 092075a17e0d80a74dbdfbc71ad3cf4c@10.4.119.245 CSeq: 103 INVITE User-Agent: Asterisk PBX Max-Forwards: 70 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces X-asterisk-Info: SIP re-invite (External RTP bridge) Content-Type: application/sdp Content-Length: 183 v=0 o=root 30858 30859 IN IP4 10.4.127.199 s=session c=IN IP4 10.4.127.199 t=0 0 m=audio 5004 RTP/AVP 0 a=rtpmap:0 PCMU/8000 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv --- [Sep 21 16:02:39] DEBUG[30893]: chan_sip.c:2101 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #-1 [Sep 21 16:02:39] DEBUG[30863]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5678 [Sep 21 16:02:39] DEBUG[30863]: chan_sip.c:17080 sip_devicestate: Checking device state for peer 5678 [Sep 21 16:02:39] DEBUG[30863]: devicestate.c:287 do_state_change: Changing state for SIP/5678 - state 1 (Not in use) [Sep 21 16:02:39] DEBUG[30863]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 4567 [Sep 21 16:02:39] DEBUG[30863]: chan_sip.c:17080 sip_devicestate: Checking device state for peer 4567 [Sep 21 16:02:39] DEBUG[30863]: devicestate.c:287 do_state_change: Changing state for SIP/4567 - state 1 (Not in use) [Sep 21 16:02:39] DEBUG[30875]: app_queue.c:675 handle_statechange: Device 'SIP/5678' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Sep 21 16:02:39] DEBUG[30875]: app_queue.c:675 handle_statechange: Device 'SIP/4567' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Sep 21 16:02:39] DEBUG[30893]: rtp.c:2885 ast_rtp_write: Ooh, format changed from unknown to ulaw [Sep 21 16:02:39] DEBUG[30893]: rtp.c:2902 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160 [Sep 21 16:02:39] <--- SIP read from 10.4.127.199:5060 ---> ACK sip:5678@10.4.119.245 SIP/2.0 Via: SIP/2.0/UDP 10.4.127.199;branch=z9hG4bKfc0e6335c Content-Length: 0 To: sip:5678@10.4.119.245;tag=as23d9cdf5 From: sip:4567@10.4.119.245;tag=f6cd0ba5dded5ef Call-ID: 2a18d5e0791e956a19adf1ee11461c08@10.4.119.245 CSeq: 488449818 ACK Contact: sip:4567@10.4.127.199 User-Agent: MxSipApp/5.0.25.189 <-------------> [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 0: ACK sip:5678@10.4.119.245 SIP/2.0 (33) [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 1: Via: SIP/2.0/UDP 10.4.127.199;branch=z9hG4bKfc0e6335c (53) [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 2: Content-Length: 0 (17) [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 3: To: sip:5678@10.4.119.245;tag=as23d9cdf5 (40) [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 4: From: sip:4567@10.4.119.245;tag=f6cd0ba5dded5ef (47) [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 5: Call-ID: 2a18d5e0791e956a19adf1ee11461c08@10.4.119.245 (54) [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 6: CSeq: 488449818 ACK (19) [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 7: Contact: sip:4567@10.4.127.199 (30) [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 8: User-Agent: MxSipApp/5.0.25.189 (32) [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 9: (0) [Sep 21 16:02:39] --- (9 headers 0 lines) --- [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:4817 find_call: = No match Their Call ID: 092075a17e0d80a74dbdfbc71ad3cf4c@10.4.119.245 Their Tag bfbf74c143c367a Our tag: as292fe2e3 [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:4817 find_call: = Found Their Call ID: 2a18d5e0791e956a19adf1ee11461c08@10.4.119.245 Their Tag f6cd0ba5dded5ef Our tag: as23d9cdf5 [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:16306 handle_request: **** Received ACK (6) - Command in SIP ACK [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:2234 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #62 [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:2258 __sip_ack: Stopping retransmission on '2a18d5e0791e956a19adf1ee11461c08@10.4.119.245' of Response 488449818: Match Found [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:12660 check_pendings: Sending pending reinvite on '2a18d5e0791e956a19adf1ee11461c08@10.4.119.245' [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:6335 reqprep: Strict routing enforced for session 2a18d5e0791e956a19adf1ee11461c08@10.4.119.245 [Sep 21 16:02:39] set_destination: Parsing for address/port to send to [Sep 21 16:02:39] set_destination: set destination to 10.4.127.199, port 5060 [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:6826 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:6827 add_sdp: ** Our prefcodec: 0x0 (nothing) [Sep 21 16:02:39] Audio is at 10.4.119.245 port 19168 [Sep 21 16:02:39] Adding codec 0x4 (ulaw) to SDP [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:6944 add_sdp: -- Done with adding codecs to SDP [Sep 21 16:02:39] DEBUG[30876]: channel.c:2509 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:7053 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw) [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:1694 initialize_initreq: Initializing already initialized SIP dialog 2a18d5e0791e956a19adf1ee11461c08@10.4.119.245 (presumably reinvite) [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 0: INVITE sip:4567@10.4.127.199 SIP/2.0 (36) [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 1: Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK59d5cdea;rport (63) [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 2: From: sip:5678@10.4.119.245;tag=as23d9cdf5 (42) [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 3: To: sip:4567@10.4.119.245;tag=f6cd0ba5dded5ef (45) [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 4: Contact: (32) [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 5: Call-ID: 2a18d5e0791e956a19adf1ee11461c08@10.4.119.245 (54) [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 6: CSeq: 102 INVITE (16) [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 7: User-Agent: Asterisk PBX (24) [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 8: Max-Forwards: 70 (16) [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 9: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO (72) [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 10: Supported: replaces (19) [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 11: X-asterisk-Info: SIP re-invite (External RTP bridge) (52) [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 12: Content-Type: application/sdp (29) [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 13: Content-Length: 183 (19) [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 14: (0) [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:5064 parse_request: Line: v=0 (3) [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:5064 parse_request: Line: o=root 30858 30859 IN IP4 10.4.127.199 (38) [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:5064 parse_request: Line: s=session (9) [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:5064 parse_request: Line: c=IN IP4 10.4.127.199 (21) [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:5064 parse_request: Line: t=0 0 (5) [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:5064 parse_request: Line: m=audio 5006 RTP/AVP 0 (22) [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:5064 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:5064 parse_request: Line: a=silenceSupp:off - - - - (25) [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:5064 parse_request: Line: a=ptime:20 (10) [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:5064 parse_request: Line: a=sendrecv (10) [Sep 21 16:02:39] Reliably Transmitting (NAT) to 10.4.127.199:5060: INVITE sip:4567@10.4.127.199 SIP/2.0 Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK59d5cdea;rport From: sip:5678@10.4.119.245;tag=as23d9cdf5 To: sip:4567@10.4.119.245;tag=f6cd0ba5dded5ef Contact: Call-ID: 2a18d5e0791e956a19adf1ee11461c08@10.4.119.245 CSeq: 102 INVITE User-Agent: Asterisk PBX Max-Forwards: 70 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces X-asterisk-Info: SIP re-invite (External RTP bridge) Content-Type: application/sdp Content-Length: 183 v=0 o=root 30858 30859 IN IP4 10.4.127.199 s=session c=IN IP4 10.4.127.199 t=0 0 m=audio 5006 RTP/AVP 0 a=rtpmap:0 PCMU/8000 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv --- [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:2101 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #-1 [Sep 21 16:02:39] <--- SIP read from 10.4.127.199:5060 ---> SIP/2.0 100 Trying Call-ID: 092075a17e0d80a74dbdfbc71ad3cf4c@10.4.119.245 CSeq: 103 INVITE From: "4567" ;tag=as292fe2e3 To: ;tag=bfbf74c143c367a Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK583479fb;rport Content-Length: 0 User-Agent: MxSipApp/5.0.25.189 <-------------> [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 0: SIP/2.0 100 Trying (18) [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 1: Call-ID: 092075a17e0d80a74dbdfbc71ad3cf4c@10.4.119.245 (54) [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 2: CSeq: 103 INVITE (16) [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 3: From: "4567" ;tag=as292fe2e3 (51) [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 4: To: ;tag=bfbf74c143c367a (47) [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 5: Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK583479fb;rport (63) [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 6: Content-Length: 0 (17) [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 7: User-Agent: MxSipApp/5.0.25.189 (32) [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 8: (0) [Sep 21 16:02:39] --- (8 headers 0 lines) --- [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:4817 find_call: = Found Their Call ID: 092075a17e0d80a74dbdfbc71ad3cf4c@10.4.119.245 Their Tag bfbf74c143c367a Our tag: as292fe2e3 [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:2292 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #63 - INVITE (got response) [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:2300 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '092075a17e0d80a74dbdfbc71ad3cf4c@10.4.119.245' Request 103: Found [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:12696 handle_response_invite: SIP response 100 to RE-invite on outgoing call 092075a17e0d80a74dbdfbc71ad3cf4c@10.4.119.245 [Sep 21 16:02:39] <--- SIP read from 10.4.127.199:5060 ---> SIP/2.0 200 OK Call-ID: 092075a17e0d80a74dbdfbc71ad3cf4c@10.4.119.245 CSeq: 103 INVITE From: "4567" ;tag=as292fe2e3 To: ;tag=bfbf74c143c367a Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK583479fb;rport Content-Length: 166 Session-Expires: 3600;refresher=uas Allow: INVITE, ACK, BYE, CANCEL, REFER, NOTIFY Content-Type: application/sdp Supported: replaces Contact: sip:5678@10.4.127.199 User-Agent: MxSipApp/5.0.25.189 v=0 o=MxSIP 2043881467134172207 323961897138394746 IN IP4 10.4.127.199 s=- c=IN IP4 10.4.127.199 t=0 0 a=sendrecv m=audio 5006 RTP/AVP 0 a=rtpmap:0 PCMU/8000 <-------------> [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 0: SIP/2.0 200 OK (14) [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 1: Call-ID: 092075a17e0d80a74dbdfbc71ad3cf4c@10.4.119.245 (54) [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 2: CSeq: 103 INVITE (16) [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 3: From: "4567" ;tag=as292fe2e3 (51) [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 4: To: ;tag=bfbf74c143c367a (47) [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 5: Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK583479fb;rport (63) [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 6: Content-Length: 166 (19) [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 7: Session-Expires: 3600;refresher=uas (35) [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 8: Allow: INVITE, ACK, BYE, CANCEL, REFER, NOTIFY (46) [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 9: Content-Type: application/sdp (29) [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 10: Supported: replaces (19) [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 11: Contact: sip:5678@10.4.127.199 (30) [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 12: User-Agent: MxSipApp/5.0.25.189 (32) [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 13: (0) [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:5064 parse_request: Line: v=0 (3) [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:5064 parse_request: Line: o=MxSIP 2043881467134172207 323961897138394746 IN IP4 10.4.127.199 (66) [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:5064 parse_request: Line: s=- (3) [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:5064 parse_request: Line: c=IN IP4 10.4.127.199 (21) [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:5064 parse_request: Line: t=0 0 (5) [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:5064 parse_request: Line: a=sendrecv (10) [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:5064 parse_request: Line: m=audio 5006 RTP/AVP 0 (22) [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:5064 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Sep 21 16:02:39] --- (13 headers 8 lines) --- [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:4817 find_call: = Found Their Call ID: 092075a17e0d80a74dbdfbc71ad3cf4c@10.4.119.245 Their Tag bfbf74c143c367a Our tag: as292fe2e3 [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:2226 __sip_ack: Acked pending invite 103 [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:2258 __sip_ack: Stopping retransmission on '092075a17e0d80a74dbdfbc71ad3cf4c@10.4.119.245' of Request 103: Match Found [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:12696 handle_response_invite: SIP response 200 to RE-invite on outgoing call 092075a17e0d80a74dbdfbc71ad3cf4c@10.4.119.245 [Sep 21 16:02:39] Found RTP audio format 0 [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:5505 process_sdp: Peer doesn't provide T.38 UDPTL [Sep 21 16:02:39] Peer audio RTP is at port 10.4.127.199:5006 [Sep 21 16:02:39] Found audio description format PCMU for ID 0 [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:5778 process_sdp: T38 state changed to 0 on channel SIP/5678-09201800 [Sep 21 16:02:39] Capabilities: us - 0x804 (ulaw|g726), peer - audio=0x4 (ulaw)/video=0x0 (nothing), combined - 0x4 (ulaw) [Sep 21 16:02:39] Non-codec capabilities (dtmf): us - 0x0 (nothing), peer - 0x0 (nothing), combined - 0x0 (nothing) [Sep 21 16:02:39] Peer audio RTP is at port 10.4.127.199:5006 [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:5858 process_sdp: We're settling with these formats: 0x4 (ulaw) [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:5865 process_sdp: We have an owner, now see if we need to change this call [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:3366 update_call_counter: Updating call counter for outgoing call [Sep 21 16:02:39] DEBUG[30876]: chan_sip.c:6335 reqprep: Strict routing enforced for session 092075a17e0d80a74dbdfbc71ad3cf4c@10.4.119.245 [Sep 21 16:02:39] set_destination: Parsing for address/port to send to [Sep 21 16:02:39] set_destination: set destination to 10.4.127.199, port 5060 [Sep 21 16:02:39] Transmitting (NAT) to 10.4.127.199:5060: ACK sip:5678@10.4.127.199 SIP/2.0 Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK48aa1ce5;rport From: "4567" ;tag=as292fe2e3 To: ;tag=bfbf74c143c367a Contact: Call-ID: 092075a17e0d80a74dbdfbc71ad3cf4c@10.4.119.245 CSeq: 103 ACK User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- [Sep 21 16:02:40] <--- SIP read from 10.4.127.199:5060 ---> SIP/2.0 100 Trying Call-ID: 2a18d5e0791e956a19adf1ee11461c08@10.4.119.245 CSeq: 102 INVITE From: sip:5678@10.4.119.245;tag=as23d9cdf5 To: sip:4567@10.4.119.245;tag=f6cd0ba5dded5ef Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK59d5cdea;rport Content-Length: 0 User-Agent: MxSipApp/5.0.25.189 <-------------> [Sep 21 16:02:40] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 0: SIP/2.0 100 Trying (18) [Sep 21 16:02:40] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 1: Call-ID: 2a18d5e0791e956a19adf1ee11461c08@10.4.119.245 (54) [Sep 21 16:02:40] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 2: CSeq: 102 INVITE (16) [Sep 21 16:02:40] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 3: From: sip:5678@10.4.119.245;tag=as23d9cdf5 (42) [Sep 21 16:02:40] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 4: To: sip:4567@10.4.119.245;tag=f6cd0ba5dded5ef (45) [Sep 21 16:02:40] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 5: Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK59d5cdea;rport (63) [Sep 21 16:02:40] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 6: Content-Length: 0 (17) [Sep 21 16:02:40] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 7: User-Agent: MxSipApp/5.0.25.189 (32) [Sep 21 16:02:40] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 8: (0) [Sep 21 16:02:40] --- (8 headers 0 lines) --- [Sep 21 16:02:40] DEBUG[30876]: chan_sip.c:4817 find_call: = No match Their Call ID: 092075a17e0d80a74dbdfbc71ad3cf4c@10.4.119.245 Their Tag bfbf74c143c367a Our tag: as292fe2e3 [Sep 21 16:02:40] DEBUG[30876]: chan_sip.c:4817 find_call: = Found Their Call ID: 2a18d5e0791e956a19adf1ee11461c08@10.4.119.245 Their Tag f6cd0ba5dded5ef Our tag: as23d9cdf5 [Sep 21 16:02:40] DEBUG[30876]: chan_sip.c:2292 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #66 - INVITE (got response) [Sep 21 16:02:40] DEBUG[30876]: chan_sip.c:2300 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '2a18d5e0791e956a19adf1ee11461c08@10.4.119.245' Request 102: Found [Sep 21 16:02:40] DEBUG[30876]: chan_sip.c:12696 handle_response_invite: SIP response 100 to RE-invite on outgoing call 2a18d5e0791e956a19adf1ee11461c08@10.4.119.245 [Sep 21 16:02:40] <--- SIP read from 10.4.127.199:5060 ---> SIP/2.0 200 OK Call-ID: 2a18d5e0791e956a19adf1ee11461c08@10.4.119.245 CSeq: 102 INVITE From: sip:5678@10.4.119.245;tag=as23d9cdf5 To: sip:4567@10.4.119.245;tag=f6cd0ba5dded5ef Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK59d5cdea;rport Content-Length: 166 Session-Expires: 3600;refresher=uas Allow: INVITE, ACK, BYE, CANCEL, REFER, NOTIFY Content-Type: application/sdp Supported: replaces Contact: sip:4567@10.4.127.199 User-Agent: MxSipApp/5.0.25.189 v=0 o=MxSIP 1198078906162342458 394531713152601135 IN IP4 10.4.127.199 s=- c=IN IP4 10.4.127.199 t=0 0 a=sendrecv m=audio 5004 RTP/AVP 0 a=rtpmap:0 PCMU/8000 <-------------> [Sep 21 16:02:40] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 0: SIP/2.0 200 OK (14) [Sep 21 16:02:40] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 1: Call-ID: 2a18d5e0791e956a19adf1ee11461c08@10.4.119.245 (54) [Sep 21 16:02:40] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 2: CSeq: 102 INVITE (16) [Sep 21 16:02:40] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 3: From: sip:5678@10.4.119.245;tag=as23d9cdf5 (42) [Sep 21 16:02:40] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 4: To: sip:4567@10.4.119.245;tag=f6cd0ba5dded5ef (45) [Sep 21 16:02:40] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 5: Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK59d5cdea;rport (63) [Sep 21 16:02:40] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 6: Content-Length: 166 (19) [Sep 21 16:02:40] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 7: Session-Expires: 3600;refresher=uas (35) [Sep 21 16:02:40] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 8: Allow: INVITE, ACK, BYE, CANCEL, REFER, NOTIFY (46) [Sep 21 16:02:40] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 9: Content-Type: application/sdp (29) [Sep 21 16:02:40] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 10: Supported: replaces (19) [Sep 21 16:02:40] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 11: Contact: sip:4567@10.4.127.199 (30) [Sep 21 16:02:40] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 12: User-Agent: MxSipApp/5.0.25.189 (32) [Sep 21 16:02:40] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 13: (0) [Sep 21 16:02:40] DEBUG[30876]: chan_sip.c:5064 parse_request: Line: v=0 (3) [Sep 21 16:02:40] DEBUG[30876]: chan_sip.c:5064 parse_request: Line: o=MxSIP 1198078906162342458 394531713152601135 IN IP4 10.4.127.199 (66) [Sep 21 16:02:40] DEBUG[30876]: chan_sip.c:5064 parse_request: Line: s=- (3) [Sep 21 16:02:40] DEBUG[30876]: chan_sip.c:5064 parse_request: Line: c=IN IP4 10.4.127.199 (21) [Sep 21 16:02:40] DEBUG[30876]: chan_sip.c:5064 parse_request: Line: t=0 0 (5) [Sep 21 16:02:40] DEBUG[30876]: chan_sip.c:5064 parse_request: Line: a=sendrecv (10) [Sep 21 16:02:40] DEBUG[30876]: chan_sip.c:5064 parse_request: Line: m=audio 5004 RTP/AVP 0 (22) [Sep 21 16:02:40] DEBUG[30876]: chan_sip.c:5064 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Sep 21 16:02:40] --- (13 headers 8 lines) --- [Sep 21 16:02:40] DEBUG[30876]: chan_sip.c:4817 find_call: = No match Their Call ID: 092075a17e0d80a74dbdfbc71ad3cf4c@10.4.119.245 Their Tag bfbf74c143c367a Our tag: as292fe2e3 [Sep 21 16:02:40] DEBUG[30876]: chan_sip.c:4817 find_call: = Found Their Call ID: 2a18d5e0791e956a19adf1ee11461c08@10.4.119.245 Their Tag f6cd0ba5dded5ef Our tag: as23d9cdf5 [Sep 21 16:02:40] DEBUG[30876]: chan_sip.c:2226 __sip_ack: Acked pending invite 102 [Sep 21 16:02:40] DEBUG[30876]: chan_sip.c:2258 __sip_ack: Stopping retransmission on '2a18d5e0791e956a19adf1ee11461c08@10.4.119.245' of Request 102: Match Found [Sep 21 16:02:40] DEBUG[30876]: chan_sip.c:12696 handle_response_invite: SIP response 200 to RE-invite on outgoing call 2a18d5e0791e956a19adf1ee11461c08@10.4.119.245 [Sep 21 16:02:40] Found RTP audio format 0 [Sep 21 16:02:40] DEBUG[30876]: chan_sip.c:5505 process_sdp: Peer doesn't provide T.38 UDPTL [Sep 21 16:02:40] Peer audio RTP is at port 10.4.127.199:5004 [Sep 21 16:02:40] Found audio description format PCMU for ID 0 [Sep 21 16:02:40] DEBUG[30876]: chan_sip.c:5778 process_sdp: T38 state changed to 0 on channel SIP/4567-091fc8e8 [Sep 21 16:02:40] Capabilities: us - 0x804 (ulaw|g726), peer - audio=0x4 (ulaw)/video=0x0 (nothing), combined - 0x4 (ulaw) [Sep 21 16:02:40] Non-codec capabilities (dtmf): us - 0x0 (nothing), peer - 0x0 (nothing), combined - 0x0 (nothing) [Sep 21 16:02:40] Peer audio RTP is at port 10.4.127.199:5004 [Sep 21 16:02:40] DEBUG[30876]: chan_sip.c:5858 process_sdp: We're settling with these formats: 0x4 (ulaw) [Sep 21 16:02:40] DEBUG[30876]: chan_sip.c:5865 process_sdp: We have an owner, now see if we need to change this call [Sep 21 16:02:40] DEBUG[30876]: chan_sip.c:3366 update_call_counter: Updating call counter for incoming call [Sep 21 16:02:40] DEBUG[30876]: chan_sip.c:6335 reqprep: Strict routing enforced for session 2a18d5e0791e956a19adf1ee11461c08@10.4.119.245 [Sep 21 16:02:40] set_destination: Parsing for address/port to send to [Sep 21 16:02:40] set_destination: set destination to 10.4.127.199, port 5060 [Sep 21 16:02:40] Transmitting (NAT) to 10.4.127.199:5060: ACK sip:4567@10.4.127.199 SIP/2.0 Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK26878b25;rport From: sip:5678@10.4.119.245;tag=as23d9cdf5 To: sip:4567@10.4.119.245;tag=f6cd0ba5dded5ef Contact: Call-ID: 2a18d5e0791e956a19adf1ee11461c08@10.4.119.245 CSeq: 102 ACK User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- [Sep 21 16:02:43] <--- SIP read from 10.4.127.199:5060 ---> INVITE sip:5678@10.4.119.245 SIP/2.0 Via: SIP/2.0/UDP 10.4.127.199;branch=z9hG4bK4a004a558 Content-Length: 336 To: sip:5678@10.4.119.245;tag=as23d9cdf5 From: sip:4567@10.4.119.245;tag=f6cd0ba5dded5ef Call-ID: 2a18d5e0791e956a19adf1ee11461c08@10.4.119.245 CSeq: 488449819 INVITE Supported: timer Min-SE: 1800 Session-Expires: 3600 Allow: INVITE, ACK, BYE, CANCEL, REFER, NOTIFY Content-Type: application/sdp Contact: sip:4567@10.4.127.199 Supported: replaces User-Agent: MxSipApp/5.0.25.189 v=0 o=MxSIP 1198078906162342458 394531713152601136 IN IP4 10.4.127.199 s=- c=IN IP4 10.4.127.199 t=0 0 a=sendrecv m=image 6004 udptl t38 a=T38MaxBitRate:14400 a=T38FaxRateManagement:transferredTCF a=T38FaxFillBitRemoval:0 a=T38FaxTranscodingMMR:0 a=T38FaxTranscodingJBIG:0 a=T38FaxVersion:0 a=T38FaxUdpEC:t38UDPRedundancy <-------------> [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 0: INVITE sip:5678@10.4.119.245 SIP/2.0 (36) [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 1: Via: SIP/2.0/UDP 10.4.127.199;branch=z9hG4bK4a004a558 (53) [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 2: Content-Length: 336 (19) [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 3: To: sip:5678@10.4.119.245;tag=as23d9cdf5 (40) [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 4: From: sip:4567@10.4.119.245;tag=f6cd0ba5dded5ef (47) [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 5: Call-ID: 2a18d5e0791e956a19adf1ee11461c08@10.4.119.245 (54) [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 6: CSeq: 488449819 INVITE (22) [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 7: Supported: timer (16) [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 8: Min-SE: 1800 (12) [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 9: Session-Expires: 3600 (21) [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 10: Allow: INVITE, ACK, BYE, CANCEL, REFER, NOTIFY (46) [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 11: Content-Type: application/sdp (29) [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 12: Contact: sip:4567@10.4.127.199 (30) [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 13: Supported: replaces (19) [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 14: User-Agent: MxSipApp/5.0.25.189 (32) [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 15: (0) [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:5064 parse_request: Line: v=0 (3) [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:5064 parse_request: Line: o=MxSIP 1198078906162342458 394531713152601136 IN IP4 10.4.127.199 (66) [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:5064 parse_request: Line: s=- (3) [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:5064 parse_request: Line: c=IN IP4 10.4.127.199 (21) [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:5064 parse_request: Line: t=0 0 (5) [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:5064 parse_request: Line: a=sendrecv (10) [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:5064 parse_request: Line: m=image 6004 udptl t38 (22) [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:5064 parse_request: Line: a=T38MaxBitRate:14400 (21) [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:5064 parse_request: Line: a=T38FaxRateManagement:transferredTCF (37) [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:5064 parse_request: Line: a=T38FaxFillBitRemoval:0 (24) [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:5064 parse_request: Line: a=T38FaxTranscodingMMR:0 (24) [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:5064 parse_request: Line: a=T38FaxTranscodingJBIG:0 (25) [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:5064 parse_request: Line: a=T38FaxVersion:0 (17) [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:5064 parse_request: Line: a=T38FaxUdpEC:t38UDPRedundancy (30) [Sep 21 16:02:43] --- (15 headers 14 lines) --- [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:4817 find_call: = No match Their Call ID: 092075a17e0d80a74dbdfbc71ad3cf4c@10.4.119.245 Their Tag bfbf74c143c367a Our tag: as292fe2e3 [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:4817 find_call: = Found Their Call ID: 2a18d5e0791e956a19adf1ee11461c08@10.4.119.245 Their Tag f6cd0ba5dded5ef Our tag: as23d9cdf5 [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:16306 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Sep 21 16:02:43] Sending to 10.4.127.199 : 5060 (NAT) [Sep 21 16:02:43] Got T.38 offer in SDP in dialog 2a18d5e0791e956a19adf1ee11461c08@10.4.119.245 [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:5435 process_sdp: T38 state changed to 3 on channel SIP/4567-091fc8e8 [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:5501 process_sdp: Peer T.38 UDPTL is at port 10.4.127.199:6004 [Sep 21 16:02:43] Got T.38 Re-invite without audio. Keeping RTP active during T.38 session. Callid 2a18d5e0791e956a19adf1ee11461c08@10.4.119.245 [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:5669 process_sdp: T38MaxBitRate: 14400 [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:5743 process_sdp: RateManagement: transferredTCF [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:5708 process_sdp: FillBitRemoval: 0 [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:5720 process_sdp: Transcoding MMR: 0 [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:5732 process_sdp: Transcoding JBIG: 0 [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:5693 process_sdp: FaxVersion: 0 [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:5751 process_sdp: UDP EC: t38UDPRedundancy [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:5771 process_sdp: Our T38 capability = (3872), peer T38 capability (16160), joint T38 capability (3872) [Sep 21 16:02:43] Capabilities: us - 0x804 (ulaw|g726), peer - audio=0x0 (nothing)/video=0x0 (nothing), combined - 0x0 (nothing) [Sep 21 16:02:43] Non-codec capabilities (dtmf): us - 0x0 (nothing), peer - 0x0 (nothing), combined - 0x0 (nothing) [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:5813 process_sdp: Have T.38 but no audio codecs, accepting offer anyway [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:15005 handle_request_invite: Got a SIP re-invite for call 2a18d5e0791e956a19adf1ee11461c08@10.4.119.245 [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:15119 handle_request_invite: SIP/4567-091fc8e8: This call is UP.... [Sep 21 16:02:43] <--- Transmitting (NAT) to 10.4.127.199:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.4.127.199;branch=z9hG4bK4a004a558;received=10.4.127.199 From: sip:4567@10.4.119.245;tag=f6cd0ba5dded5ef To: sip:5678@10.4.119.245;tag=as23d9cdf5 Call-ID: 2a18d5e0791e956a19adf1ee11461c08@10.4.119.245 CSeq: 488449819 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces Contact: Content-Length: 0 <------------> [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:18727 sip_handle_t38_reinvite: Sending reinvite on SIP '092075a17e0d80a74dbdfbc71ad3cf4c@10.4.119.245' - It's UDPTL soon redirected to IP 10.4.127.199:6004 [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:6335 reqprep: Strict routing enforced for session 092075a17e0d80a74dbdfbc71ad3cf4c@10.4.119.245 [Sep 21 16:02:43] set_destination: Parsing for address/port to send to [Sep 21 16:02:43] set_destination: set destination to 10.4.127.199, port 5060 [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:6978 add_sdp: T.38 UDPTL is at 10.4.119.245 port 4454 [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:6979 add_sdp: Our T38 capability (3872), peer T38 capability (3872), joint capability (3872) [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:6686 t38_get_rate: T38MaxBitRate 9600 found [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:7053 add_sdp: Done building SDP. Settling with this capability: 0x0 (nothing) [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:1694 initialize_initreq: Initializing already initialized SIP dialog 092075a17e0d80a74dbdfbc71ad3cf4c@10.4.119.245 (presumably reinvite) [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 0: INVITE sip:5678@10.4.127.199 SIP/2.0 (36) [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 1: Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK1762f715;rport (63) [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 2: From: "4567" ;tag=as292fe2e3 (51) [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 3: To: ;tag=bfbf74c143c367a (47) [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 4: Contact: (32) [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 5: Call-ID: 092075a17e0d80a74dbdfbc71ad3cf4c@10.4.119.245 (54) [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 6: CSeq: 104 INVITE (16) [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 7: User-Agent: Asterisk PBX (24) [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 8: Max-Forwards: 70 (16) [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 9: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO (72) [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 10: Supported: replaces (19) [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 11: X-asterisk-info: SIP re-invite (T38 switchover) (47) [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 12: Content-Type: application/sdp (29) [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 13: Content-Length: 270 (19) [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 14: (0) [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:5064 parse_request: Line: v=0 (3) [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:5064 parse_request: Line: o=root 30858 30860 IN IP4 10.4.127.199 (38) [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:5064 parse_request: Line: s=session (9) [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:5064 parse_request: Line: c=IN IP4 10.4.127.199 (21) [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:5064 parse_request: Line: t=0 0 (5) [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:5064 parse_request: Line: m=image 6004 udptl t38 (22) [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:5064 parse_request: Line: a=T38FaxVersion:0 (17) [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:5064 parse_request: Line: a=T38MaxBitRate:9600 (20) [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:5064 parse_request: Line: a=T38FaxRateManagement:transferredTCF (37) [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:5064 parse_request: Line: a=T38FaxMaxBuffer:400 (21) [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:5064 parse_request: Line: a=T38FaxMaxDatagram:400 (23) [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:5064 parse_request: Line: a=T38FaxUdpEC:t38UDPRedundancy (30) [Sep 21 16:02:43] Reliably Transmitting (NAT) to 10.4.127.199:5060: INVITE sip:5678@10.4.127.199 SIP/2.0 Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK1762f715;rport From: "4567" ;tag=as292fe2e3 To: ;tag=bfbf74c143c367a Contact: Call-ID: 092075a17e0d80a74dbdfbc71ad3cf4c@10.4.119.245 CSeq: 104 INVITE User-Agent: Asterisk PBX Max-Forwards: 70 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces X-asterisk-info: SIP re-invite (T38 switchover) Content-Type: application/sdp Content-Length: 270 v=0 o=root 30858 30860 IN IP4 10.4.127.199 s=session c=IN IP4 10.4.127.199 t=0 0 m=image 6004 udptl t38 a=T38FaxVersion:0 a=T38MaxBitRate:9600 a=T38FaxRateManagement:transferredTCF a=T38FaxMaxBuffer:400 a=T38FaxMaxDatagram:400 a=T38FaxUdpEC:t38UDPRedundancy --- [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:2101 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #-1 [Sep 21 16:02:43] <--- SIP read from 10.4.127.199:5060 ---> SIP/2.0 100 Trying Call-ID: 092075a17e0d80a74dbdfbc71ad3cf4c@10.4.119.245 CSeq: 104 INVITE From: "4567" ;tag=as292fe2e3 To: ;tag=bfbf74c143c367a Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK1762f715;rport Content-Length: 0 User-Agent: MxSipApp/5.0.25.189 <-------------> [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 0: SIP/2.0 100 Trying (18) [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 1: Call-ID: 092075a17e0d80a74dbdfbc71ad3cf4c@10.4.119.245 (54) [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 2: CSeq: 104 INVITE (16) [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 3: From: "4567" ;tag=as292fe2e3 (51) [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 4: To: ;tag=bfbf74c143c367a (47) [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 5: Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK1762f715;rport (63) [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 6: Content-Length: 0 (17) [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 7: User-Agent: MxSipApp/5.0.25.189 (32) [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 8: (0) [Sep 21 16:02:43] --- (8 headers 0 lines) --- [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:4817 find_call: = Found Their Call ID: 092075a17e0d80a74dbdfbc71ad3cf4c@10.4.119.245 Their Tag bfbf74c143c367a Our tag: as292fe2e3 [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:2292 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #67 - INVITE (got response) [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:2300 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '092075a17e0d80a74dbdfbc71ad3cf4c@10.4.119.245' Request 104: Found [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:12696 handle_response_invite: SIP response 100 to RE-invite on outgoing call 092075a17e0d80a74dbdfbc71ad3cf4c@10.4.119.245 [Sep 21 16:02:43] <--- SIP read from 10.4.127.199:5060 ---> SIP/2.0 488 Not Acceptable Here Call-ID: 092075a17e0d80a74dbdfbc71ad3cf4c@10.4.119.245 CSeq: 104 INVITE From: "4567" ;tag=as292fe2e3 To: ;tag=bfbf74c143c367a Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK1762f715;rport Content-Length: 0 User-Agent: MxSipApp/5.0.25.189 <-------------> [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 0: SIP/2.0 488 Not Acceptable Here (31) [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 1: Call-ID: 092075a17e0d80a74dbdfbc71ad3cf4c@10.4.119.245 (54) [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 2: CSeq: 104 INVITE (16) [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 3: From: "4567" ;tag=as292fe2e3 (51) [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 4: To: ;tag=bfbf74c143c367a (47) [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 5: Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK1762f715;rport (63) [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 6: Content-Length: 0 (17) [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 7: User-Agent: MxSipApp/5.0.25.189 (32) [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 8: (0) [Sep 21 16:02:43] --- (8 headers 0 lines) --- [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:4817 find_call: = Found Their Call ID: 092075a17e0d80a74dbdfbc71ad3cf4c@10.4.119.245 Their Tag bfbf74c143c367a Our tag: as292fe2e3 [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:2226 __sip_ack: Acked pending invite 104 [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:2258 __sip_ack: Stopping retransmission on '092075a17e0d80a74dbdfbc71ad3cf4c@10.4.119.245' of Request 104: Match Found [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:12696 handle_response_invite: SIP response 488 to RE-invite on outgoing call 092075a17e0d80a74dbdfbc71ad3cf4c@10.4.119.245 [Sep 21 16:02:43] DEBUG[30876]: chan_sip.c:6335 reqprep: Strict routing enforced for session 092075a17e0d80a74dbdfbc71ad3cf4c@10.4.119.245 [Sep 21 16:02:43] set_destination: Parsing for address/port to send to [Sep 21 16:02:43] set_destination: set destination to 10.4.127.199, port 5060 [Sep 21 16:02:43] Transmitting (NAT) to 10.4.127.199:5060: ACK sip:5678@10.4.127.199 SIP/2.0 Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK1762f715;rport From: "4567" ;tag=as292fe2e3 To: ;tag=bfbf74c143c367a Contact: Call-ID: 092075a17e0d80a74dbdfbc71ad3cf4c@10.4.119.245 CSeq: 104 ACK User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- [Sep 21 16:02:43] ERROR[30876]: chan_sip.c:12949 handle_response_invite: Got error on T.38 re-invite. Bad configuration. Peer needs to have T.38 disabled. [Sep 21 16:02:43] DEBUG[30893]: rtp.c:3121 bridge_native_loop: Got a FRAME_CONTROL (8) frame on channel SIP/5678-09201800 [Sep 21 16:02:43] DEBUG[30893]: channel.c:4535 ast_channel_bridge: Returning from native bridge, channels: SIP/4567-091fc8e8, SIP/5678-09201800 [Sep 21 16:02:43] DEBUG[30893]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '4567' [Sep 21 16:02:43] DEBUG[30893]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '4567' [Sep 21 16:02:43] DEBUG[30893]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '5678' [Sep 21 16:02:43] DEBUG[30893]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is 'default' [Sep 21 16:02:43] DEBUG[30893]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is 'SIP/4567-091fc8e8' [Sep 21 16:02:43] DEBUG[30893]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is 'SIP/5678-09201800' [Sep 21 16:02:43] DEBUG[30893]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is 'Dial' [Sep 21 16:02:43] DEBUG[30893]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is 'SIP/5678|20' [Sep 21 16:02:43] DEBUG[30893]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '2009-09-21 16:02:37' [Sep 21 16:02:43] DEBUG[30893]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '2009-09-21 16:02:39' [Sep 21 16:02:43] DEBUG[30893]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '2009-09-21 16:02:43' [Sep 21 16:02:43] DEBUG[30893]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '6' [Sep 21 16:02:43] DEBUG[30893]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '4' [Sep 21 16:02:43] DEBUG[30893]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is 'ANSWERED' [Sep 21 16:02:43] DEBUG[30893]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' [Sep 21 16:02:43] DEBUG[30893]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '(null)' [Sep 21 16:02:43] DEBUG[30893]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '1253563357.0' [Sep 21 16:02:43] DEBUG[30893]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '(null)' [Sep 21 16:02:43] DEBUG[30893]: channel.c:1546 ast_hangup: Hanging up channel 'SIP/5678-09201800' [Sep 21 16:02:43] DEBUG[30893]: chan_sip.c:3683 sip_hangup: Hangup call SIP/5678-09201800, SIP callid 092075a17e0d80a74dbdfbc71ad3cf4c@10.4.119.245) [Sep 21 16:02:43] Scheduling destruction of SIP dialog '092075a17e0d80a74dbdfbc71ad3cf4c@10.4.119.245' in 32000 ms (Method: INVITE) [Sep 21 16:02:43] DEBUG[30893]: chan_sip.c:6335 reqprep: Strict routing enforced for session 092075a17e0d80a74dbdfbc71ad3cf4c@10.4.119.245 [Sep 21 16:02:43] set_destination: Parsing for address/port to send to [Sep 21 16:02:43] set_destination: set destination to 10.4.127.199, port 5060 [Sep 21 16:02:43] Reliably Transmitting (NAT) to 10.4.127.199:5060: BYE sip:5678@10.4.127.199 SIP/2.0 Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK79625477;rport From: "4567" ;tag=as292fe2e3 To: ;tag=bfbf74c143c367a Call-ID: 092075a17e0d80a74dbdfbc71ad3cf4c@10.4.119.245 CSeq: 105 BYE User-Agent: Asterisk PBX Max-Forwards: 70 X-Asterisk-HangupCause: Bearer capability not available X-Asterisk-HangupCauseCode: 58 Content-Length: 0 --- [Sep 21 16:02:43] DEBUG[30893]: chan_sip.c:2101 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #-1 [Sep 21 16:02:43] DEBUG[30893]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/5678 [Sep 21 16:02:43] DEBUG[30893]: rtp.c:1567 ast_rtp_early_bridge: Channel '' has no RTP, not doing anything [Sep 21 16:02:43] DEBUG[30893]: app_dial.c:1824 dial_exec_full: Exiting with DIALSTATUS=ANSWER. [Sep 21 16:02:43] DEBUG[30893]: pbx.c:2392 __ast_pbx_run: Spawn extension (default,5678,1) exited non-zero on 'SIP/4567-091fc8e8' [Sep 21 16:02:43] DEBUG[30863]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5678 [Sep 21 16:02:43] DEBUG[30863]: chan_sip.c:17080 sip_devicestate: Checking device state for peer 5678 [Sep 21 16:02:43] DEBUG[30863]: devicestate.c:287 do_state_change: Changing state for SIP/5678 - state 1 (Not in use) [Sep 21 16:02:43] DEBUG[30875]: app_queue.c:675 handle_statechange: Device 'SIP/5678' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Sep 21 16:02:43] == Spawn extension (default, 5678, 1) exited non-zero on 'SIP/4567-091fc8e8' [Sep 21 16:02:43] DEBUG[30893]: channel.c:1453 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/4567-091fc8e8' [Sep 21 16:02:43] DEBUG[30893]: channel.c:1546 ast_hangup: Hanging up channel 'SIP/4567-091fc8e8' [Sep 21 16:02:43] DEBUG[30893]: chan_sip.c:3683 sip_hangup: Hangup call SIP/4567-091fc8e8, SIP callid 2a18d5e0791e956a19adf1ee11461c08@10.4.119.245) [Sep 21 16:02:43] Scheduling destruction of SIP dialog '2a18d5e0791e956a19adf1ee11461c08@10.4.119.245' in 32000 ms (Method: INVITE) [Sep 21 16:02:43] DEBUG[30893]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/4567 [Sep 21 16:02:43] DEBUG[30863]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 4567 [Sep 21 16:02:43] DEBUG[30863]: chan_sip.c:17080 sip_devicestate: Checking device state for peer 4567 [Sep 21 16:02:43] DEBUG[30863]: devicestate.c:287 do_state_change: Changing state for SIP/4567 - state 1 (Not in use) [Sep 21 16:02:43] DEBUG[30875]: app_queue.c:675 handle_statechange: Device 'SIP/4567' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Sep 21 16:02:44] <--- SIP read from 10.4.127.199:5060 ---> SIP/2.0 200 OK Call-ID: 092075a17e0d80a74dbdfbc71ad3cf4c@10.4.119.245 CSeq: 105 BYE From: "4567" ;tag=as292fe2e3 To: ;tag=bfbf74c143c367a Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK79625477;rport Content-Length: 0 Supported: replaces User-Agent: MxSipApp/5.0.25.189 <-------------> [Sep 21 16:02:44] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 0: SIP/2.0 200 OK (14) [Sep 21 16:02:44] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 1: Call-ID: 092075a17e0d80a74dbdfbc71ad3cf4c@10.4.119.245 (54) [Sep 21 16:02:44] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 2: CSeq: 105 BYE (13) [Sep 21 16:02:44] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 3: From: "4567" ;tag=as292fe2e3 (51) [Sep 21 16:02:44] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 4: To: ;tag=bfbf74c143c367a (47) [Sep 21 16:02:44] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 5: Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK79625477;rport (63) [Sep 21 16:02:44] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 6: Content-Length: 0 (17) [Sep 21 16:02:44] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 7: Supported: replaces (19) [Sep 21 16:02:44] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 8: User-Agent: MxSipApp/5.0.25.189 (32) [Sep 21 16:02:44] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 9: (0) [Sep 21 16:02:44] --- (9 headers 0 lines) --- [Sep 21 16:02:44] DEBUG[30876]: chan_sip.c:4817 find_call: = Found Their Call ID: 092075a17e0d80a74dbdfbc71ad3cf4c@10.4.119.245 Their Tag bfbf74c143c367a Our tag: as292fe2e3 [Sep 21 16:02:44] DEBUG[30876]: chan_sip.c:2234 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #69 [Sep 21 16:02:44] DEBUG[30876]: chan_sip.c:2258 __sip_ack: Stopping retransmission on '092075a17e0d80a74dbdfbc71ad3cf4c@10.4.119.245' of Request 105: Match Found [Sep 21 16:02:44] Really destroying SIP dialog '092075a17e0d80a74dbdfbc71ad3cf4c@10.4.119.245' Method: INVITE [Sep 21 16:02:54] <--- SIP read from 10.4.127.199:5060 ---> CANCEL sip:5678@10.4.119.245 SIP/2.0 Via: SIP/2.0/UDP 10.4.127.199;branch=z9hG4bK4a004a558 Content-Length: 0 To: sip:5678@10.4.119.245;tag=as23d9cdf5 From: sip:4567@10.4.119.245;tag=f6cd0ba5dded5ef Call-ID: 2a18d5e0791e956a19adf1ee11461c08@10.4.119.245 CSeq: 488449819 CANCEL Supported: timer Supported: replaces User-Agent: MxSipApp/5.0.25.189 <-------------> [Sep 21 16:02:54] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 0: CANCEL sip:5678@10.4.119.245 SIP/2.0 (36) [Sep 21 16:02:54] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 1: Via: SIP/2.0/UDP 10.4.127.199;branch=z9hG4bK4a004a558 (53) [Sep 21 16:02:54] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 2: Content-Length: 0 (17) [Sep 21 16:02:54] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 3: To: sip:5678@10.4.119.245;tag=as23d9cdf5 (40) [Sep 21 16:02:54] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 4: From: sip:4567@10.4.119.245;tag=f6cd0ba5dded5ef (47) [Sep 21 16:02:54] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 5: Call-ID: 2a18d5e0791e956a19adf1ee11461c08@10.4.119.245 (54) [Sep 21 16:02:54] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 6: CSeq: 488449819 CANCEL (22) [Sep 21 16:02:54] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 7: Supported: timer (16) [Sep 21 16:02:54] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 8: Supported: replaces (19) [Sep 21 16:02:54] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 9: User-Agent: MxSipApp/5.0.25.189 (32) [Sep 21 16:02:54] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 10: (0) [Sep 21 16:02:54] --- (10 headers 0 lines) --- [Sep 21 16:02:54] DEBUG[30876]: chan_sip.c:4817 find_call: = Found Their Call ID: 2a18d5e0791e956a19adf1ee11461c08@10.4.119.245 Their Tag f6cd0ba5dded5ef Our tag: as23d9cdf5 [Sep 21 16:02:54] DEBUG[30876]: chan_sip.c:16306 handle_request: **** Received CANCEL (14) - Command in SIP CANCEL [Sep 21 16:02:54] Sending to 10.4.127.199 : 5060 (NAT) [Sep 21 16:02:54] DEBUG[30876]: chan_sip.c:1706 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 2a18d5e0791e956a19adf1ee11461c08@10.4.119.245 [Sep 21 16:02:54] Scheduling destruction of SIP dialog '2a18d5e0791e956a19adf1ee11461c08@10.4.119.245' in 32000 ms (Method: CANCEL) [Sep 21 16:02:54] <--- Reliably Transmitting (NAT) to 10.4.127.199:5060 ---> SIP/2.0 487 Request Terminated Via: SIP/2.0/UDP 10.4.127.199;branch=z9hG4bK4a004a558;received=10.4.127.199 From: sip:4567@10.4.119.245;tag=f6cd0ba5dded5ef To: sip:5678@10.4.119.245;tag=as23d9cdf5 Call-ID: 2a18d5e0791e956a19adf1ee11461c08@10.4.119.245 CSeq: 488449819 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces Content-Length: 0 <------------> [Sep 21 16:02:54] DEBUG[30876]: chan_sip.c:2101 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #-1 [Sep 21 16:02:54] <--- Transmitting (NAT) to 10.4.127.199:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.4.127.199;branch=z9hG4bK4a004a558;received=10.4.127.199 From: sip:4567@10.4.119.245;tag=f6cd0ba5dded5ef To: sip:5678@10.4.119.245;tag=as23d9cdf5 Call-ID: 2a18d5e0791e956a19adf1ee11461c08@10.4.119.245 CSeq: 488449819 CANCEL User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces Content-Length: 0 <------------> [Sep 21 16:02:54] <--- SIP read from 10.4.127.199:5060 ---> ACK sip:5678@10.4.119.245 SIP/2.0 Via: SIP/2.0/UDP 10.4.127.199;branch=z9hG4bK4a004a558 Content-Length: 0 To: sip:5678@10.4.119.245;tag=as23d9cdf5 From: sip:4567@10.4.119.245;tag=f6cd0ba5dded5ef Call-ID: 2a18d5e0791e956a19adf1ee11461c08@10.4.119.245 CSeq: 488449819 ACK User-Agent: MxSipApp/5.0.25.189 <-------------> [Sep 21 16:02:54] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 0: ACK sip:5678@10.4.119.245 SIP/2.0 (33) [Sep 21 16:02:54] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 1: Via: SIP/2.0/UDP 10.4.127.199;branch=z9hG4bK4a004a558 (53) [Sep 21 16:02:54] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 2: Content-Length: 0 (17) [Sep 21 16:02:54] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 3: To: sip:5678@10.4.119.245;tag=as23d9cdf5 (40) [Sep 21 16:02:54] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 4: From: sip:4567@10.4.119.245;tag=f6cd0ba5dded5ef (47) [Sep 21 16:02:54] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 5: Call-ID: 2a18d5e0791e956a19adf1ee11461c08@10.4.119.245 (54) [Sep 21 16:02:54] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 6: CSeq: 488449819 ACK (19) [Sep 21 16:02:54] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 7: User-Agent: MxSipApp/5.0.25.189 (32) [Sep 21 16:02:54] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 8: (0) [Sep 21 16:02:54] --- (8 headers 0 lines) --- [Sep 21 16:02:54] DEBUG[30876]: chan_sip.c:4817 find_call: = Found Their Call ID: 2a18d5e0791e956a19adf1ee11461c08@10.4.119.245 Their Tag f6cd0ba5dded5ef Our tag: as23d9cdf5 [Sep 21 16:02:54] DEBUG[30876]: chan_sip.c:16306 handle_request: **** Received ACK (6) - Command in SIP ACK [Sep 21 16:02:54] DEBUG[30876]: chan_sip.c:2234 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #72 [Sep 21 16:02:54] DEBUG[30876]: chan_sip.c:2258 __sip_ack: Stopping retransmission on '2a18d5e0791e956a19adf1ee11461c08@10.4.119.245' of Response 488449819: Match Found [Sep 21 16:02:54] DEBUG[30876]: chan_sip.c:6335 reqprep: Strict routing enforced for session 2a18d5e0791e956a19adf1ee11461c08@10.4.119.245 [Sep 21 16:02:54] set_destination: Parsing for address/port to send to [Sep 21 16:02:54] set_destination: set destination to 10.4.127.199, port 5060 [Sep 21 16:02:54] Reliably Transmitting (NAT) to 10.4.127.199:5060: BYE sip:4567@10.4.127.199 SIP/2.0 Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK4e5e3b7e;rport From: sip:5678@10.4.119.245;tag=as23d9cdf5 To: sip:4567@10.4.119.245;tag=f6cd0ba5dded5ef Call-ID: 2a18d5e0791e956a19adf1ee11461c08@10.4.119.245 CSeq: 103 BYE User-Agent: Asterisk PBX Max-Forwards: 70 X-Asterisk-HangupCause: Bearer capability not available X-Asterisk-HangupCauseCode: 58 Content-Length: 0 --- [Sep 21 16:02:54] DEBUG[30876]: chan_sip.c:2101 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #-1 [Sep 21 16:02:54] Scheduling destruction of SIP dialog '2a18d5e0791e956a19adf1ee11461c08@10.4.119.245' in 32000 ms (Method: ACK) [Sep 21 16:02:54] <--- SIP read from 10.4.127.199:5060 ---> BYE sip:5678@10.4.119.245 SIP/2.0 Via: SIP/2.0/UDP 10.4.127.199;branch=z9hG4bK8e7a8ac2b Content-Length: 0 To: sip:5678@10.4.119.245;tag=as23d9cdf5 From: sip:4567@10.4.119.245;tag=f6cd0ba5dded5ef Call-ID: 2a18d5e0791e956a19adf1ee11461c08@10.4.119.245 CSeq: 488449820 BYE Supported: timer Supported: replaces User-Agent: MxSipApp/5.0.25.189 <-------------> [Sep 21 16:02:54] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 0: BYE sip:5678@10.4.119.245 SIP/2.0 (33) [Sep 21 16:02:54] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 1: Via: SIP/2.0/UDP 10.4.127.199;branch=z9hG4bK8e7a8ac2b (53) [Sep 21 16:02:54] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 2: Content-Length: 0 (17) [Sep 21 16:02:54] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 3: To: sip:5678@10.4.119.245;tag=as23d9cdf5 (40) [Sep 21 16:02:54] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 4: From: sip:4567@10.4.119.245;tag=f6cd0ba5dded5ef (47) [Sep 21 16:02:54] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 5: Call-ID: 2a18d5e0791e956a19adf1ee11461c08@10.4.119.245 (54) [Sep 21 16:02:54] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 6: CSeq: 488449820 BYE (19) [Sep 21 16:02:54] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 7: Supported: timer (16) [Sep 21 16:02:54] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 8: Supported: replaces (19) [Sep 21 16:02:54] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 9: User-Agent: MxSipApp/5.0.25.189 (32) [Sep 21 16:02:54] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 10: (0) [Sep 21 16:02:54] --- (10 headers 0 lines) --- [Sep 21 16:02:54] DEBUG[30876]: chan_sip.c:4817 find_call: = Found Their Call ID: 2a18d5e0791e956a19adf1ee11461c08@10.4.119.245 Their Tag f6cd0ba5dded5ef Our tag: as23d9cdf5 [Sep 21 16:02:54] DEBUG[30876]: chan_sip.c:16306 handle_request: **** Received BYE (8) - Command in SIP BYE [Sep 21 16:02:54] DEBUG[30876]: chan_sip.c:2234 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #73 [Sep 21 16:02:54] DEBUG[30876]: chan_sip.c:2258 __sip_ack: Stopping retransmission on '2a18d5e0791e956a19adf1ee11461c08@10.4.119.245' of Request 103: Match Found [Sep 21 16:02:54] Sending to 10.4.127.199 : 5060 (NAT) [Sep 21 16:02:54] DEBUG[30876]: chan_sip.c:1706 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 2a18d5e0791e956a19adf1ee11461c08@10.4.119.245 [Sep 21 16:02:54] Scheduling destruction of SIP dialog '2a18d5e0791e956a19adf1ee11461c08@10.4.119.245' in 32000 ms (Method: BYE) [Sep 21 16:02:54] DEBUG[30876]: chan_sip.c:15845 handle_request_bye: Received bye, no owner, selfdestruct soon. [Sep 21 16:02:54] <--- Transmitting (NAT) to 10.4.127.199:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.4.127.199;branch=z9hG4bK8e7a8ac2b;received=10.4.127.199 From: sip:4567@10.4.119.245;tag=f6cd0ba5dded5ef To: sip:5678@10.4.119.245;tag=as23d9cdf5 Call-ID: 2a18d5e0791e956a19adf1ee11461c08@10.4.119.245 CSeq: 488449820 BYE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces Content-Length: 0 <------------> [Sep 21 16:02:54] <--- SIP read from 10.4.127.199:5060 ---> SIP/2.0 200 OK Call-ID: 2a18d5e0791e956a19adf1ee11461c08@10.4.119.245 CSeq: 103 BYE From: sip:5678@10.4.119.245;tag=as23d9cdf5 To: sip:4567@10.4.119.245;tag=f6cd0ba5dded5ef Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK4e5e3b7e;rport Content-Length: 0 Supported: replaces User-Agent: MxSipApp/5.0.25.189 <-------------> [Sep 21 16:02:54] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 0: SIP/2.0 200 OK (14) [Sep 21 16:02:54] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 1: Call-ID: 2a18d5e0791e956a19adf1ee11461c08@10.4.119.245 (54) [Sep 21 16:02:54] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 2: CSeq: 103 BYE (13) [Sep 21 16:02:54] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 3: From: sip:5678@10.4.119.245;tag=as23d9cdf5 (42) [Sep 21 16:02:54] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 4: To: sip:4567@10.4.119.245;tag=f6cd0ba5dded5ef (45) [Sep 21 16:02:54] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 5: Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK4e5e3b7e;rport (63) [Sep 21 16:02:54] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 6: Content-Length: 0 (17) [Sep 21 16:02:54] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 7: Supported: replaces (19) [Sep 21 16:02:54] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 8: User-Agent: MxSipApp/5.0.25.189 (32) [Sep 21 16:02:54] DEBUG[30876]: chan_sip.c:5028 parse_request: Header 9: (0) [Sep 21 16:02:54] --- (9 headers 0 lines) --- [Sep 21 16:02:54] DEBUG[30876]: chan_sip.c:4817 find_call: = Found Their Call ID: 2a18d5e0791e956a19adf1ee11461c08@10.4.119.245 Their Tag f6cd0ba5dded5ef Our tag: as23d9cdf5 [Sep 21 16:02:54] DEBUG[30876]: chan_sip.c:2258 __sip_ack: Stopping retransmission on '2a18d5e0791e956a19adf1ee11461c08@10.4.119.245' of Request 103: Match Not Found