[Mar 19 09:34:04] Asterisk SVN-branch-1.4-r58957, Copyright (C) 1999 - 2006 Digium, Inc. and others. [Mar 19 09:34:04] Created by Mark Spencer [Mar 19 09:34:04] Asterisk comes with ABSOLUTELY NO WARRANTY; type 'core show warranty' for details. [Mar 19 09:34:04] This is free software, with components licensed under the GNU General Public [Mar 19 09:34:04] License version 2 and other licenses; you are welcome to redistribute it under [Mar 19 09:34:04] certain conditions. Type 'core show license' for details. [Mar 19 09:34:04] ========================================================================= [Mar 19 09:34:53] <--- SIP read from 10.4.126.232:5060 ---> INVITE sip:4321@10.4.119.245 SIP/2.0 Via: SIP/2.0/UDP 10.4.126.232;branch=z9hG4bK6a4eabaab Content-Length: 242 To: sip:4321@10.4.119.245 From: Test1 ;tag=2e0ba312e07ed9f Call-ID: 437ca631f88d70553dbe5edc5ce7d949@10.4.119.245 CSeq: 1093933437 INVITE Supported: timer Min-SE: 1800 Session-Expires: 3600 Allow: INVITE, ACK, BYE, CANCEL, REFER, NOTIFY Content-Type: application/sdp Contact: Test1 Supported: replaces User-Agent: MxSipApp/5.0.16.99 MxSF/v3.2.1.1 v=0 o=MxSIP 352673312983635746 376570794169103869 IN IP4 10.4.126.232 s=- c=IN IP4 10.4.126.232 t=0 0 a=sendrecv m=audio 5004 RTP/AVP 0 18 4 8 13 a=rtpmap:0 PCMU/8000 a=rtpmap:18 G729/8000 a=rtpmap:4 G723/8000 a=rtpmap:8 PCMA/8000 <-------------> [Mar 19 09:34:53] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 0: INVITE sip:4321@10.4.119.245 SIP/2.0 (36) [Mar 19 09:34:53] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 1: Via: SIP/2.0/UDP 10.4.126.232;branch=z9hG4bK6a4eabaab (53) [Mar 19 09:34:53] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 2: Content-Length: 242 (19) [Mar 19 09:34:53] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 3: To: sip:4321@10.4.119.245 (25) [Mar 19 09:34:53] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 4: From: Test1 ;tag=2e0ba312e07ed9f (55) [Mar 19 09:34:53] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 5: Call-ID: 437ca631f88d70553dbe5edc5ce7d949@10.4.119.245 (54) [Mar 19 09:34:53] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 6: CSeq: 1093933437 INVITE (23) [Mar 19 09:34:53] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 7: Supported: timer (16) [Mar 19 09:34:53] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 8: Min-SE: 1800 (12) [Mar 19 09:34:53] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 9: Session-Expires: 3600 (21) [Mar 19 09:34:53] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 10: Allow: INVITE, ACK, BYE, CANCEL, REFER, NOTIFY (46) [Mar 19 09:34:53] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 11: Content-Type: application/sdp (29) [Mar 19 09:34:53] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 12: Contact: Test1 (38) [Mar 19 09:34:53] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 13: Supported: replaces (19) [Mar 19 09:34:53] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 14: User-Agent: MxSipApp/5.0.16.99 MxSF/v3.2.1.1 (44) [Mar 19 09:34:53] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 15: (0) [Mar 19 09:34:53] DEBUG[30638]: chan_sip.c:4605 parse_request: Line: v=0 (3) [Mar 19 09:34:53] DEBUG[30638]: chan_sip.c:4605 parse_request: Line: o=MxSIP 352673312983635746 376570794169103869 IN IP4 10.4.126.232 (65) [Mar 19 09:34:53] DEBUG[30638]: chan_sip.c:4605 parse_request: Line: s=- (3) [Mar 19 09:34:53] DEBUG[30638]: chan_sip.c:4605 parse_request: Line: c=IN IP4 10.4.126.232 (21) [Mar 19 09:34:53] DEBUG[30638]: chan_sip.c:4605 parse_request: Line: t=0 0 (5) [Mar 19 09:34:53] DEBUG[30638]: chan_sip.c:4605 parse_request: Line: a=sendrecv (10) [Mar 19 09:34:53] DEBUG[30638]: chan_sip.c:4605 parse_request: Line: m=audio 5004 RTP/AVP 0 18 4 8 13 (32) [Mar 19 09:34:53] DEBUG[30638]: chan_sip.c:4605 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Mar 19 09:34:53] DEBUG[30638]: chan_sip.c:4605 parse_request: Line: a=rtpmap:18 G729/8000 (21) [Mar 19 09:34:53] DEBUG[30638]: chan_sip.c:4605 parse_request: Line: a=rtpmap:4 G723/8000 (20) [Mar 19 09:34:53] DEBUG[30638]: chan_sip.c:4605 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Mar 19 09:34:53] --- (15 headers 11 lines) --- [Mar 19 09:34:53] DEBUG[30638]: chan_sip.c:2575 do_setnat: Setting NAT on RTP to Off [Mar 19 09:34:53] DEBUG[30638]: chan_sip.c:4310 sip_alloc: Allocating new SIP dialog for 437ca631f88d70553dbe5edc5ce7d949@10.4.119.245 - INVITE (With RTP) [Mar 19 09:34:53] DEBUG[30638]: chan_sip.c:14629 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Mar 19 09:34:53] DEBUG[30638]: chan_sip.c:1680 parse_sip_options: Begin: parsing SIP "Supported: timer" [Mar 19 09:34:53] DEBUG[30638]: chan_sip.c:1688 parse_sip_options: Found SIP option: -timer- [Mar 19 09:34:53] DEBUG[30638]: chan_sip.c:1694 parse_sip_options: Matched SIP option: timer [Mar 19 09:34:53] Sending to 10.4.126.232 : 5060 (no NAT) [Mar 19 09:34:53] Using INVITE request as basis request - 437ca631f88d70553dbe5edc5ce7d949@10.4.119.245 [Mar 19 09:34:53] DEBUG[30638]: chan_sip.c:2575 do_setnat: Setting NAT on RTP to Off [Mar 19 09:34:53] Found user '1234' [Mar 19 09:34:53] Found RTP audio format 0 [Mar 19 09:34:53] Found RTP audio format 18 [Mar 19 09:34:53] Found RTP audio format 4 [Mar 19 09:34:53] Found RTP audio format 8 [Mar 19 09:34:53] Found RTP audio format 13 [Mar 19 09:34:53] Peer audio RTP is at port 10.4.126.232:5004 [Mar 19 09:34:53] Found description format PCMU for ID 0 [Mar 19 09:34:53] Found description format G729 for ID 18 [Mar 19 09:34:53] Found description format G723 for ID 4 [Mar 19 09:34:53] Found description format PCMA for ID 8 [Mar 19 09:34:53] DEBUG[30638]: chan_sip.c:5129 process_sdp: T38 state changed to 0 on channel [Mar 19 09:34:53] Capabilities: us - 0xc (ulaw|alaw), peer - audio=0x10d (g723|ulaw|alaw|g729)/video=0x0 (nothing), combined - 0xc (ulaw|alaw) [Mar 19 09:34:53] Non-codec capabilities (dtmf): us - 0x0 (nothing), peer - 0x2 (CN), combined - 0x0 (nothing) [Mar 19 09:34:53] Peer audio RTP is at port 10.4.126.232:5004 [Mar 19 09:34:53] DEBUG[30638]: chan_sip.c:5209 process_sdp: We're settling with these formats: 0xc (ulaw|alaw) [Mar 19 09:34:53] DEBUG[30638]: chan_sip.c:13401 handle_request_invite: Checking SIP call limits for device 1234 [Mar 19 09:34:53] DEBUG[30638]: chan_sip.c:3003 update_call_counter: Updating call counter for incoming call [Mar 19 09:34:53] Looking for 4321 in default (domain 10.4.119.245) [Mar 19 09:34:53] DEBUG[30638]: chan_sip.c:3805 sip_new: *** Our native formats are 0x4 (ulaw) [Mar 19 09:34:53] DEBUG[30638]: chan_sip.c:3806 sip_new: *** Joint capabilities are 0xc (ulaw|alaw) [Mar 19 09:34:53] DEBUG[30638]: chan_sip.c:3807 sip_new: *** Our capabilities are 0xc (ulaw|alaw) [Mar 19 09:34:53] DEBUG[30638]: chan_sip.c:3808 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Mar 19 09:34:53] DEBUG[30638]: chan_sip.c:3831 sip_new: This channel will not be able to handle video. [Mar 19 09:34:53] DEBUG[30638]: chan_sip.c:7980 build_route: build_route: Contact hop: Test1 [Mar 19 09:34:53] list_route: hop: [Mar 19 09:34:53] DEBUG[30638]: chan_sip.c:13476 handle_request_invite: SIP/1234-08a1a280: New call is still down.... Trying... [Mar 19 09:34:53] <--- Transmitting (no NAT) to 10.4.126.232:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.4.126.232;branch=z9hG4bK6a4eabaab;received=10.4.126.232 From: Test1 ;tag=2e0ba312e07ed9f To: sip:4321@10.4.119.245 Call-ID: 437ca631f88d70553dbe5edc5ce7d949@10.4.119.245 CSeq: 1093933437 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Mar 19 09:34:53] DEBUG[30638]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/1234-08a1a280 [Mar 19 09:34:53] DEBUG[30628]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 1234 [Mar 19 09:34:53] DEBUG[30628]: chan_sip.c:15240 sip_devicestate: Checking device state for peer 1234 [Mar 19 09:34:53] DEBUG[30628]: devicestate.c:287 do_state_change: Changing state for SIP/1234 - state 1 (Not in use) [Mar 19 09:34:53] DEBUG[30656]: pbx.c:1795 pbx_extension_helper: Launching 'Dial' [Mar 19 09:34:53] -- Executing [4321@default:1] Dial("SIP/1234-08a1a280", "SIP/4321||") in new stack [Mar 19 09:34:53] DEBUG[30656]: chan_sip.c:15306 sip_request_call: Asked to create a SIP channel with formats: 0x4 (ulaw) [Mar 19 09:34:53] DEBUG[30656]: chan_sip.c:4310 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Mar 19 09:34:53] DEBUG[30656]: chan_sip.c:2575 do_setnat: Setting NAT on RTP to Off [Mar 19 09:34:53] DEBUG[30656]: chan_sip.c:3805 sip_new: *** Our native formats are 0x4 (ulaw) [Mar 19 09:34:53] DEBUG[30657]: app_queue.c:546 changethread: Device 'SIP/1234' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Mar 19 09:34:53] DEBUG[30656]: chan_sip.c:3806 sip_new: *** Joint capabilities are 0x0 (nothing) [Mar 19 09:34:53] DEBUG[30656]: chan_sip.c:3807 sip_new: *** Our capabilities are 0xc (ulaw|alaw) [Mar 19 09:34:53] DEBUG[30656]: chan_sip.c:3808 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Mar 19 09:34:53] DEBUG[30656]: chan_sip.c:3810 sip_new: *** Our preferred formats from the incoming channel are 0x4 (ulaw) [Mar 19 09:34:53] DEBUG[30656]: chan_sip.c:3831 sip_new: This channel will not be able to handle video. [Mar 19 09:34:53] DEBUG[30656]: rtp.c:1598 ast_rtp_make_compatible: Seeded SDP of 'SIP/4321-08a1e1e8' with that of 'SIP/1234-08a1a280' [Mar 19 09:34:53] DEBUG[30656]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-default-4321-1. [Mar 19 09:34:53] DEBUG[30656]: channel.c:3301 ast_channel_inherit_variables: Not copying variable SIPCALLID. [Mar 19 09:34:53] DEBUG[30656]: channel.c:3301 ast_channel_inherit_variables: Not copying variable SIPUSERAGENT. [Mar 19 09:34:53] DEBUG[30656]: channel.c:3301 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [Mar 19 09:34:53] DEBUG[30656]: channel.c:3301 ast_channel_inherit_variables: Not copying variable SIPURI. [Mar 19 09:34:53] DEBUG[30656]: chan_sip.c:2830 sip_call: Outgoing Call for 4321 [Mar 19 09:34:53] DEBUG[30656]: chan_sip.c:3003 update_call_counter: Updating call counter for outgoing call [Mar 19 09:34:53] DEBUG[30656]: chan_sip.c:2845 sip_call: Our T38 capability (0), joint T38 capability (0) [Mar 19 09:34:53] DEBUG[30656]: chan_sip.c:6188 add_sdp: ** Our capability: 0xc (ulaw|alaw) Video flag: False [Mar 19 09:34:53] DEBUG[30656]: chan_sip.c:6189 add_sdp: ** Our prefcodec: 0x4 (ulaw) [Mar 19 09:34:53] Audio is at 10.4.119.245 port 13288 [Mar 19 09:34:53] Adding codec 0x4 (ulaw) to SDP [Mar 19 09:34:53] Adding codec 0x8 (alaw) to SDP [Mar 19 09:34:53] DEBUG[30656]: chan_sip.c:6320 add_sdp: -- Done with adding codecs to SDP [Mar 19 09:34:53] DEBUG[30656]: chan_sip.c:6365 add_sdp: Done building SDP. Settling with this capability: 0xc (ulaw|alaw) [Mar 19 09:34:53] DEBUG[30656]: chan_sip.c:4573 parse_request: Header 0: INVITE sip:4321@10.4.127.230 SIP/2.0 (36) [Mar 19 09:34:53] DEBUG[30656]: chan_sip.c:4573 parse_request: Header 1: Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK04c29b43 (57) [Mar 19 09:34:53] DEBUG[30656]: chan_sip.c:4573 parse_request: Header 2: From: "Test1" ;tag=as048f2ce7 (52) [Mar 19 09:34:53] DEBUG[30656]: chan_sip.c:4573 parse_request: Header 3: To: (27) [Mar 19 09:34:53] DEBUG[30656]: chan_sip.c:4573 parse_request: Header 4: Contact: (32) [Mar 19 09:34:53] DEBUG[30656]: chan_sip.c:4573 parse_request: Header 5: Call-ID: 4639e6c371fc2daa253ab6f923e3ed63@10.4.119.245 (54) [Mar 19 09:34:53] DEBUG[30656]: chan_sip.c:4573 parse_request: Header 6: CSeq: 102 INVITE (16) [Mar 19 09:34:53] DEBUG[30656]: chan_sip.c:4573 parse_request: Header 7: User-Agent: Asterisk PBX (24) [Mar 19 09:34:53] DEBUG[30656]: chan_sip.c:4573 parse_request: Header 8: Max-Forwards: 70 (16) [Mar 19 09:34:53] DEBUG[30656]: chan_sip.c:4573 parse_request: Header 9: Date: Mon, 19 Mar 2007 13:34:53 GMT (35) [Mar 19 09:34:53] DEBUG[30656]: chan_sip.c:4573 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Mar 19 09:34:53] DEBUG[30656]: chan_sip.c:4573 parse_request: Header 11: Supported: replaces (19) [Mar 19 09:34:53] DEBUG[30656]: chan_sip.c:4573 parse_request: Header 12: Content-Type: application/sdp (29) [Mar 19 09:34:53] DEBUG[30656]: chan_sip.c:4573 parse_request: Header 13: Content-Length: 208 (19) [Mar 19 09:34:53] DEBUG[30656]: chan_sip.c:4573 parse_request: Header 14: (0) [Mar 19 09:34:53] DEBUG[30656]: chan_sip.c:4605 parse_request: Line: v=0 (3) [Mar 19 09:34:53] DEBUG[30656]: chan_sip.c:4605 parse_request: Line: o=root 30622 30622 IN IP4 10.4.119.245 (38) [Mar 19 09:34:53] DEBUG[30656]: chan_sip.c:4605 parse_request: Line: s=session (9) [Mar 19 09:34:53] DEBUG[30656]: chan_sip.c:4605 parse_request: Line: c=IN IP4 10.4.119.245 (21) [Mar 19 09:34:53] DEBUG[30656]: chan_sip.c:4605 parse_request: Line: t=0 0 (5) [Mar 19 09:34:53] DEBUG[30656]: chan_sip.c:4605 parse_request: Line: m=audio 13288 RTP/AVP 0 8 (25) [Mar 19 09:34:53] DEBUG[30656]: chan_sip.c:4605 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Mar 19 09:34:53] DEBUG[30656]: chan_sip.c:4605 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Mar 19 09:34:53] DEBUG[30656]: chan_sip.c:4605 parse_request: Line: a=silenceSupp:off - - - - (25) [Mar 19 09:34:53] DEBUG[30656]: chan_sip.c:4605 parse_request: Line: a=ptime:20 (10) [Mar 19 09:34:53] DEBUG[30656]: chan_sip.c:4605 parse_request: Line: a=sendrecv (10) [Mar 19 09:34:53] Reliably Transmitting (no NAT) to 10.4.127.230:5060: INVITE sip:4321@10.4.127.230 SIP/2.0 Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK04c29b43 From: "Test1" ;tag=as048f2ce7 To: Contact: Call-ID: 4639e6c371fc2daa253ab6f923e3ed63@10.4.119.245 CSeq: 102 INVITE User-Agent: Asterisk PBX Max-Forwards: 70 Date: Mon, 19 Mar 2007 13:34:53 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Type: application/sdp Content-Length: 208 v=0 o=root 30622 30622 IN IP4 10.4.119.245 s=session c=IN IP4 10.4.119.245 t=0 0 m=audio 13288 RTP/AVP 0 8 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv --- [Mar 19 09:34:53] DEBUG[30656]: chan_sip.c:1975 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #28 [Mar 19 09:34:53] -- Called 4321 [Mar 19 09:34:54] <--- SIP read from 10.4.127.230:5060 ---> SIP/2.0 100 Trying Call-ID: 4639e6c371fc2daa253ab6f923e3ed63@10.4.119.245 CSeq: 102 INVITE From: "Test1" ;tag=as048f2ce7 To: ;tag=fb81406bf2af5d8 Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK04c29b43 Content-Length: 0 User-Agent: MxSipApp/5.0.15.88 MxSF/v3.2.1.1 <-------------> [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 0: SIP/2.0 100 Trying (18) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 1: Call-ID: 4639e6c371fc2daa253ab6f923e3ed63@10.4.119.245 (54) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 2: CSeq: 102 INVITE (16) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 3: From: "Test1" ;tag=as048f2ce7 (52) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 4: To: ;tag=fb81406bf2af5d8 (47) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 5: Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK04c29b43 (57) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 6: Content-Length: 0 (17) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 7: User-Agent: MxSipApp/5.0.15.88 MxSF/v3.2.1.1 (44) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 8: (0) [Mar 19 09:34:54] --- (8 headers 0 lines) --- [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:2122 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #28 - INVITE (got response) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:2131 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '4639e6c371fc2daa253ab6f923e3ed63@10.4.119.245' Request 102: Found [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:11641 handle_response_invite: SIP response 100 to standard invite [Mar 19 09:34:54] <--- SIP read from 10.4.127.230:5060 ---> SIP/2.0 180 Ringing Call-ID: 4639e6c371fc2daa253ab6f923e3ed63@10.4.119.245 CSeq: 102 INVITE From: "Test1" ;tag=as048f2ce7 To: ;tag=fb81406bf2af5d8 Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK04c29b43 Content-Length: 0 Contact: Test2 User-Agent: MxSipApp/5.0.15.88 MxSF/v3.2.1.1 <-------------> [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 0: SIP/2.0 180 Ringing (19) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 1: Call-ID: 4639e6c371fc2daa253ab6f923e3ed63@10.4.119.245 (54) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 2: CSeq: 102 INVITE (16) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 3: From: "Test1" ;tag=as048f2ce7 (52) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 4: To: ;tag=fb81406bf2af5d8 (47) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 5: Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK04c29b43 (57) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 6: Content-Length: 0 (17) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 7: Contact: Test2 (38) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 8: User-Agent: MxSipApp/5.0.15.88 MxSF/v3.2.1.1 (44) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 9: (0) [Mar 19 09:34:54] --- (9 headers 0 lines) --- [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:2131 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '4639e6c371fc2daa253ab6f923e3ed63@10.4.119.245' Request 102: Found [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:11641 handle_response_invite: SIP response 180 to standard invite [Mar 19 09:34:54] DEBUG[30638]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/4321-08a1e1e8 [Mar 19 09:34:54] -- SIP/4321-08a1e1e8 is ringing [Mar 19 09:34:54] DEBUG[30656]: rtp.c:1527 ast_rtp_early_bridge: Setting early bridge SDP of 'SIP/1234-08a1a280' with that of 'SIP/4321-08a1e1e8' [Mar 19 09:34:54] <--- Transmitting (no NAT) to 10.4.126.232:5060 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 10.4.126.232;branch=z9hG4bK6a4eabaab;received=10.4.126.232 From: Test1 ;tag=2e0ba312e07ed9f To: sip:4321@10.4.119.245;tag=as3287914c Call-ID: 437ca631f88d70553dbe5edc5ce7d949@10.4.119.245 CSeq: 1093933437 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Mar 19 09:34:54] DEBUG[30628]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 4321 [Mar 19 09:34:54] DEBUG[30628]: chan_sip.c:15240 sip_devicestate: Checking device state for peer 4321 [Mar 19 09:34:54] DEBUG[30628]: devicestate.c:287 do_state_change: Changing state for SIP/4321 - state 1 (Not in use) [Mar 19 09:34:54] DEBUG[30658]: app_queue.c:546 changethread: Device 'SIP/4321' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Mar 19 09:34:54] <--- SIP read from 10.4.127.230:5060 ---> SIP/2.0 200 OK Call-ID: 4639e6c371fc2daa253ab6f923e3ed63@10.4.119.245 CSeq: 102 INVITE From: "Test1" ;tag=as048f2ce7 To: ;tag=fb81406bf2af5d8 Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK04c29b43 Content-Length: 190 Session-Expires: 3600;refresher=uas Allow: INVITE, ACK, BYE, CANCEL, REFER, NOTIFY Content-Type: application/sdp Supported: replaces Contact: Test2 User-Agent: MxSipApp/5.0.15.88 MxSF/v3.2.1.1 v=0 o=MxSIP 599798619795376287 2005741632565392604 IN IP4 10.4.127.230 s=- c=IN IP4 10.4.127.230 t=0 0 a=sendrecv m=audio 5004 RTP/AVP 0 8 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 <-------------> [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 0: SIP/2.0 200 OK (14) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 1: Call-ID: 4639e6c371fc2daa253ab6f923e3ed63@10.4.119.245 (54) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 2: CSeq: 102 INVITE (16) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 3: From: "Test1" ;tag=as048f2ce7 (52) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 4: To: ;tag=fb81406bf2af5d8 (47) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 5: Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK04c29b43 (57) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 6: Content-Length: 190 (19) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 7: Session-Expires: 3600;refresher=uas (35) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 8: Allow: INVITE, ACK, BYE, CANCEL, REFER, NOTIFY (46) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 9: Content-Type: application/sdp (29) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 10: Supported: replaces (19) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 11: Contact: Test2 (38) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 12: User-Agent: MxSipApp/5.0.15.88 MxSF/v3.2.1.1 (44) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 13: (0) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4605 parse_request: Line: v=0 (3) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4605 parse_request: Line: o=MxSIP 599798619795376287 2005741632565392604 IN IP4 10.4.127.230 (66) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4605 parse_request: Line: s=- (3) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4605 parse_request: Line: c=IN IP4 10.4.127.230 (21) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4605 parse_request: Line: t=0 0 (5) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4605 parse_request: Line: a=sendrecv (10) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4605 parse_request: Line: m=audio 5004 RTP/AVP 0 8 (24) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4605 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4605 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Mar 19 09:34:54] --- (13 headers 9 lines) --- [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:2071 __sip_ack: Acked pending invite 102 [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '4639e6c371fc2daa253ab6f923e3ed63@10.4.119.245' of Request 102: Match Not Found [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:11641 handle_response_invite: SIP response 200 to standard invite [Mar 19 09:34:54] Found RTP audio format 0 [Mar 19 09:34:54] Found RTP audio format 8 [Mar 19 09:34:54] Peer audio RTP is at port 10.4.127.230:5004 [Mar 19 09:34:54] Found description format PCMU for ID 0 [Mar 19 09:34:54] Found description format PCMA for ID 8 [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:5129 process_sdp: T38 state changed to 0 on channel SIP/4321-08a1e1e8 [Mar 19 09:34:54] Capabilities: us - 0xc (ulaw|alaw), peer - audio=0xc (ulaw|alaw)/video=0x0 (nothing), combined - 0xc (ulaw|alaw) [Mar 19 09:34:54] Non-codec capabilities (dtmf): us - 0x0 (nothing), peer - 0x0 (nothing), combined - 0x0 (nothing) [Mar 19 09:34:54] Peer audio RTP is at port 10.4.127.230:5004 [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:5209 process_sdp: We're settling with these formats: 0xc (ulaw|alaw) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:5216 process_sdp: We have an owner, now see if we need to change this call [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:3003 update_call_counter: Updating call counter for outgoing call [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:7980 build_route: build_route: Contact hop: Test2 [Mar 19 09:34:54] list_route: hop: [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:5643 reqprep: Strict routing enforced for session 4639e6c371fc2daa253ab6f923e3ed63@10.4.119.245 [Mar 19 09:34:54] set_destination: Parsing for address/port to send to [Mar 19 09:34:54] set_destination: set destination to 10.4.127.230, port 5060 [Mar 19 09:34:54] Transmitting (no NAT) to 10.4.127.230:5060: ACK sip:4321@10.4.127.230 SIP/2.0 Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK6a2a649b From: "Test1" ;tag=as048f2ce7 To: ;tag=fb81406bf2af5d8 Contact: Call-ID: 4639e6c371fc2daa253ab6f923e3ed63@10.4.119.245 CSeq: 102 ACK User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- [Mar 19 09:34:54] -- Call on SIP/4321-08a1e1e8 left from hold [Mar 19 09:34:54] DEBUG[30656]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/4321-08a1e1e8 [Mar 19 09:34:54] -- SIP/4321-08a1e1e8 answered SIP/1234-08a1a280 [Mar 19 09:34:54] DEBUG[30628]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 4321 [Mar 19 09:34:54] DEBUG[30628]: chan_sip.c:15240 sip_devicestate: Checking device state for peer 4321 [Mar 19 09:34:54] DEBUG[30628]: devicestate.c:287 do_state_change: Changing state for SIP/4321 - state 1 (Not in use) [Mar 19 09:34:54] DEBUG[30656]: rtp.c:1527 ast_rtp_early_bridge: Setting early bridge SDP of 'SIP/1234-08a1a280' with that of 'SIP/4321-08a1e1e8' [Mar 19 09:34:54] DEBUG[30656]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/1234-08a1a280 [Mar 19 09:34:54] DEBUG[30656]: chan_sip.c:3463 sip_answer: SIP answering channel: SIP/1234-08a1a280 [Mar 19 09:34:54] DEBUG[30656]: chan_sip.c:6420 transmit_response_with_sdp: Setting framing from config on incoming call [Mar 19 09:34:54] DEBUG[30656]: chan_sip.c:6188 add_sdp: ** Our capability: 0xc (ulaw|alaw) Video flag: True [Mar 19 09:34:54] DEBUG[30656]: chan_sip.c:6189 add_sdp: ** Our prefcodec: 0x0 (nothing) [Mar 19 09:34:54] Audio is at 10.4.119.245 port 18712 [Mar 19 09:34:54] Adding codec 0x4 (ulaw) to SDP [Mar 19 09:34:54] Adding codec 0x8 (alaw) to SDP [Mar 19 09:34:54] DEBUG[30656]: chan_sip.c:6320 add_sdp: -- Done with adding codecs to SDP [Mar 19 09:34:54] DEBUG[30656]: chan_sip.c:6365 add_sdp: Done building SDP. Settling with this capability: 0xc (ulaw|alaw) [Mar 19 09:34:54] <--- Reliably Transmitting (no NAT) to 10.4.126.232:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.4.126.232;branch=z9hG4bK6a4eabaab;received=10.4.126.232 From: Test1 ;tag=2e0ba312e07ed9f To: sip:4321@10.4.119.245;tag=as3287914c Call-ID: 437ca631f88d70553dbe5edc5ce7d949@10.4.119.245 CSeq: 1093933437 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 208 v=0 o=root 30622 30622 IN IP4 10.4.119.245 s=session c=IN IP4 10.4.119.245 t=0 0 m=audio 18712 RTP/AVP 0 8 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv <------------> [Mar 19 09:34:54] DEBUG[30656]: chan_sip.c:1975 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #30 [Mar 19 09:34:54] -- Native bridging SIP/1234-08a1a280 and SIP/4321-08a1e1e8 [Mar 19 09:34:54] DEBUG[30628]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 1234 [Mar 19 09:34:54] DEBUG[30628]: chan_sip.c:15240 sip_devicestate: Checking device state for peer 1234 [Mar 19 09:34:54] DEBUG[30628]: devicestate.c:287 do_state_change: Changing state for SIP/1234 - state 1 (Not in use) [Mar 19 09:34:54] DEBUG[30656]: chan_sip.c:16908 sip_set_rtp_peer: Deferring reinvite on SIP '437ca631f88d70553dbe5edc5ce7d949@10.4.119.245' - It's audio will be redirected to IP 10.4.127.230 [Mar 19 09:34:54] DEBUG[30656]: chan_sip.c:16903 sip_set_rtp_peer: Sending reinvite on SIP '4639e6c371fc2daa253ab6f923e3ed63@10.4.119.245' - It's audio soon redirected to IP 10.4.126.232 [Mar 19 09:34:54] DEBUG[30656]: chan_sip.c:5643 reqprep: Strict routing enforced for session 4639e6c371fc2daa253ab6f923e3ed63@10.4.119.245 [Mar 19 09:34:54] set_destination: Parsing for address/port to send to [Mar 19 09:34:54] set_destination: set destination to 10.4.127.230, port 5060 [Mar 19 09:34:54] DEBUG[30656]: chan_sip.c:6188 add_sdp: ** Our capability: 0xc (ulaw|alaw) Video flag: True [Mar 19 09:34:54] DEBUG[30656]: chan_sip.c:6189 add_sdp: ** Our prefcodec: 0x4 (ulaw) [Mar 19 09:34:54] Audio is at 10.4.119.245 port 13288 [Mar 19 09:34:54] Adding codec 0x4 (ulaw) to SDP [Mar 19 09:34:54] Adding codec 0x8 (alaw) to SDP [Mar 19 09:34:54] DEBUG[30656]: chan_sip.c:6320 add_sdp: -- Done with adding codecs to SDP [Mar 19 09:34:54] DEBUG[30656]: chan_sip.c:6365 add_sdp: Done building SDP. Settling with this capability: 0xc (ulaw|alaw) [Mar 19 09:34:54] DEBUG[30656]: chan_sip.c:1621 initialize_initreq: Initializing already initialized SIP dialog 4639e6c371fc2daa253ab6f923e3ed63@10.4.119.245 (presumably reinvite) [Mar 19 09:34:54] DEBUG[30656]: chan_sip.c:4573 parse_request: Header 0: INVITE sip:4321@10.4.127.230 SIP/2.0 (36) [Mar 19 09:34:54] DEBUG[30656]: chan_sip.c:4573 parse_request: Header 1: Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK692c5a81 (57) [Mar 19 09:34:54] DEBUG[30656]: chan_sip.c:4573 parse_request: Header 2: From: "Test1" ;tag=as048f2ce7 (52) [Mar 19 09:34:54] DEBUG[30656]: chan_sip.c:4573 parse_request: Header 3: To: ;tag=fb81406bf2af5d8 (47) [Mar 19 09:34:54] DEBUG[30656]: chan_sip.c:4573 parse_request: Header 4: Contact: (32) [Mar 19 09:34:54] DEBUG[30656]: chan_sip.c:4573 parse_request: Header 5: Call-ID: 4639e6c371fc2daa253ab6f923e3ed63@10.4.119.245 (54) [Mar 19 09:34:54] DEBUG[30656]: chan_sip.c:4573 parse_request: Header 6: CSeq: 103 INVITE (16) [Mar 19 09:34:54] DEBUG[30656]: chan_sip.c:4573 parse_request: Header 7: User-Agent: Asterisk PBX (24) [Mar 19 09:34:54] DEBUG[30656]: chan_sip.c:4573 parse_request: Header 8: Max-Forwards: 70 (16) [Mar 19 09:34:54] DEBUG[30656]: chan_sip.c:4573 parse_request: Header 9: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Mar 19 09:34:54] DEBUG[30656]: chan_sip.c:4573 parse_request: Header 10: Supported: replaces (19) [Mar 19 09:34:54] DEBUG[30656]: chan_sip.c:4573 parse_request: Header 11: X-asterisk-Info: SIP re-invite (External RTP bridge) (52) [Mar 19 09:34:54] DEBUG[30656]: chan_sip.c:4573 parse_request: Header 12: Content-Type: application/sdp (29) [Mar 19 09:34:54] DEBUG[30656]: chan_sip.c:4573 parse_request: Header 13: Content-Length: 207 (19) [Mar 19 09:34:54] DEBUG[30656]: chan_sip.c:4573 parse_request: Header 14: (0) [Mar 19 09:34:54] DEBUG[30656]: chan_sip.c:4605 parse_request: Line: v=0 (3) [Mar 19 09:34:54] DEBUG[30656]: chan_sip.c:4605 parse_request: Line: o=root 30622 30623 IN IP4 10.4.126.232 (38) [Mar 19 09:34:54] DEBUG[30656]: chan_sip.c:4605 parse_request: Line: s=session (9) [Mar 19 09:34:54] DEBUG[30656]: chan_sip.c:4605 parse_request: Line: c=IN IP4 10.4.126.232 (21) [Mar 19 09:34:54] DEBUG[30656]: chan_sip.c:4605 parse_request: Line: t=0 0 (5) [Mar 19 09:34:54] DEBUG[30656]: chan_sip.c:4605 parse_request: Line: m=audio 5004 RTP/AVP 0 8 (24) [Mar 19 09:34:54] DEBUG[30656]: chan_sip.c:4605 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Mar 19 09:34:54] DEBUG[30656]: chan_sip.c:4605 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Mar 19 09:34:54] DEBUG[30656]: chan_sip.c:4605 parse_request: Line: a=silenceSupp:off - - - - (25) [Mar 19 09:34:54] DEBUG[30656]: chan_sip.c:4605 parse_request: Line: a=ptime:20 (10) [Mar 19 09:34:54] DEBUG[30656]: chan_sip.c:4605 parse_request: Line: a=sendrecv (10) [Mar 19 09:34:54] Reliably Transmitting (no NAT) to 10.4.127.230:5060: INVITE sip:4321@10.4.127.230 SIP/2.0 Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK692c5a81 From: "Test1" ;tag=as048f2ce7 To: ;tag=fb81406bf2af5d8 Contact: Call-ID: 4639e6c371fc2daa253ab6f923e3ed63@10.4.119.245 CSeq: 103 INVITE User-Agent: Asterisk PBX Max-Forwards: 70 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces X-asterisk-Info: SIP re-invite (External RTP bridge) Content-Type: application/sdp Content-Length: 207 v=0 o=root 30622 30623 IN IP4 10.4.126.232 s=session c=IN IP4 10.4.126.232 t=0 0 m=audio 5004 RTP/AVP 0 8 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv --- [Mar 19 09:34:54] DEBUG[30656]: chan_sip.c:1975 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #31 [Mar 19 09:34:54] DEBUG[30659]: app_queue.c:546 changethread: Device 'SIP/4321' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Mar 19 09:34:54] DEBUG[30660]: app_queue.c:546 changethread: Device 'SIP/1234' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Mar 19 09:34:54] <--- SIP read from 10.4.126.232:5060 ---> ACK sip:4321@10.4.119.245 SIP/2.0 Via: SIP/2.0/UDP 10.4.126.232;branch=z9hG4bKaf5cc17c4 Content-Length: 0 To: sip:4321@10.4.119.245;tag=as3287914c From: Test1 ;tag=2e0ba312e07ed9f Call-ID: 437ca631f88d70553dbe5edc5ce7d949@10.4.119.245 CSeq: 1093933437 ACK Contact: Test1 User-Agent: MxSipApp/5.0.16.99 MxSF/v3.2.1.1 <-------------> [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 0: ACK sip:4321@10.4.119.245 SIP/2.0 (33) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 1: Via: SIP/2.0/UDP 10.4.126.232;branch=z9hG4bKaf5cc17c4 (53) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 2: Content-Length: 0 (17) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 3: To: sip:4321@10.4.119.245;tag=as3287914c (40) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 4: From: Test1 ;tag=2e0ba312e07ed9f (55) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 5: Call-ID: 437ca631f88d70553dbe5edc5ce7d949@10.4.119.245 (54) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 6: CSeq: 1093933437 ACK (20) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 7: Contact: Test1 (38) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 8: User-Agent: MxSipApp/5.0.16.99 MxSF/v3.2.1.1 (44) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 9: (0) [Mar 19 09:34:54] --- (9 headers 0 lines) --- [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:14629 handle_request: **** Received ACK (6) - Command in SIP ACK [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:2079 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #30 [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '437ca631f88d70553dbe5edc5ce7d949@10.4.119.245' of Response 1093933437: Match Not Found [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:11622 check_pendings: Sending pending reinvite on '437ca631f88d70553dbe5edc5ce7d949@10.4.119.245' [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:5643 reqprep: Strict routing enforced for session 437ca631f88d70553dbe5edc5ce7d949@10.4.119.245 [Mar 19 09:34:54] set_destination: Parsing for address/port to send to [Mar 19 09:34:54] set_destination: set destination to 10.4.126.232, port 5060 [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:6188 add_sdp: ** Our capability: 0xc (ulaw|alaw) Video flag: True [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:6189 add_sdp: ** Our prefcodec: 0x0 (nothing) [Mar 19 09:34:54] Audio is at 10.4.119.245 port 18712 [Mar 19 09:34:54] Adding codec 0x4 (ulaw) to SDP [Mar 19 09:34:54] Adding codec 0x8 (alaw) to SDP [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:6320 add_sdp: -- Done with adding codecs to SDP [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:6365 add_sdp: Done building SDP. Settling with this capability: 0xc (ulaw|alaw) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:1621 initialize_initreq: Initializing already initialized SIP dialog 437ca631f88d70553dbe5edc5ce7d949@10.4.119.245 (presumably reinvite) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 0: INVITE sip:1234@10.4.126.232 SIP/2.0 (36) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 1: Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK151d3e42 (57) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 2: From: sip:4321@10.4.119.245;tag=as3287914c (42) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 3: To: Test1 ;tag=2e0ba312e07ed9f (53) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 4: Contact: (32) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 5: Call-ID: 437ca631f88d70553dbe5edc5ce7d949@10.4.119.245 (54) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 6: CSeq: 102 INVITE (16) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 7: User-Agent: Asterisk PBX (24) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 8: Max-Forwards: 70 (16) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 9: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 10: Supported: replaces (19) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 11: X-asterisk-Info: SIP re-invite (External RTP bridge) (52) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 12: Content-Type: application/sdp (29) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 13: Content-Length: 207 (19) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 14: (0) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4605 parse_request: Line: v=0 (3) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4605 parse_request: Line: o=root 30622 30623 IN IP4 10.4.127.230 (38) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4605 parse_request: Line: s=session (9) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4605 parse_request: Line: c=IN IP4 10.4.127.230 (21) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4605 parse_request: Line: t=0 0 (5) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4605 parse_request: Line: m=audio 5004 RTP/AVP 0 8 (24) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4605 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4605 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4605 parse_request: Line: a=silenceSupp:off - - - - (25) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4605 parse_request: Line: a=ptime:20 (10) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4605 parse_request: Line: a=sendrecv (10) [Mar 19 09:34:54] Reliably Transmitting (no NAT) to 10.4.126.232:5060: INVITE sip:1234@10.4.126.232 SIP/2.0 Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK151d3e42 From: sip:4321@10.4.119.245;tag=as3287914c To: Test1 ;tag=2e0ba312e07ed9f Contact: Call-ID: 437ca631f88d70553dbe5edc5ce7d949@10.4.119.245 CSeq: 102 INVITE User-Agent: Asterisk PBX Max-Forwards: 70 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces X-asterisk-Info: SIP re-invite (External RTP bridge) Content-Type: application/sdp Content-Length: 207 v=0 o=root 30622 30623 IN IP4 10.4.127.230 s=session c=IN IP4 10.4.127.230 t=0 0 m=audio 5004 RTP/AVP 0 8 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv --- [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:1975 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #32 [Mar 19 09:34:54] <--- SIP read from 10.4.127.230:5060 ---> SIP/2.0 100 Trying Call-ID: 4639e6c371fc2daa253ab6f923e3ed63@10.4.119.245 CSeq: 103 INVITE From: "Test1" ;tag=as048f2ce7 To: ;tag=fb81406bf2af5d8 Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK692c5a81 Content-Length: 0 User-Agent: MxSipApp/5.0.15.88 MxSF/v3.2.1.1 <-------------> [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 0: SIP/2.0 100 Trying (18) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 1: Call-ID: 4639e6c371fc2daa253ab6f923e3ed63@10.4.119.245 (54) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 2: CSeq: 103 INVITE (16) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 3: From: "Test1" ;tag=as048f2ce7 (52) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 4: To: ;tag=fb81406bf2af5d8 (47) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 5: Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK692c5a81 (57) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 6: Content-Length: 0 (17) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 7: User-Agent: MxSipApp/5.0.15.88 MxSF/v3.2.1.1 (44) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 8: (0) [Mar 19 09:34:54] --- (8 headers 0 lines) --- [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:2122 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #31 - INVITE (got response) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:2131 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '4639e6c371fc2daa253ab6f923e3ed63@10.4.119.245' Request 103: Found [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:11639 handle_response_invite: SIP response 100 to RE-invite on outgoing call 4639e6c371fc2daa253ab6f923e3ed63@10.4.119.245 [Mar 19 09:34:54] <--- SIP read from 10.4.127.230:5060 ---> SIP/2.0 200 OK Call-ID: 4639e6c371fc2daa253ab6f923e3ed63@10.4.119.245 CSeq: 103 INVITE From: "Test1" ;tag=as048f2ce7 To: ;tag=fb81406bf2af5d8 Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK692c5a81 Content-Length: 190 Session-Expires: 3600;refresher=uas Allow: INVITE, ACK, BYE, CANCEL, REFER, NOTIFY Content-Type: application/sdp Supported: replaces Contact: Test2 User-Agent: MxSipApp/5.0.15.88 MxSF/v3.2.1.1 v=0 o=MxSIP 599798619795376287 2005741632565392604 IN IP4 10.4.127.230 s=- c=IN IP4 10.4.127.230 t=0 0 a=sendrecv m=audio 5004 RTP/AVP 0 8 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 <-------------> [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 0: SIP/2.0 200 OK (14) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 1: Call-ID: 4639e6c371fc2daa253ab6f923e3ed63@10.4.119.245 (54) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 2: CSeq: 103 INVITE (16) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 3: From: "Test1" ;tag=as048f2ce7 (52) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 4: To: ;tag=fb81406bf2af5d8 (47) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 5: Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK692c5a81 (57) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 6: Content-Length: 190 (19) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 7: Session-Expires: 3600;refresher=uas (35) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 8: Allow: INVITE, ACK, BYE, CANCEL, REFER, NOTIFY (46) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 9: Content-Type: application/sdp (29) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 10: Supported: replaces (19) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 11: Contact: Test2 (38) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 12: User-Agent: MxSipApp/5.0.15.88 MxSF/v3.2.1.1 (44) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 13: (0) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4605 parse_request: Line: v=0 (3) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4605 parse_request: Line: o=MxSIP 599798619795376287 2005741632565392604 IN IP4 10.4.127.230 (66) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4605 parse_request: Line: s=- (3) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4605 parse_request: Line: c=IN IP4 10.4.127.230 (21) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4605 parse_request: Line: t=0 0 (5) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4605 parse_request: Line: a=sendrecv (10) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4605 parse_request: Line: m=audio 5004 RTP/AVP 0 8 (24) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4605 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4605 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Mar 19 09:34:54] --- (13 headers 9 lines) --- [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:2071 __sip_ack: Acked pending invite 103 [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '4639e6c371fc2daa253ab6f923e3ed63@10.4.119.245' of Request 103: Match Not Found [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:11639 handle_response_invite: SIP response 200 to RE-invite on outgoing call 4639e6c371fc2daa253ab6f923e3ed63@10.4.119.245 [Mar 19 09:34:54] Found RTP audio format 0 [Mar 19 09:34:54] Found RTP audio format 8 [Mar 19 09:34:54] Peer audio RTP is at port 10.4.127.230:5004 [Mar 19 09:34:54] Found description format PCMU for ID 0 [Mar 19 09:34:54] Found description format PCMA for ID 8 [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:5129 process_sdp: T38 state changed to 0 on channel SIP/4321-08a1e1e8 [Mar 19 09:34:54] Capabilities: us - 0xc (ulaw|alaw), peer - audio=0xc (ulaw|alaw)/video=0x0 (nothing), combined - 0xc (ulaw|alaw) [Mar 19 09:34:54] Non-codec capabilities (dtmf): us - 0x0 (nothing), peer - 0x0 (nothing), combined - 0x0 (nothing) [Mar 19 09:34:54] Peer audio RTP is at port 10.4.127.230:5004 [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:5209 process_sdp: We're settling with these formats: 0xc (ulaw|alaw) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:5216 process_sdp: We have an owner, now see if we need to change this call [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:3003 update_call_counter: Updating call counter for outgoing call [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:7919 build_route: build_route: Retaining previous route: [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:11772 handle_response_invite: Strange... The other side of the bridge does not have a udptl struct [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:11777 handle_response_invite: T38 state changed to 0 on channel SIP [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:11780 handle_response_invite: T38 state changed to 0 on channel SIP/4321-08a1e1e8 [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:5643 reqprep: Strict routing enforced for session 4639e6c371fc2daa253ab6f923e3ed63@10.4.119.245 [Mar 19 09:34:54] set_destination: Parsing for address/port to send to [Mar 19 09:34:54] set_destination: set destination to 10.4.127.230, port 5060 [Mar 19 09:34:54] Transmitting (no NAT) to 10.4.127.230:5060: ACK sip:4321@10.4.127.230 SIP/2.0 Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK72a616d2 From: "Test1" ;tag=as048f2ce7 To: ;tag=fb81406bf2af5d8 Contact: Call-ID: 4639e6c371fc2daa253ab6f923e3ed63@10.4.119.245 CSeq: 103 ACK User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- [Mar 19 09:34:54] <--- SIP read from 10.4.126.232:5060 ---> SIP/2.0 100 Trying Call-ID: 437ca631f88d70553dbe5edc5ce7d949@10.4.119.245 CSeq: 102 INVITE From: sip:4321@10.4.119.245;tag=as3287914c To: Test1 ;tag=2e0ba312e07ed9f Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK151d3e42 Content-Length: 0 User-Agent: MxSipApp/5.0.16.99 MxSF/v3.2.1.1 <-------------> [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 0: SIP/2.0 100 Trying (18) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 1: Call-ID: 437ca631f88d70553dbe5edc5ce7d949@10.4.119.245 (54) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 2: CSeq: 102 INVITE (16) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 3: From: sip:4321@10.4.119.245;tag=as3287914c (42) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 4: To: Test1 ;tag=2e0ba312e07ed9f (53) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 5: Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK151d3e42 (57) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 6: Content-Length: 0 (17) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 7: User-Agent: MxSipApp/5.0.16.99 MxSF/v3.2.1.1 (44) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 8: (0) [Mar 19 09:34:54] --- (8 headers 0 lines) --- [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:2122 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #32 - INVITE (got response) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:2131 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '437ca631f88d70553dbe5edc5ce7d949@10.4.119.245' Request 102: Found [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:11639 handle_response_invite: SIP response 100 to RE-invite on outgoing call 437ca631f88d70553dbe5edc5ce7d949@10.4.119.245 [Mar 19 09:34:54] <--- SIP read from 10.4.126.232:5060 ---> SIP/2.0 200 OK Call-ID: 437ca631f88d70553dbe5edc5ce7d949@10.4.119.245 CSeq: 102 INVITE From: sip:4321@10.4.119.245;tag=as3287914c To: Test1 ;tag=2e0ba312e07ed9f Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK151d3e42 Content-Length: 189 Session-Expires: 3600;refresher=uas Allow: INVITE, ACK, BYE, CANCEL, REFER, NOTIFY Content-Type: application/sdp Supported: replaces Contact: Test1 User-Agent: MxSipApp/5.0.16.99 MxSF/v3.2.1.1 v=0 o=MxSIP 352673312983635746 376570794169103870 IN IP4 10.4.126.232 s=- c=IN IP4 10.4.126.232 t=0 0 a=sendrecv m=audio 5004 RTP/AVP 0 8 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 <-------------> [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 0: SIP/2.0 200 OK (14) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 1: Call-ID: 437ca631f88d70553dbe5edc5ce7d949@10.4.119.245 (54) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 2: CSeq: 102 INVITE (16) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 3: From: sip:4321@10.4.119.245;tag=as3287914c (42) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 4: To: Test1 ;tag=2e0ba312e07ed9f (53) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 5: Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK151d3e42 (57) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 6: Content-Length: 189 (19) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 7: Session-Expires: 3600;refresher=uas (35) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 8: Allow: INVITE, ACK, BYE, CANCEL, REFER, NOTIFY (46) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 9: Content-Type: application/sdp (29) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 10: Supported: replaces (19) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 11: Contact: Test1 (38) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 12: User-Agent: MxSipApp/5.0.16.99 MxSF/v3.2.1.1 (44) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 13: (0) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4605 parse_request: Line: v=0 (3) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4605 parse_request: Line: o=MxSIP 352673312983635746 376570794169103870 IN IP4 10.4.126.232 (65) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4605 parse_request: Line: s=- (3) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4605 parse_request: Line: c=IN IP4 10.4.126.232 (21) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4605 parse_request: Line: t=0 0 (5) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4605 parse_request: Line: a=sendrecv (10) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4605 parse_request: Line: m=audio 5004 RTP/AVP 0 8 (24) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4605 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:4605 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Mar 19 09:34:54] --- (13 headers 9 lines) --- [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:2071 __sip_ack: Acked pending invite 102 [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '437ca631f88d70553dbe5edc5ce7d949@10.4.119.245' of Request 102: Match Not Found [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:11639 handle_response_invite: SIP response 200 to RE-invite on outgoing call 437ca631f88d70553dbe5edc5ce7d949@10.4.119.245 [Mar 19 09:34:54] Found RTP audio format 0 [Mar 19 09:34:54] Found RTP audio format 8 [Mar 19 09:34:54] Peer audio RTP is at port 10.4.126.232:5004 [Mar 19 09:34:54] Found description format PCMU for ID 0 [Mar 19 09:34:54] Found description format PCMA for ID 8 [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:5129 process_sdp: T38 state changed to 0 on channel SIP/1234-08a1a280 [Mar 19 09:34:54] Capabilities: us - 0xc (ulaw|alaw), peer - audio=0xc (ulaw|alaw)/video=0x0 (nothing), combined - 0xc (ulaw|alaw) [Mar 19 09:34:54] Non-codec capabilities (dtmf): us - 0x0 (nothing), peer - 0x0 (nothing), combined - 0x0 (nothing) [Mar 19 09:34:54] Peer audio RTP is at port 10.4.126.232:5004 [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:5209 process_sdp: We're settling with these formats: 0xc (ulaw|alaw) [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:5216 process_sdp: We have an owner, now see if we need to change this call [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:3003 update_call_counter: Updating call counter for incoming call [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:7980 build_route: build_route: Contact hop: Test1 [Mar 19 09:34:54] list_route: hop: [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:11772 handle_response_invite: Strange... The other side of the bridge does not have a udptl struct [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:11777 handle_response_invite: T38 state changed to 0 on channel SIP [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:11780 handle_response_invite: T38 state changed to 0 on channel SIP/1234-08a1a280 [Mar 19 09:34:54] DEBUG[30638]: chan_sip.c:5643 reqprep: Strict routing enforced for session 437ca631f88d70553dbe5edc5ce7d949@10.4.119.245 [Mar 19 09:34:54] set_destination: Parsing for address/port to send to [Mar 19 09:34:54] set_destination: set destination to 10.4.126.232, port 5060 [Mar 19 09:34:54] Transmitting (no NAT) to 10.4.126.232:5060: ACK sip:1234@10.4.126.232 SIP/2.0 Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK0a71d525 From: sip:4321@10.4.119.245;tag=as3287914c To: Test1 ;tag=2e0ba312e07ed9f Contact: Call-ID: 437ca631f88d70553dbe5edc5ce7d949@10.4.119.245 CSeq: 102 ACK User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- [Mar 19 09:34:57] <--- SIP read from 10.4.127.230:5060 ---> INVITE sip:1234@10.4.119.245 SIP/2.0 Via: SIP/2.0/UDP 10.4.127.230;branch=z9hG4bKd2620d178 Content-Length: 238 To: "Test1" ;tag=as048f2ce7 From: ;tag=fb81406bf2af5d8 Call-ID: 4639e6c371fc2daa253ab6f923e3ed63@10.4.119.245 CSeq: 765443450 INVITE Supported: timer Min-SE: 1800 Session-Expires: 3600 Allow: INVITE, ACK, BYE, CANCEL, REFER, NOTIFY Content-Type: application/sdp Contact: Test2 Supported: replaces User-Agent: MxSipApp/5.0.15.88 MxSF/v3.2.1.1 v=0 o=MxSIP 599798619795376287 2005741632565392605 IN IP4 10.4.127.230 s=- c=IN IP4 0.0.0.0 t=0 0 a=inactive m=audio 5004 RTP/AVP 0 18 4 8 13 a=rtpmap:0 PCMU/8000 a=rtpmap:18 G729/8000 a=rtpmap:4 G723/8000 a=rtpmap:8 PCMA/8000 <-------------> [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 0: INVITE sip:1234@10.4.119.245 SIP/2.0 (36) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 1: Via: SIP/2.0/UDP 10.4.127.230;branch=z9hG4bKd2620d178 (53) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 2: Content-Length: 238 (19) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 3: To: "Test1" ;tag=as048f2ce7 (50) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 4: From: ;tag=fb81406bf2af5d8 (49) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 5: Call-ID: 4639e6c371fc2daa253ab6f923e3ed63@10.4.119.245 (54) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 6: CSeq: 765443450 INVITE (22) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 7: Supported: timer (16) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 8: Min-SE: 1800 (12) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 9: Session-Expires: 3600 (21) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 10: Allow: INVITE, ACK, BYE, CANCEL, REFER, NOTIFY (46) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 11: Content-Type: application/sdp (29) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 12: Contact: Test2 (38) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 13: Supported: replaces (19) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 14: User-Agent: MxSipApp/5.0.15.88 MxSF/v3.2.1.1 (44) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 15: (0) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4605 parse_request: Line: v=0 (3) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4605 parse_request: Line: o=MxSIP 599798619795376287 2005741632565392605 IN IP4 10.4.127.230 (66) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4605 parse_request: Line: s=- (3) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4605 parse_request: Line: c=IN IP4 0.0.0.0 (16) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4605 parse_request: Line: t=0 0 (5) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4605 parse_request: Line: a=inactive (10) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4605 parse_request: Line: m=audio 5004 RTP/AVP 0 18 4 8 13 (32) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4605 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4605 parse_request: Line: a=rtpmap:18 G729/8000 (21) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4605 parse_request: Line: a=rtpmap:4 G723/8000 (20) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4605 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Mar 19 09:34:57] --- (15 headers 11 lines) --- [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:14629 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:1680 parse_sip_options: Begin: parsing SIP "Supported: timer" [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:1688 parse_sip_options: Found SIP option: -timer- [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:1694 parse_sip_options: Matched SIP option: timer [Mar 19 09:34:57] Sending to 10.4.127.230 : 5060 (no NAT) [Mar 19 09:34:57] Found RTP audio format 0 [Mar 19 09:34:57] Found RTP audio format 18 [Mar 19 09:34:57] Found RTP audio format 4 [Mar 19 09:34:57] Found RTP audio format 8 [Mar 19 09:34:57] Found RTP audio format 13 [Mar 19 09:34:57] Peer audio RTP is at port 0.0.0.0:5004 [Mar 19 09:34:57] Found description format PCMU for ID 0 [Mar 19 09:34:57] Found description format G729 for ID 18 [Mar 19 09:34:57] Found description format G723 for ID 4 [Mar 19 09:34:57] Found description format PCMA for ID 8 [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:5129 process_sdp: T38 state changed to 0 on channel SIP/4321-08a1e1e8 [Mar 19 09:34:57] Capabilities: us - 0xc (ulaw|alaw), peer - audio=0x10d (g723|ulaw|alaw|g729)/video=0x0 (nothing), combined - 0xc (ulaw|alaw) [Mar 19 09:34:57] Non-codec capabilities (dtmf): us - 0x0 (nothing), peer - 0x2 (CN), combined - 0x0 (nothing) [Mar 19 09:34:57] Peer audio RTP is at port 0.0.0.0:5004 [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:5209 process_sdp: We're settling with these formats: 0xc (ulaw|alaw) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:5216 process_sdp: We have an owner, now see if we need to change this call [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:13454 handle_request_invite: Got a SIP re-invite for call 4639e6c371fc2daa253ab6f923e3ed63@10.4.119.245 [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:13549 handle_request_invite: SIP/4321-08a1e1e8: This call is UP.... [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:6420 transmit_response_with_sdp: Setting framing from config on incoming call [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:6188 add_sdp: ** Our capability: 0xc (ulaw|alaw) Video flag: True [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:6189 add_sdp: ** Our prefcodec: 0x4 (ulaw) [Mar 19 09:34:57] Audio is at 10.4.119.245 port 13288 [Mar 19 09:34:57] Adding codec 0x4 (ulaw) to SDP [Mar 19 09:34:57] Adding codec 0x8 (alaw) to SDP [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:6320 add_sdp: -- Done with adding codecs to SDP [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:6365 add_sdp: Done building SDP. Settling with this capability: 0xc (ulaw|alaw) [Mar 19 09:34:57] <--- Reliably Transmitting (no NAT) to 10.4.127.230:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.4.127.230;branch=z9hG4bKd2620d178;received=10.4.127.230 From: ;tag=fb81406bf2af5d8 To: "Test1" ;tag=as048f2ce7 Call-ID: 4639e6c371fc2daa253ab6f923e3ed63@10.4.119.245 CSeq: 765443450 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 207 v=0 o=root 30622 30624 IN IP4 10.4.126.232 s=session c=IN IP4 10.4.126.232 t=0 0 m=audio 5004 RTP/AVP 0 8 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=silenceSupp:off - - - - a=ptime:20 a=inactive <------------> [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:1975 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #33 [Mar 19 09:34:57] DEBUG[30656]: chan_sip.c:16903 sip_set_rtp_peer: Sending reinvite on SIP '437ca631f88d70553dbe5edc5ce7d949@10.4.119.245' - It's audio soon redirected to IP 10.4.119.245 [Mar 19 09:34:57] DEBUG[30656]: chan_sip.c:5643 reqprep: Strict routing enforced for session 437ca631f88d70553dbe5edc5ce7d949@10.4.119.245 [Mar 19 09:34:57] set_destination: Parsing for address/port to send to [Mar 19 09:34:57] set_destination: set destination to 10.4.126.232, port 5060 [Mar 19 09:34:57] DEBUG[30656]: chan_sip.c:6188 add_sdp: ** Our capability: 0xc (ulaw|alaw) Video flag: True [Mar 19 09:34:57] DEBUG[30656]: chan_sip.c:6189 add_sdp: ** Our prefcodec: 0x0 (nothing) [Mar 19 09:34:57] Audio is at 10.4.119.245 port 18712 [Mar 19 09:34:57] Adding codec 0x4 (ulaw) to SDP [Mar 19 09:34:57] Adding codec 0x8 (alaw) to SDP [Mar 19 09:34:57] DEBUG[30656]: chan_sip.c:6320 add_sdp: -- Done with adding codecs to SDP [Mar 19 09:34:57] DEBUG[30656]: chan_sip.c:6365 add_sdp: Done building SDP. Settling with this capability: 0xc (ulaw|alaw) [Mar 19 09:34:57] DEBUG[30656]: chan_sip.c:1621 initialize_initreq: Initializing already initialized SIP dialog 437ca631f88d70553dbe5edc5ce7d949@10.4.119.245 (presumably reinvite) [Mar 19 09:34:57] DEBUG[30656]: chan_sip.c:4573 parse_request: Header 0: INVITE sip:1234@10.4.126.232 SIP/2.0 (36) [Mar 19 09:34:57] DEBUG[30656]: chan_sip.c:4573 parse_request: Header 1: Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK7b844fee (57) [Mar 19 09:34:57] DEBUG[30656]: chan_sip.c:4573 parse_request: Header 2: From: sip:4321@10.4.119.245;tag=as3287914c (42) [Mar 19 09:34:57] DEBUG[30656]: chan_sip.c:4573 parse_request: Header 3: To: Test1 ;tag=2e0ba312e07ed9f (53) [Mar 19 09:34:57] DEBUG[30656]: chan_sip.c:4573 parse_request: Header 4: Contact: (32) [Mar 19 09:34:57] DEBUG[30656]: chan_sip.c:4573 parse_request: Header 5: Call-ID: 437ca631f88d70553dbe5edc5ce7d949@10.4.119.245 (54) [Mar 19 09:34:57] DEBUG[30656]: chan_sip.c:4573 parse_request: Header 6: CSeq: 103 INVITE (16) [Mar 19 09:34:57] DEBUG[30656]: chan_sip.c:4573 parse_request: Header 7: User-Agent: Asterisk PBX (24) [Mar 19 09:34:57] DEBUG[30656]: chan_sip.c:4573 parse_request: Header 8: Max-Forwards: 70 (16) [Mar 19 09:34:57] DEBUG[30656]: chan_sip.c:4573 parse_request: Header 9: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Mar 19 09:34:57] DEBUG[30656]: chan_sip.c:4573 parse_request: Header 10: Supported: replaces (19) [Mar 19 09:34:57] DEBUG[30656]: chan_sip.c:4573 parse_request: Header 11: X-asterisk-Info: SIP re-invite (External RTP bridge) (52) [Mar 19 09:34:57] DEBUG[30656]: chan_sip.c:4573 parse_request: Header 12: Content-Type: application/sdp (29) [Mar 19 09:34:57] DEBUG[30656]: chan_sip.c:4573 parse_request: Header 13: Content-Length: 208 (19) [Mar 19 09:34:57] DEBUG[30656]: chan_sip.c:4573 parse_request: Header 14: (0) [Mar 19 09:34:57] DEBUG[30656]: chan_sip.c:4605 parse_request: Line: v=0 (3) [Mar 19 09:34:57] DEBUG[30656]: chan_sip.c:4605 parse_request: Line: o=root 30622 30624 IN IP4 10.4.119.245 (38) [Mar 19 09:34:57] DEBUG[30656]: chan_sip.c:4605 parse_request: Line: s=session (9) [Mar 19 09:34:57] DEBUG[30656]: chan_sip.c:4605 parse_request: Line: c=IN IP4 10.4.119.245 (21) [Mar 19 09:34:57] DEBUG[30656]: chan_sip.c:4605 parse_request: Line: t=0 0 (5) [Mar 19 09:34:57] DEBUG[30656]: chan_sip.c:4605 parse_request: Line: m=audio 18712 RTP/AVP 0 8 (25) [Mar 19 09:34:57] DEBUG[30656]: chan_sip.c:4605 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Mar 19 09:34:57] DEBUG[30656]: chan_sip.c:4605 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Mar 19 09:34:57] DEBUG[30656]: chan_sip.c:4605 parse_request: Line: a=silenceSupp:off - - - - (25) [Mar 19 09:34:57] DEBUG[30656]: chan_sip.c:4605 parse_request: Line: a=ptime:20 (10) [Mar 19 09:34:57] DEBUG[30656]: chan_sip.c:4605 parse_request: Line: a=sendrecv (10) [Mar 19 09:34:57] Reliably Transmitting (no NAT) to 10.4.126.232:5060: INVITE sip:1234@10.4.126.232 SIP/2.0 Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK7b844fee From: sip:4321@10.4.119.245;tag=as3287914c To: Test1 ;tag=2e0ba312e07ed9f Contact: Call-ID: 437ca631f88d70553dbe5edc5ce7d949@10.4.119.245 CSeq: 103 INVITE User-Agent: Asterisk PBX Max-Forwards: 70 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces X-asterisk-Info: SIP re-invite (External RTP bridge) Content-Type: application/sdp Content-Length: 208 v=0 o=root 30622 30624 IN IP4 10.4.119.245 s=session c=IN IP4 10.4.119.245 t=0 0 m=audio 18712 RTP/AVP 0 8 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv --- [Mar 19 09:34:57] DEBUG[30656]: chan_sip.c:1975 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #34 [Mar 19 09:34:57] -- Started music on hold, class 'default', on SIP/1234-08a1a280 [Mar 19 09:34:57] DEBUG[30656]: channel.c:1997 ast_settimeout: Scheduling timer at 160 sample intervals [Mar 19 09:34:57] DEBUG[30656]: rtp.c:2825 bridge_native_loop: Oooh, 'SIP/4321-08a1e1e8' changed end address to 0.0.0.0:0 (format 269) [Mar 19 09:34:57] DEBUG[30656]: rtp.c:2827 bridge_native_loop: Oooh, 'SIP/4321-08a1e1e8' changed end vaddress to 0.0.0.0:0 (format 269) [Mar 19 09:34:57] DEBUG[30656]: rtp.c:2829 bridge_native_loop: Oooh, 'SIP/4321-08a1e1e8' was 10.4.127.230:5004/(format 12) [Mar 19 09:34:57] DEBUG[30656]: rtp.c:2831 bridge_native_loop: Oooh, 'SIP/4321-08a1e1e8' was 0.0.0.0:0/(format 12) [Mar 19 09:34:57] DEBUG[30656]: chan_sip.c:16908 sip_set_rtp_peer: Deferring reinvite on SIP '437ca631f88d70553dbe5edc5ce7d949@10.4.119.245' - It's audio will be redirected to IP 10.4.119.245 [Mar 19 09:34:57] DEBUG[30656]: channel.c:2845 set_format: Set channel SIP/1234-08a1a280 to write format slin [Mar 19 09:34:57] DEBUG[30656]: res_musiconhold.c:254 ast_moh_files_next: SIP/1234-08a1a280 Opened file 1 '/var/lib/asterisk/moh/fpm-world-mix' [Mar 19 09:34:57] DEBUG[30656]: rtp.c:2689 ast_rtp_write: Ooh, format changed from unknown to ulaw [Mar 19 09:34:57] DEBUG[30656]: rtp.c:2706 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160 [Mar 19 09:34:57] DEBUG[30656]: channel.c:2332 __ast_read: Generator got voice, switching to phase locked mode [Mar 19 09:34:57] DEBUG[30656]: channel.c:1997 ast_settimeout: Scheduling timer at 0 sample intervals [Mar 19 09:34:57] <--- SIP read from 10.4.127.230:5060 ---> ACK sip:1234@10.4.119.245 SIP/2.0 Via: SIP/2.0/UDP 10.4.127.230;branch=z9hG4bK002008830 Content-Length: 0 To: "Test1" ;tag=as048f2ce7 From: ;tag=fb81406bf2af5d8 Call-ID: 4639e6c371fc2daa253ab6f923e3ed63@10.4.119.245 CSeq: 765443450 ACK Contact: Test2 User-Agent: MxSipApp/5.0.15.88 MxSF/v3.2.1.1 <-------------> [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 0: ACK sip:1234@10.4.119.245 SIP/2.0 (33) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 1: Via: SIP/2.0/UDP 10.4.127.230;branch=z9hG4bK002008830 (53) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 2: Content-Length: 0 (17) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 3: To: "Test1" ;tag=as048f2ce7 (50) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 4: From: ;tag=fb81406bf2af5d8 (49) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 5: Call-ID: 4639e6c371fc2daa253ab6f923e3ed63@10.4.119.245 (54) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 6: CSeq: 765443450 ACK (19) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 7: Contact: Test2 (38) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 8: User-Agent: MxSipApp/5.0.15.88 MxSF/v3.2.1.1 (44) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 9: (0) [Mar 19 09:34:57] --- (9 headers 0 lines) --- [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:14629 handle_request: **** Received ACK (6) - Command in SIP ACK [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:2079 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #33 [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '4639e6c371fc2daa253ab6f923e3ed63@10.4.119.245' of Response 765443450: Match Not Found [Mar 19 09:34:57] <--- SIP read from 10.4.126.232:5060 ---> SIP/2.0 100 Trying Call-ID: 437ca631f88d70553dbe5edc5ce7d949@10.4.119.245 CSeq: 103 INVITE From: sip:4321@10.4.119.245;tag=as3287914c To: Test1 ;tag=2e0ba312e07ed9f Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK7b844fee Content-Length: 0 User-Agent: MxSipApp/5.0.16.99 MxSF/v3.2.1.1 <-------------> [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 0: SIP/2.0 100 Trying (18) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 1: Call-ID: 437ca631f88d70553dbe5edc5ce7d949@10.4.119.245 (54) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 2: CSeq: 103 INVITE (16) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 3: From: sip:4321@10.4.119.245;tag=as3287914c (42) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 4: To: Test1 ;tag=2e0ba312e07ed9f (53) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 5: Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK7b844fee (57) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 6: Content-Length: 0 (17) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 7: User-Agent: MxSipApp/5.0.16.99 MxSF/v3.2.1.1 (44) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 8: (0) [Mar 19 09:34:57] --- (8 headers 0 lines) --- [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:2122 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #34 - INVITE (got response) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:2131 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '437ca631f88d70553dbe5edc5ce7d949@10.4.119.245' Request 103: Found [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:11639 handle_response_invite: SIP response 100 to RE-invite on outgoing call 437ca631f88d70553dbe5edc5ce7d949@10.4.119.245 [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:11622 check_pendings: Sending pending reinvite on '437ca631f88d70553dbe5edc5ce7d949@10.4.119.245' [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:5643 reqprep: Strict routing enforced for session 437ca631f88d70553dbe5edc5ce7d949@10.4.119.245 [Mar 19 09:34:57] set_destination: Parsing for address/port to send to [Mar 19 09:34:57] set_destination: set destination to 10.4.126.232, port 5060 [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:6188 add_sdp: ** Our capability: 0xc (ulaw|alaw) Video flag: True [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:6189 add_sdp: ** Our prefcodec: 0x0 (nothing) [Mar 19 09:34:57] Audio is at 10.4.119.245 port 18712 [Mar 19 09:34:57] Adding codec 0x4 (ulaw) to SDP [Mar 19 09:34:57] Adding codec 0x8 (alaw) to SDP [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:6320 add_sdp: -- Done with adding codecs to SDP [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:6365 add_sdp: Done building SDP. Settling with this capability: 0xc (ulaw|alaw) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:1621 initialize_initreq: Initializing already initialized SIP dialog 437ca631f88d70553dbe5edc5ce7d949@10.4.119.245 (presumably reinvite) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 0: INVITE sip:1234@10.4.126.232 SIP/2.0 (36) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 1: Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK1e2cf1f4 (57) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 2: From: sip:4321@10.4.119.245;tag=as3287914c (42) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 3: To: Test1 ;tag=2e0ba312e07ed9f (53) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 4: Contact: (32) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 5: Call-ID: 437ca631f88d70553dbe5edc5ce7d949@10.4.119.245 (54) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 6: CSeq: 104 INVITE (16) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 7: User-Agent: Asterisk PBX (24) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 8: Max-Forwards: 70 (16) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 9: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 10: Supported: replaces (19) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 11: X-asterisk-Info: SIP re-invite (External RTP bridge) (52) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 12: Content-Type: application/sdp (29) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 13: Content-Length: 208 (19) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 14: (0) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4605 parse_request: Line: v=0 (3) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4605 parse_request: Line: o=root 30622 30625 IN IP4 10.4.119.245 (38) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4605 parse_request: Line: s=session (9) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4605 parse_request: Line: c=IN IP4 10.4.119.245 (21) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4605 parse_request: Line: t=0 0 (5) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4605 parse_request: Line: m=audio 18712 RTP/AVP 0 8 (25) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4605 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4605 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4605 parse_request: Line: a=silenceSupp:off - - - - (25) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4605 parse_request: Line: a=ptime:20 (10) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4605 parse_request: Line: a=sendrecv (10) [Mar 19 09:34:57] Reliably Transmitting (no NAT) to 10.4.126.232:5060: INVITE sip:1234@10.4.126.232 SIP/2.0 Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK1e2cf1f4 From: sip:4321@10.4.119.245;tag=as3287914c To: Test1 ;tag=2e0ba312e07ed9f Contact: Call-ID: 437ca631f88d70553dbe5edc5ce7d949@10.4.119.245 CSeq: 104 INVITE User-Agent: Asterisk PBX Max-Forwards: 70 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces X-asterisk-Info: SIP re-invite (External RTP bridge) Content-Type: application/sdp Content-Length: 208 v=0 o=root 30622 30625 IN IP4 10.4.119.245 s=session c=IN IP4 10.4.119.245 t=0 0 m=audio 18712 RTP/AVP 0 8 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv --- [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:1975 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #36 [Mar 19 09:34:57] <--- SIP read from 10.4.126.232:5060 ---> SIP/2.0 200 OK Call-ID: 437ca631f88d70553dbe5edc5ce7d949@10.4.119.245 CSeq: 103 INVITE From: sip:4321@10.4.119.245;tag=as3287914c To: Test1 ;tag=2e0ba312e07ed9f Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK7b844fee Content-Length: 189 Session-Expires: 3600;refresher=uas Allow: INVITE, ACK, BYE, CANCEL, REFER, NOTIFY Content-Type: application/sdp Supported: replaces Contact: Test1 User-Agent: MxSipApp/5.0.16.99 MxSF/v3.2.1.1 v=0 o=MxSIP 352673312983635746 376570794169103870 IN IP4 10.4.126.232 s=- c=IN IP4 10.4.126.232 t=0 0 a=sendrecv m=audio 5004 RTP/AVP 0 8 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 <-------------> [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 0: SIP/2.0 200 OK (14) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 1: Call-ID: 437ca631f88d70553dbe5edc5ce7d949@10.4.119.245 (54) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 2: CSeq: 103 INVITE (16) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 3: From: sip:4321@10.4.119.245;tag=as3287914c (42) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 4: To: Test1 ;tag=2e0ba312e07ed9f (53) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 5: Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK7b844fee (57) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 6: Content-Length: 189 (19) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 7: Session-Expires: 3600;refresher=uas (35) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 8: Allow: INVITE, ACK, BYE, CANCEL, REFER, NOTIFY (46) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 9: Content-Type: application/sdp (29) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 10: Supported: replaces (19) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 11: Contact: Test1 (38) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 12: User-Agent: MxSipApp/5.0.16.99 MxSF/v3.2.1.1 (44) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 13: (0) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4605 parse_request: Line: v=0 (3) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4605 parse_request: Line: o=MxSIP 352673312983635746 376570794169103870 IN IP4 10.4.126.232 (65) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4605 parse_request: Line: s=- (3) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4605 parse_request: Line: c=IN IP4 10.4.126.232 (21) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4605 parse_request: Line: t=0 0 (5) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4605 parse_request: Line: a=sendrecv (10) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4605 parse_request: Line: m=audio 5004 RTP/AVP 0 8 (24) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4605 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4605 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Mar 19 09:34:57] --- (13 headers 9 lines) --- [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '437ca631f88d70553dbe5edc5ce7d949@10.4.119.245' of Request 103: Match Not Found [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:11639 handle_response_invite: SIP response 200 to RE-invite on outgoing call 437ca631f88d70553dbe5edc5ce7d949@10.4.119.245 [Mar 19 09:34:57] Found RTP audio format 0 [Mar 19 09:34:57] Found RTP audio format 8 [Mar 19 09:34:57] Peer audio RTP is at port 10.4.126.232:5004 [Mar 19 09:34:57] Found description format PCMU for ID 0 [Mar 19 09:34:57] Found description format PCMA for ID 8 [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:5129 process_sdp: T38 state changed to 0 on channel SIP/1234-08a1a280 [Mar 19 09:34:57] Capabilities: us - 0xc (ulaw|alaw), peer - audio=0xc (ulaw|alaw)/video=0x0 (nothing), combined - 0xc (ulaw|alaw) [Mar 19 09:34:57] Non-codec capabilities (dtmf): us - 0x0 (nothing), peer - 0x0 (nothing), combined - 0x0 (nothing) [Mar 19 09:34:57] Peer audio RTP is at port 10.4.126.232:5004 [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:5209 process_sdp: We're settling with these formats: 0xc (ulaw|alaw) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:5216 process_sdp: We have an owner, now see if we need to change this call [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:3003 update_call_counter: Updating call counter for incoming call [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:7919 build_route: build_route: Retaining previous route: [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:11772 handle_response_invite: Strange... The other side of the bridge does not have a udptl struct [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:11777 handle_response_invite: T38 state changed to 0 on channel SIP [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:11780 handle_response_invite: T38 state changed to 0 on channel SIP/1234-08a1a280 [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:5643 reqprep: Strict routing enforced for session 437ca631f88d70553dbe5edc5ce7d949@10.4.119.245 [Mar 19 09:34:57] set_destination: Parsing for address/port to send to [Mar 19 09:34:57] set_destination: set destination to 10.4.126.232, port 5060 [Mar 19 09:34:57] Transmitting (no NAT) to 10.4.126.232:5060: ACK sip:1234@10.4.126.232 SIP/2.0 Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK7b0ec2ad From: sip:4321@10.4.119.245;tag=as3287914c To: Test1 ;tag=2e0ba312e07ed9f Contact: Call-ID: 437ca631f88d70553dbe5edc5ce7d949@10.4.119.245 CSeq: 103 ACK User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- [Mar 19 09:34:57] DEBUG[30656]: chan_sip.c:16903 sip_set_rtp_peer: Sending reinvite on SIP '4639e6c371fc2daa253ab6f923e3ed63@10.4.119.245' - It's audio soon redirected to IP 10.4.126.232 [Mar 19 09:34:57] DEBUG[30656]: chan_sip.c:5643 reqprep: Strict routing enforced for session 4639e6c371fc2daa253ab6f923e3ed63@10.4.119.245 [Mar 19 09:34:57] set_destination: Parsing for address/port to send to [Mar 19 09:34:57] set_destination: set destination to 10.4.127.230, port 5060 [Mar 19 09:34:57] DEBUG[30656]: chan_sip.c:6188 add_sdp: ** Our capability: 0xc (ulaw|alaw) Video flag: True [Mar 19 09:34:57] DEBUG[30656]: chan_sip.c:6189 add_sdp: ** Our prefcodec: 0x4 (ulaw) [Mar 19 09:34:57] Audio is at 10.4.119.245 port 13288 [Mar 19 09:34:57] Adding codec 0x4 (ulaw) to SDP [Mar 19 09:34:57] Adding codec 0x8 (alaw) to SDP [Mar 19 09:34:57] DEBUG[30656]: chan_sip.c:6320 add_sdp: -- Done with adding codecs to SDP [Mar 19 09:34:57] DEBUG[30656]: chan_sip.c:6365 add_sdp: Done building SDP. Settling with this capability: 0xc (ulaw|alaw) [Mar 19 09:34:57] DEBUG[30656]: chan_sip.c:1621 initialize_initreq: Initializing already initialized SIP dialog 4639e6c371fc2daa253ab6f923e3ed63@10.4.119.245 (presumably reinvite) [Mar 19 09:34:57] DEBUG[30656]: chan_sip.c:4573 parse_request: Header 0: INVITE sip:4321@10.4.127.230 SIP/2.0 (36) [Mar 19 09:34:57] DEBUG[30656]: chan_sip.c:4573 parse_request: Header 1: Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK35f1824b (57) [Mar 19 09:34:57] DEBUG[30656]: chan_sip.c:4573 parse_request: Header 2: From: "Test1" ;tag=as048f2ce7 (52) [Mar 19 09:34:57] DEBUG[30656]: chan_sip.c:4573 parse_request: Header 3: To: ;tag=fb81406bf2af5d8 (47) [Mar 19 09:34:57] DEBUG[30656]: chan_sip.c:4573 parse_request: Header 4: Contact: (32) [Mar 19 09:34:57] DEBUG[30656]: chan_sip.c:4573 parse_request: Header 5: Call-ID: 4639e6c371fc2daa253ab6f923e3ed63@10.4.119.245 (54) [Mar 19 09:34:57] DEBUG[30656]: chan_sip.c:4573 parse_request: Header 6: CSeq: 104 INVITE (16) [Mar 19 09:34:57] DEBUG[30656]: chan_sip.c:4573 parse_request: Header 7: User-Agent: Asterisk PBX (24) [Mar 19 09:34:57] DEBUG[30656]: chan_sip.c:4573 parse_request: Header 8: Max-Forwards: 70 (16) [Mar 19 09:34:57] DEBUG[30656]: chan_sip.c:4573 parse_request: Header 9: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Mar 19 09:34:57] DEBUG[30656]: chan_sip.c:4573 parse_request: Header 10: Supported: replaces (19) [Mar 19 09:34:57] DEBUG[30656]: chan_sip.c:4573 parse_request: Header 11: X-asterisk-Info: SIP re-invite (External RTP bridge) (52) [Mar 19 09:34:57] DEBUG[30656]: chan_sip.c:4573 parse_request: Header 12: Content-Type: application/sdp (29) [Mar 19 09:34:57] DEBUG[30656]: chan_sip.c:4573 parse_request: Header 13: Content-Length: 207 (19) [Mar 19 09:34:57] DEBUG[30656]: chan_sip.c:4573 parse_request: Header 14: (0) [Mar 19 09:34:57] DEBUG[30656]: chan_sip.c:4605 parse_request: Line: v=0 (3) [Mar 19 09:34:57] DEBUG[30656]: chan_sip.c:4605 parse_request: Line: o=root 30622 30625 IN IP4 10.4.126.232 (38) [Mar 19 09:34:57] DEBUG[30656]: chan_sip.c:4605 parse_request: Line: s=session (9) [Mar 19 09:34:57] DEBUG[30656]: chan_sip.c:4605 parse_request: Line: c=IN IP4 10.4.126.232 (21) [Mar 19 09:34:57] DEBUG[30656]: chan_sip.c:4605 parse_request: Line: t=0 0 (5) [Mar 19 09:34:57] DEBUG[30656]: chan_sip.c:4605 parse_request: Line: m=audio 5004 RTP/AVP 0 8 (24) [Mar 19 09:34:57] DEBUG[30656]: chan_sip.c:4605 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Mar 19 09:34:57] DEBUG[30656]: chan_sip.c:4605 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Mar 19 09:34:57] DEBUG[30656]: chan_sip.c:4605 parse_request: Line: a=silenceSupp:off - - - - (25) [Mar 19 09:34:57] DEBUG[30656]: chan_sip.c:4605 parse_request: Line: a=ptime:20 (10) [Mar 19 09:34:57] DEBUG[30656]: chan_sip.c:4605 parse_request: Line: a=inactive (10) [Mar 19 09:34:57] Reliably Transmitting (no NAT) to 10.4.127.230:5060: INVITE sip:4321@10.4.127.230 SIP/2.0 Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK35f1824b From: "Test1" ;tag=as048f2ce7 To: ;tag=fb81406bf2af5d8 Contact: Call-ID: 4639e6c371fc2daa253ab6f923e3ed63@10.4.119.245 CSeq: 104 INVITE User-Agent: Asterisk PBX Max-Forwards: 70 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces X-asterisk-Info: SIP re-invite (External RTP bridge) Content-Type: application/sdp Content-Length: 207 v=0 o=root 30622 30625 IN IP4 10.4.126.232 s=session c=IN IP4 10.4.126.232 t=0 0 m=audio 5004 RTP/AVP 0 8 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=silenceSupp:off - - - - a=ptime:20 a=inactive --- [Mar 19 09:34:57] DEBUG[30656]: chan_sip.c:1975 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #37 [Mar 19 09:34:57] <--- SIP read from 10.4.126.232:5060 ---> SIP/2.0 500 Server Internal Error Call-ID: 437ca631f88d70553dbe5edc5ce7d949@10.4.119.245 CSeq: 104 INVITE From: sip:4321@10.4.119.245;tag=as3287914c To: Test1 ;tag=2e0ba312e07ed9f Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK1e2cf1f4 Content-Length: 0 Retry-After: 3 User-Agent: MxSipApp/5.0.16.99 MxSF/v3.2.1.1 <-------------> [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 0: SIP/2.0 500 Server Internal Error (33) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 1: Call-ID: 437ca631f88d70553dbe5edc5ce7d949@10.4.119.245 (54) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 2: CSeq: 104 INVITE (16) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 3: From: sip:4321@10.4.119.245;tag=as3287914c (42) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 4: To: Test1 ;tag=2e0ba312e07ed9f (53) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 5: Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK1e2cf1f4 (57) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 6: Content-Length: 0 (17) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 7: Retry-After: 3 (14) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 8: User-Agent: MxSipApp/5.0.16.99 MxSF/v3.2.1.1 (44) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 9: (0) [Mar 19 09:34:57] --- (9 headers 0 lines) --- [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:2071 __sip_ack: Acked pending invite 104 [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:2079 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #36 [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '437ca631f88d70553dbe5edc5ce7d949@10.4.119.245' of Request 104: Match Not Found [Mar 19 09:34:57] -- Got SIP response 500 "Server Internal Error" back from 10.4.126.232 [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:5643 reqprep: Strict routing enforced for session 437ca631f88d70553dbe5edc5ce7d949@10.4.119.245 [Mar 19 09:34:57] set_destination: Parsing for address/port to send to [Mar 19 09:34:57] set_destination: set destination to 10.4.126.232, port 5060 [Mar 19 09:34:57] Transmitting (no NAT) to 10.4.126.232:5060: ACK sip:1234@10.4.126.232 SIP/2.0 Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK7b0ec2ad From: sip:4321@10.4.119.245;tag=as3287914c To: Test1 ;tag=2e0ba312e07ed9f Contact: Call-ID: 437ca631f88d70553dbe5edc5ce7d949@10.4.119.245 CSeq: 104 ACK User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:1633 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 437ca631f88d70553dbe5edc5ce7d949@10.4.119.245 [Mar 19 09:34:57] DEBUG[30656]: rtp.c:2904 bridge_native_loop: Got a FRAME_CONTROL (8) frame on channel SIP/1234-08a1a280 [Mar 19 09:34:57] DEBUG[30656]: channel.c:4048 ast_channel_bridge: Returning from native bridge, channels: SIP/1234-08a1a280, SIP/4321-08a1e1e8 [Mar 19 09:34:57] DEBUG[30656]: channel.c:1693 ast_hangup: Hanging up channel 'SIP/4321-08a1e1e8' [Mar 19 09:34:57] DEBUG[30656]: chan_sip.c:3312 sip_hangup: Hangup call SIP/4321-08a1e1e8, SIP callid 4639e6c371fc2daa253ab6f923e3ed63@10.4.119.245) [Mar 19 09:34:57] Scheduling destruction of SIP dialog '4639e6c371fc2daa253ab6f923e3ed63@10.4.119.245' in 32000 ms (Method: ACK) [Mar 19 09:34:57] DEBUG[30656]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/4321-08a1e1e8 [Mar 19 09:34:57] DEBUG[30656]: rtp.c:1476 ast_rtp_early_bridge: Channel '' has no RTP, not doing anything [Mar 19 09:34:57] DEBUG[30656]: app_dial.c:1670 dial_exec_full: Exiting with DIALSTATUS=ANSWER. [Mar 19 09:34:57] DEBUG[30656]: pbx.c:2393 __ast_pbx_run: Spawn extension (default,4321,1) exited non-zero on 'SIP/1234-08a1a280' [Mar 19 09:34:57] == Spawn extension (default, 4321, 1) exited non-zero on 'SIP/1234-08a1a280' [Mar 19 09:34:57] -- Stopped music on hold on SIP/1234-08a1a280 [Mar 19 09:34:57] DEBUG[30656]: channel.c:2845 set_format: Set channel SIP/1234-08a1a280 to write format ulaw [Mar 19 09:34:57] DEBUG[30656]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '"Test1" <1234>' [Mar 19 09:34:57] DEBUG[30656]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '1234' [Mar 19 09:34:57] DEBUG[30656]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '4321' [Mar 19 09:34:57] DEBUG[30656]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'default' [Mar 19 09:34:57] DEBUG[30656]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'SIP/1234-08a1a280' [Mar 19 09:34:57] DEBUG[30656]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'SIP/4321-08a1e1e8' [Mar 19 09:34:57] DEBUG[30656]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'Dial' [Mar 19 09:34:57] DEBUG[30656]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'SIP/4321||' [Mar 19 09:34:57] DEBUG[30656]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '2007-03-19 09:34:53' [Mar 19 09:34:57] DEBUG[30656]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '2007-03-19 09:34:54' [Mar 19 09:34:57] DEBUG[30656]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '2007-03-19 09:34:57' [Mar 19 09:34:57] DEBUG[30656]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '4' [Mar 19 09:34:57] DEBUG[30656]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '3' [Mar 19 09:34:57] DEBUG[30656]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'ANSWERED' [Mar 19 09:34:57] DEBUG[30656]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' [Mar 19 09:34:57] DEBUG[30656]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '' [Mar 19 09:34:57] DEBUG[30656]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '1174311293.0' [Mar 19 09:34:57] DEBUG[30656]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '' [Mar 19 09:34:57] DEBUG[30628]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 4321 [Mar 19 09:34:57] DEBUG[30656]: channel.c:1693 ast_hangup: Hanging up channel 'SIP/1234-08a1a280' [Mar 19 09:34:57] DEBUG[30656]: chan_sip.c:3312 sip_hangup: Hangup call SIP/1234-08a1a280, SIP callid 437ca631f88d70553dbe5edc5ce7d949@10.4.119.245) [Mar 19 09:34:57] DEBUG[30656]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/1234-08a1a280 [Mar 19 09:34:57] DEBUG[30628]: chan_sip.c:15240 sip_devicestate: Checking device state for peer 4321 [Mar 19 09:34:57] DEBUG[30628]: devicestate.c:287 do_state_change: Changing state for SIP/4321 - state 1 (Not in use) [Mar 19 09:34:57] DEBUG[30628]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 1234 [Mar 19 09:34:57] DEBUG[30628]: chan_sip.c:15240 sip_devicestate: Checking device state for peer 1234 [Mar 19 09:34:57] DEBUG[30628]: devicestate.c:287 do_state_change: Changing state for SIP/1234 - state 1 (Not in use) [Mar 19 09:34:57] DEBUG[30661]: app_queue.c:546 changethread: Device 'SIP/4321' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Mar 19 09:34:57] DEBUG[30662]: app_queue.c:546 changethread: Device 'SIP/1234' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Mar 19 09:34:57] <--- SIP read from 10.4.127.230:5060 ---> SIP/2.0 100 Trying Call-ID: 4639e6c371fc2daa253ab6f923e3ed63@10.4.119.245 CSeq: 104 INVITE From: "Test1" ;tag=as048f2ce7 To: ;tag=fb81406bf2af5d8 Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK35f1824b Content-Length: 0 User-Agent: MxSipApp/5.0.15.88 MxSF/v3.2.1.1 <-------------> [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 0: SIP/2.0 100 Trying (18) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 1: Call-ID: 4639e6c371fc2daa253ab6f923e3ed63@10.4.119.245 (54) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 2: CSeq: 104 INVITE (16) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 3: From: "Test1" ;tag=as048f2ce7 (52) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 4: To: ;tag=fb81406bf2af5d8 (47) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 5: Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK35f1824b (57) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 6: Content-Length: 0 (17) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 7: User-Agent: MxSipApp/5.0.15.88 MxSF/v3.2.1.1 (44) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 8: (0) [Mar 19 09:34:57] --- (8 headers 0 lines) --- [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:2122 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #37 - INVITE (got response) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:2131 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '4639e6c371fc2daa253ab6f923e3ed63@10.4.119.245' Request 104: Found [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:11641 handle_response_invite: SIP response 100 to standard invite [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:5643 reqprep: Strict routing enforced for session 4639e6c371fc2daa253ab6f923e3ed63@10.4.119.245 [Mar 19 09:34:57] set_destination: Parsing for address/port to send to [Mar 19 09:34:57] set_destination: set destination to 10.4.127.230, port 5060 [Mar 19 09:34:57] Reliably Transmitting (no NAT) to 10.4.127.230:5060: BYE sip:4321@10.4.127.230 SIP/2.0 Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK3a8bf0bd From: "Test1" ;tag=as048f2ce7 To: ;tag=fb81406bf2af5d8 Call-ID: 4639e6c371fc2daa253ab6f923e3ed63@10.4.119.245 CSeq: 105 BYE User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:1975 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #39 [Mar 19 09:34:57] Scheduling destruction of SIP dialog '4639e6c371fc2daa253ab6f923e3ed63@10.4.119.245' in 32000 ms (Method: ACK) [Mar 19 09:34:57] Really destroying SIP dialog '437ca631f88d70553dbe5edc5ce7d949@10.4.119.245' Method: ACK [Mar 19 09:34:57] <--- SIP read from 10.4.127.230:5060 ---> SIP/2.0 200 OK Call-ID: 4639e6c371fc2daa253ab6f923e3ed63@10.4.119.245 CSeq: 104 INVITE From: "Test1" ;tag=as048f2ce7 To: ;tag=fb81406bf2af5d8 Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK35f1824b Content-Length: 185 Session-Expires: 3600;refresher=uas Allow: INVITE, ACK, BYE, CANCEL, REFER, NOTIFY Content-Type: application/sdp Supported: replaces Contact: Test2 User-Agent: MxSipApp/5.0.15.88 MxSF/v3.2.1.1 v=0 o=MxSIP 599798619795376287 2005741632565392606 IN IP4 10.4.127.230 s=- c=IN IP4 0.0.0.0 t=0 0 a=inactive m=audio 5004 RTP/AVP 0 8 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 <-------------> [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 0: SIP/2.0 200 OK (14) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 1: Call-ID: 4639e6c371fc2daa253ab6f923e3ed63@10.4.119.245 (54) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 2: CSeq: 104 INVITE (16) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 3: From: "Test1" ;tag=as048f2ce7 (52) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 4: To: ;tag=fb81406bf2af5d8 (47) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 5: Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK35f1824b (57) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 6: Content-Length: 185 (19) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 7: Session-Expires: 3600;refresher=uas (35) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 8: Allow: INVITE, ACK, BYE, CANCEL, REFER, NOTIFY (46) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 9: Content-Type: application/sdp (29) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 10: Supported: replaces (19) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 11: Contact: Test2 (38) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 12: User-Agent: MxSipApp/5.0.15.88 MxSF/v3.2.1.1 (44) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 13: (0) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4605 parse_request: Line: v=0 (3) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4605 parse_request: Line: o=MxSIP 599798619795376287 2005741632565392606 IN IP4 10.4.127.230 (66) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4605 parse_request: Line: s=- (3) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4605 parse_request: Line: c=IN IP4 0.0.0.0 (16) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4605 parse_request: Line: t=0 0 (5) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4605 parse_request: Line: a=inactive (10) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4605 parse_request: Line: m=audio 5004 RTP/AVP 0 8 (24) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4605 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4605 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Mar 19 09:34:57] --- (13 headers 9 lines) --- [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:2071 __sip_ack: Acked pending invite 104 [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '4639e6c371fc2daa253ab6f923e3ed63@10.4.119.245' of Request 104: Match Not Found [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:11641 handle_response_invite: SIP response 200 to standard invite [Mar 19 09:34:57] Found RTP audio format 0 [Mar 19 09:34:57] Found RTP audio format 8 [Mar 19 09:34:57] Peer audio RTP is at port 0.0.0.0:5004 [Mar 19 09:34:57] Found description format PCMU for ID 0 [Mar 19 09:34:57] Found description format PCMA for ID 8 [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:5129 process_sdp: T38 state changed to 0 on channel [Mar 19 09:34:57] Capabilities: us - 0xc (ulaw|alaw), peer - audio=0xc (ulaw|alaw)/video=0x0 (nothing), combined - 0xc (ulaw|alaw) [Mar 19 09:34:57] Non-codec capabilities (dtmf): us - 0x0 (nothing), peer - 0x0 (nothing), combined - 0x0 (nothing) [Mar 19 09:34:57] Peer audio RTP is at port 0.0.0.0:5004 [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:5209 process_sdp: We're settling with these formats: 0xc (ulaw|alaw) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:3003 update_call_counter: Updating call counter for outgoing call [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:7919 build_route: build_route: Retaining previous route: [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:5643 reqprep: Strict routing enforced for session 4639e6c371fc2daa253ab6f923e3ed63@10.4.119.245 [Mar 19 09:34:57] set_destination: Parsing for address/port to send to [Mar 19 09:34:57] set_destination: set destination to 10.4.127.230, port 5060 [Mar 19 09:34:57] Transmitting (no NAT) to 10.4.127.230:5060: ACK sip:4321@10.4.127.230 SIP/2.0 Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK44aa5939 From: "Test1" ;tag=as048f2ce7 To: ;tag=fb81406bf2af5d8 Contact: Call-ID: 4639e6c371fc2daa253ab6f923e3ed63@10.4.119.245 CSeq: 104 ACK User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- [Mar 19 09:34:57] <--- SIP read from 10.4.127.230:5060 ---> SIP/2.0 200 OK Call-ID: 4639e6c371fc2daa253ab6f923e3ed63@10.4.119.245 CSeq: 105 BYE From: "Test1" ;tag=as048f2ce7 To: ;tag=fb81406bf2af5d8 Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK3a8bf0bd Content-Length: 0 Supported: replaces User-Agent: MxSipApp/5.0.15.88 MxSF/v3.2.1.1 <-------------> [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 0: SIP/2.0 200 OK (14) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 1: Call-ID: 4639e6c371fc2daa253ab6f923e3ed63@10.4.119.245 (54) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 2: CSeq: 105 BYE (13) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 3: From: "Test1" ;tag=as048f2ce7 (52) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 4: To: ;tag=fb81406bf2af5d8 (47) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 5: Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK3a8bf0bd (57) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 6: Content-Length: 0 (17) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 7: Supported: replaces (19) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 8: User-Agent: MxSipApp/5.0.15.88 MxSF/v3.2.1.1 (44) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 9: (0) [Mar 19 09:34:57] --- (9 headers 0 lines) --- [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:2079 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #39 [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '4639e6c371fc2daa253ab6f923e3ed63@10.4.119.245' of Request 105: Match Not Found [Mar 19 09:34:57] Really destroying SIP dialog '4639e6c371fc2daa253ab6f923e3ed63@10.4.119.245' Method: ACK [Mar 19 09:34:57] <--- SIP read from 10.4.126.232:5060 ---> SIP/2.0 500 Server Internal Error Call-ID: 437ca631f88d70553dbe5edc5ce7d949@10.4.119.245 CSeq: 104 INVITE From: sip:4321@10.4.119.245;tag=as3287914c To: Test1 ;tag=2e0ba312e07ed9f Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK1e2cf1f4 Content-Length: 0 Retry-After: 3 User-Agent: MxSipApp/5.0.16.99 MxSF/v3.2.1.1 <-------------> [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 0: SIP/2.0 500 Server Internal Error (33) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 1: Call-ID: 437ca631f88d70553dbe5edc5ce7d949@10.4.119.245 (54) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 2: CSeq: 104 INVITE (16) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 3: From: sip:4321@10.4.119.245;tag=as3287914c (42) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 4: To: Test1 ;tag=2e0ba312e07ed9f (53) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 5: Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK1e2cf1f4 (57) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 6: Content-Length: 0 (17) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 7: Retry-After: 3 (14) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 8: User-Agent: MxSipApp/5.0.16.99 MxSF/v3.2.1.1 (44) [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 9: (0) [Mar 19 09:34:57] --- (9 headers 0 lines) --- [Mar 19 09:34:57] DEBUG[30638]: chan_sip.c:14813 sipsock_read: Invalid SIP message - rejected , no callid, len 350 [Mar 19 09:34:58] <--- SIP read from 10.4.126.232:5060 ---> SIP/2.0 500 Server Internal Error Call-ID: 437ca631f88d70553dbe5edc5ce7d949@10.4.119.245 CSeq: 104 INVITE From: sip:4321@10.4.119.245;tag=as3287914c To: Test1 ;tag=2e0ba312e07ed9f Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK1e2cf1f4 Content-Length: 0 Retry-After: 3 User-Agent: MxSipApp/5.0.16.99 MxSF/v3.2.1.1 <-------------> [Mar 19 09:34:58] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 0: SIP/2.0 500 Server Internal Error (33) [Mar 19 09:34:58] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 1: Call-ID: 437ca631f88d70553dbe5edc5ce7d949@10.4.119.245 (54) [Mar 19 09:34:58] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 2: CSeq: 104 INVITE (16) [Mar 19 09:34:58] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 3: From: sip:4321@10.4.119.245;tag=as3287914c (42) [Mar 19 09:34:58] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 4: To: Test1 ;tag=2e0ba312e07ed9f (53) [Mar 19 09:34:58] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 5: Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK1e2cf1f4 (57) [Mar 19 09:34:58] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 6: Content-Length: 0 (17) [Mar 19 09:34:58] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 7: Retry-After: 3 (14) [Mar 19 09:34:58] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 8: User-Agent: MxSipApp/5.0.16.99 MxSF/v3.2.1.1 (44) [Mar 19 09:34:58] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 9: (0) [Mar 19 09:34:58] --- (9 headers 0 lines) --- [Mar 19 09:34:58] DEBUG[30638]: chan_sip.c:14813 sipsock_read: Invalid SIP message - rejected , no callid, len 350 [Mar 19 09:35:00] <--- SIP read from 10.4.126.232:5060 ---> SIP/2.0 500 Server Internal Error Call-ID: 437ca631f88d70553dbe5edc5ce7d949@10.4.119.245 CSeq: 104 INVITE From: sip:4321@10.4.119.245;tag=as3287914c To: Test1 ;tag=2e0ba312e07ed9f Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK1e2cf1f4 Content-Length: 0 Retry-After: 3 User-Agent: MxSipApp/5.0.16.99 MxSF/v3.2.1.1 <-------------> [Mar 19 09:35:00] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 0: SIP/2.0 500 Server Internal Error (33) [Mar 19 09:35:00] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 1: Call-ID: 437ca631f88d70553dbe5edc5ce7d949@10.4.119.245 (54) [Mar 19 09:35:00] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 2: CSeq: 104 INVITE (16) [Mar 19 09:35:00] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 3: From: sip:4321@10.4.119.245;tag=as3287914c (42) [Mar 19 09:35:00] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 4: To: Test1 ;tag=2e0ba312e07ed9f (53) [Mar 19 09:35:00] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 5: Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK1e2cf1f4 (57) [Mar 19 09:35:00] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 6: Content-Length: 0 (17) [Mar 19 09:35:00] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 7: Retry-After: 3 (14) [Mar 19 09:35:00] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 8: User-Agent: MxSipApp/5.0.16.99 MxSF/v3.2.1.1 (44) [Mar 19 09:35:00] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 9: (0) [Mar 19 09:35:00] --- (9 headers 0 lines) --- [Mar 19 09:35:00] DEBUG[30638]: chan_sip.c:14813 sipsock_read: Invalid SIP message - rejected , no callid, len 350 [Mar 19 09:35:00] <--- SIP read from 10.4.123.235:5060 ---> REGISTER sip:10.4.119.245 SIP/2.0 Via: SIP/2.0/UDP 10.4.123.235;branch=z9hG4bKa092d3c40 Content-Length: 0 To: Test3 From: Test3 ;tag=0abead759761211 Call-ID: a86b58442719b96c033029da1651b6fb@10.4.119.245 CSeq: 1360341125 REGISTER Contact: Test3 User-Agent: MxSipApp/5.0.16.96 MxSF/v3.2.1.1 <-------------> [Mar 19 09:35:00] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 0: REGISTER sip:10.4.119.245 SIP/2.0 (33) [Mar 19 09:35:00] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 1: Via: SIP/2.0/UDP 10.4.123.235;branch=z9hG4bKa092d3c40 (53) [Mar 19 09:35:00] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 2: Content-Length: 0 (17) [Mar 19 09:35:00] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 3: To: Test3 (33) [Mar 19 09:35:00] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 4: From: Test3 ;tag=0abead759761211 (55) [Mar 19 09:35:00] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 5: Call-ID: a86b58442719b96c033029da1651b6fb@10.4.119.245 (54) [Mar 19 09:35:00] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 6: CSeq: 1360341125 REGISTER (25) [Mar 19 09:35:00] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 7: Contact: Test3 (38) [Mar 19 09:35:00] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 8: User-Agent: MxSipApp/5.0.16.96 MxSF/v3.2.1.1 (44) [Mar 19 09:35:00] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 9: (0) [Mar 19 09:35:00] --- (9 headers 0 lines) --- [Mar 19 09:35:00] DEBUG[30638]: chan_sip.c:4310 sip_alloc: Allocating new SIP dialog for a86b58442719b96c033029da1651b6fb@10.4.119.245 - REGISTER (No RTP) [Mar 19 09:35:00] DEBUG[30638]: chan_sip.c:14629 handle_request: **** Received REGISTER (2) - Command in SIP REGISTER [Mar 19 09:35:00] Using latest REGISTER request as basis request [Mar 19 09:35:00] Sending to 10.4.123.235 : 5060 (no NAT) [Mar 19 09:35:00] <--- Transmitting (no NAT) to 10.4.123.235:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.4.123.235;branch=z9hG4bKa092d3c40;received=10.4.123.235 From: Test3 ;tag=0abead759761211 To: Test3 Call-ID: a86b58442719b96c033029da1651b6fb@10.4.119.245 CSeq: 1360341125 REGISTER User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Mar 19 09:35:00] -- Saved useragent "MxSipApp/5.0.16.96 MxSF/v3.2.1.1" for peer 5678 [Mar 19 09:35:00] <--- Transmitting (no NAT) to 10.4.123.235:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.4.123.235;branch=z9hG4bKa092d3c40;received=10.4.123.235 From: Test3 ;tag=0abead759761211 To: Test3 ;tag=as00a8218d Call-ID: a86b58442719b96c033029da1651b6fb@10.4.119.245 CSeq: 1360341125 REGISTER User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Expires: 120 Contact: ;expires=120 Date: Mon, 19 Mar 2007 13:35:00 GMT Content-Length: 0 <------------> [Mar 19 09:35:00] DEBUG[30638]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/5678 [Mar 19 09:35:00] Scheduling destruction of SIP dialog 'a86b58442719b96c033029da1651b6fb@10.4.119.245' in 32000 ms (Method: REGISTER) [Mar 19 09:35:00] DEBUG[30628]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5678 [Mar 19 09:35:00] DEBUG[30628]: chan_sip.c:15240 sip_devicestate: Checking device state for peer 5678 [Mar 19 09:35:00] DEBUG[30628]: devicestate.c:287 do_state_change: Changing state for SIP/5678 - state 1 (Not in use) [Mar 19 09:35:00] DEBUG[30663]: app_queue.c:546 changethread: Device 'SIP/5678' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Mar 19 09:35:01] <--- SIP read from 10.4.126.232:5060 ---> REGISTER sip:10.4.119.245 SIP/2.0 Via: SIP/2.0/UDP 10.4.126.232;branch=z9hG4bK86542519f Content-Length: 0 To: Test1 From: Test1 ;tag=7872b303b2c30ae Call-ID: ca51fef242c670e33e7ef124f61fda18@10.4.119.245 CSeq: 1781711407 REGISTER Contact: Test1 User-Agent: MxSipApp/5.0.16.99 MxSF/v3.2.1.1 <-------------> [Mar 19 09:35:01] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 0: REGISTER sip:10.4.119.245 SIP/2.0 (33) [Mar 19 09:35:01] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 1: Via: SIP/2.0/UDP 10.4.126.232;branch=z9hG4bK86542519f (53) [Mar 19 09:35:01] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 2: Content-Length: 0 (17) [Mar 19 09:35:01] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 3: To: Test1 (33) [Mar 19 09:35:01] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 4: From: Test1 ;tag=7872b303b2c30ae (55) [Mar 19 09:35:01] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 5: Call-ID: ca51fef242c670e33e7ef124f61fda18@10.4.119.245 (54) [Mar 19 09:35:01] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 6: CSeq: 1781711407 REGISTER (25) [Mar 19 09:35:01] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 7: Contact: Test1 (38) [Mar 19 09:35:01] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 8: User-Agent: MxSipApp/5.0.16.99 MxSF/v3.2.1.1 (44) [Mar 19 09:35:01] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 9: (0) [Mar 19 09:35:01] --- (9 headers 0 lines) --- [Mar 19 09:35:01] DEBUG[30638]: chan_sip.c:4310 sip_alloc: Allocating new SIP dialog for ca51fef242c670e33e7ef124f61fda18@10.4.119.245 - REGISTER (No RTP) [Mar 19 09:35:01] DEBUG[30638]: chan_sip.c:14629 handle_request: **** Received REGISTER (2) - Command in SIP REGISTER [Mar 19 09:35:01] Using latest REGISTER request as basis request [Mar 19 09:35:01] Sending to 10.4.126.232 : 5060 (no NAT) [Mar 19 09:35:01] <--- Transmitting (no NAT) to 10.4.126.232:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.4.126.232;branch=z9hG4bK86542519f;received=10.4.126.232 From: Test1 ;tag=7872b303b2c30ae To: Test1 Call-ID: ca51fef242c670e33e7ef124f61fda18@10.4.119.245 CSeq: 1781711407 REGISTER User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Mar 19 09:35:01] -- Saved useragent "MxSipApp/5.0.16.99 MxSF/v3.2.1.1" for peer 1234 [Mar 19 09:35:01] <--- Transmitting (no NAT) to 10.4.126.232:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.4.126.232;branch=z9hG4bK86542519f;received=10.4.126.232 From: Test1 ;tag=7872b303b2c30ae To: Test1 ;tag=as7fd5c655 Call-ID: ca51fef242c670e33e7ef124f61fda18@10.4.119.245 CSeq: 1781711407 REGISTER User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Expires: 120 Contact: ;expires=120 Date: Mon, 19 Mar 2007 13:35:01 GMT Content-Length: 0 <------------> [Mar 19 09:35:01] DEBUG[30638]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/1234 [Mar 19 09:35:01] DEBUG[30628]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 1234 [Mar 19 09:35:01] DEBUG[30628]: chan_sip.c:15240 sip_devicestate: Checking device state for peer 1234 [Mar 19 09:35:01] DEBUG[30628]: devicestate.c:287 do_state_change: Changing state for SIP/1234 - state 1 (Not in use) [Mar 19 09:35:01] Scheduling destruction of SIP dialog 'ca51fef242c670e33e7ef124f61fda18@10.4.119.245' in 32000 ms (Method: REGISTER) [Mar 19 09:35:01] DEBUG[30664]: app_queue.c:546 changethread: Device 'SIP/1234' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Mar 19 09:35:04] <--- SIP read from 10.4.126.232:5060 ---> SIP/2.0 500 Server Internal Error Call-ID: 437ca631f88d70553dbe5edc5ce7d949@10.4.119.245 CSeq: 104 INVITE From: sip:4321@10.4.119.245;tag=as3287914c To: Test1 ;tag=2e0ba312e07ed9f Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK1e2cf1f4 Content-Length: 0 Retry-After: 3 User-Agent: MxSipApp/5.0.16.99 MxSF/v3.2.1.1 <-------------> [Mar 19 09:35:04] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 0: SIP/2.0 500 Server Internal Error (33) [Mar 19 09:35:04] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 1: Call-ID: 437ca631f88d70553dbe5edc5ce7d949@10.4.119.245 (54) [Mar 19 09:35:04] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 2: CSeq: 104 INVITE (16) [Mar 19 09:35:04] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 3: From: sip:4321@10.4.119.245;tag=as3287914c (42) [Mar 19 09:35:04] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 4: To: Test1 ;tag=2e0ba312e07ed9f (53) [Mar 19 09:35:04] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 5: Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK1e2cf1f4 (57) [Mar 19 09:35:04] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 6: Content-Length: 0 (17) [Mar 19 09:35:04] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 7: Retry-After: 3 (14) [Mar 19 09:35:04] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 8: User-Agent: MxSipApp/5.0.16.99 MxSF/v3.2.1.1 (44) [Mar 19 09:35:04] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 9: (0) [Mar 19 09:35:04] --- (9 headers 0 lines) --- [Mar 19 09:35:04] DEBUG[30638]: chan_sip.c:14813 sipsock_read: Invalid SIP message - rejected , no callid, len 350 [Mar 19 09:35:04] <--- SIP read from 10.4.126.232:5060 ---> BYE sip:4321@10.4.119.245 SIP/2.0 Via: SIP/2.0/UDP 10.4.126.232;branch=z9hG4bKd50c04832 Content-Length: 0 To: sip:4321@10.4.119.245;tag=as3287914c From: Test1 ;tag=2e0ba312e07ed9f Call-ID: 437ca631f88d70553dbe5edc5ce7d949@10.4.119.245 CSeq: 1093933438 BYE Supported: timer Supported: replaces User-Agent: MxSipApp/5.0.16.99 MxSF/v3.2.1.1 <-------------> [Mar 19 09:35:04] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 0: BYE sip:4321@10.4.119.245 SIP/2.0 (33) [Mar 19 09:35:04] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 1: Via: SIP/2.0/UDP 10.4.126.232;branch=z9hG4bKd50c04832 (53) [Mar 19 09:35:04] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 2: Content-Length: 0 (17) [Mar 19 09:35:04] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 3: To: sip:4321@10.4.119.245;tag=as3287914c (40) [Mar 19 09:35:04] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 4: From: Test1 ;tag=2e0ba312e07ed9f (55) [Mar 19 09:35:04] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 5: Call-ID: 437ca631f88d70553dbe5edc5ce7d949@10.4.119.245 (54) [Mar 19 09:35:04] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 6: CSeq: 1093933438 BYE (20) [Mar 19 09:35:04] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 7: Supported: timer (16) [Mar 19 09:35:04] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 8: Supported: replaces (19) [Mar 19 09:35:04] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 9: User-Agent: MxSipApp/5.0.16.99 MxSF/v3.2.1.1 (44) [Mar 19 09:35:04] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 10: (0) [Mar 19 09:35:04] --- (10 headers 0 lines) --- [Mar 19 09:35:04] <--- Transmitting (no NAT) to 10.4.126.232:5060 ---> SIP/2.0 481 Call leg/transaction does not exist Via: SIP/2.0/UDP 10.4.126.232;branch=z9hG4bKd50c04832;received=10.4.126.232 From: Test1 ;tag=2e0ba312e07ed9f To: sip:4321@10.4.119.245;tag=as3287914c Call-ID: 437ca631f88d70553dbe5edc5ce7d949@10.4.119.245 CSeq: 1093933438 BYE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 <------------> [Mar 19 09:35:04] DEBUG[30638]: chan_sip.c:14813 sipsock_read: Invalid SIP message - rejected , no callid, len 373 [Mar 19 09:35:08] <--- SIP read from 10.4.126.232:5060 ---> SIP/2.0 500 Server Internal Error Call-ID: 437ca631f88d70553dbe5edc5ce7d949@10.4.119.245 CSeq: 104 INVITE From: sip:4321@10.4.119.245;tag=as3287914c To: Test1 ;tag=2e0ba312e07ed9f Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK1e2cf1f4 Content-Length: 0 Retry-After: 3 User-Agent: MxSipApp/5.0.16.99 MxSF/v3.2.1.1 <-------------> [Mar 19 09:35:08] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 0: SIP/2.0 500 Server Internal Error (33) [Mar 19 09:35:08] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 1: Call-ID: 437ca631f88d70553dbe5edc5ce7d949@10.4.119.245 (54) [Mar 19 09:35:08] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 2: CSeq: 104 INVITE (16) [Mar 19 09:35:08] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 3: From: sip:4321@10.4.119.245;tag=as3287914c (42) [Mar 19 09:35:08] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 4: To: Test1 ;tag=2e0ba312e07ed9f (53) [Mar 19 09:35:08] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 5: Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK1e2cf1f4 (57) [Mar 19 09:35:08] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 6: Content-Length: 0 (17) [Mar 19 09:35:08] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 7: Retry-After: 3 (14) [Mar 19 09:35:08] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 8: User-Agent: MxSipApp/5.0.16.99 MxSF/v3.2.1.1 (44) [Mar 19 09:35:08] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 9: (0) [Mar 19 09:35:08] --- (9 headers 0 lines) --- [Mar 19 09:35:08] DEBUG[30638]: chan_sip.c:14813 sipsock_read: Invalid SIP message - rejected , no callid, len 350 [Mar 19 09:35:10] DEBUG[30638]: chan_sip.c:4310 sip_alloc: Allocating new SIP dialog for (No Call-ID) - NOTIFY (No RTP) [Mar 19 09:35:10] Scheduling destruction of SIP dialog '5ae556fa0d6ce8465937211b5dc64e02@10.4.119.245' in 32000 ms (Method: NOTIFY) [Mar 19 09:35:10] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 0: NOTIFY sip:5678@10.4.123.235 SIP/2.0 (36) [Mar 19 09:35:10] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 1: Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK4d1e8572 (57) [Mar 19 09:35:10] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 2: From: "asterisk" ;tag=as1c1faf09 (59) [Mar 19 09:35:10] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 3: To: (27) [Mar 19 09:35:10] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 4: Contact: (36) [Mar 19 09:35:10] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 5: Call-ID: 5ae556fa0d6ce8465937211b5dc64e02@10.4.119.245 (54) [Mar 19 09:35:10] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 6: CSeq: 102 NOTIFY (16) [Mar 19 09:35:10] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 7: User-Agent: Asterisk PBX (24) [Mar 19 09:35:10] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 8: Max-Forwards: 70 (16) [Mar 19 09:35:10] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 9: Event: message-summary (22) [Mar 19 09:35:10] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 10: Content-Type: application/simple-message-summary (48) [Mar 19 09:35:10] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 11: Content-Length: 92 (18) [Mar 19 09:35:10] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 12: (0) [Mar 19 09:35:10] DEBUG[30638]: chan_sip.c:4605 parse_request: Line: Messages-Waiting: no (20) [Mar 19 09:35:10] DEBUG[30638]: chan_sip.c:4605 parse_request: Line: Message-Account: sip:asterisk@10.4.119.245 (42) [Mar 19 09:35:10] DEBUG[30638]: chan_sip.c:4605 parse_request: Line: Voice-Message: 0/0 (0/0) (24) [Mar 19 09:35:10] Reliably Transmitting (no NAT) to 10.4.123.235:5060: NOTIFY sip:5678@10.4.123.235 SIP/2.0 Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK4d1e8572 From: "asterisk" ;tag=as1c1faf09 To: Contact: Call-ID: 5ae556fa0d6ce8465937211b5dc64e02@10.4.119.245 CSeq: 102 NOTIFY User-Agent: Asterisk PBX Max-Forwards: 70 Event: message-summary Content-Type: application/simple-message-summary Content-Length: 92 Messages-Waiting: no Message-Account: sip:asterisk@10.4.119.245 Voice-Message: 0/0 (0/0) --- [Mar 19 09:35:10] DEBUG[30638]: chan_sip.c:1975 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #46 [Mar 19 09:35:10] DEBUG[30638]: chan_sip.c:4310 sip_alloc: Allocating new SIP dialog for (No Call-ID) - NOTIFY (No RTP) [Mar 19 09:35:10] Scheduling destruction of SIP dialog '78022b9a3e3c125d303840085572f701@10.4.119.245' in 32000 ms (Method: NOTIFY) [Mar 19 09:35:10] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 0: NOTIFY sip:1234@10.4.126.232 SIP/2.0 (36) [Mar 19 09:35:10] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 1: Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK2630c1c8 (57) [Mar 19 09:35:10] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 2: From: "asterisk" ;tag=as1ead93f3 (59) [Mar 19 09:35:10] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 3: To: (27) [Mar 19 09:35:10] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 4: Contact: (36) [Mar 19 09:35:10] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 5: Call-ID: 78022b9a3e3c125d303840085572f701@10.4.119.245 (54) [Mar 19 09:35:10] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 6: CSeq: 102 NOTIFY (16) [Mar 19 09:35:10] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 7: User-Agent: Asterisk PBX (24) [Mar 19 09:35:10] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 8: Max-Forwards: 70 (16) [Mar 19 09:35:10] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 9: Event: message-summary (22) [Mar 19 09:35:10] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 10: Content-Type: application/simple-message-summary (48) [Mar 19 09:35:10] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 11: Content-Length: 92 (18) [Mar 19 09:35:10] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 12: (0) [Mar 19 09:35:10] DEBUG[30638]: chan_sip.c:4605 parse_request: Line: Messages-Waiting: no (20) [Mar 19 09:35:10] DEBUG[30638]: chan_sip.c:4605 parse_request: Line: Message-Account: sip:asterisk@10.4.119.245 (42) [Mar 19 09:35:10] DEBUG[30638]: chan_sip.c:4605 parse_request: Line: Voice-Message: 0/0 (0/0) (24) [Mar 19 09:35:10] Reliably Transmitting (no NAT) to 10.4.126.232:5060: NOTIFY sip:1234@10.4.126.232 SIP/2.0 Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK2630c1c8 From: "asterisk" ;tag=as1ead93f3 To: Contact: Call-ID: 78022b9a3e3c125d303840085572f701@10.4.119.245 CSeq: 102 NOTIFY User-Agent: Asterisk PBX Max-Forwards: 70 Event: message-summary Content-Type: application/simple-message-summary Content-Length: 92 Messages-Waiting: no Message-Account: sip:asterisk@10.4.119.245 Voice-Message: 0/0 (0/0) --- [Mar 19 09:35:10] DEBUG[30638]: chan_sip.c:1975 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #48 [Mar 19 09:35:10] <--- SIP read from 10.4.123.235:5060 ---> SIP/2.0 200 OK Call-ID: 5ae556fa0d6ce8465937211b5dc64e02@10.4.119.245 CSeq: 102 NOTIFY From: "asterisk" ;tag=as1c1faf09 To: ;tag=183fac235d0603a Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK4d1e8572 Content-Length: 0 User-Agent: MxSipApp/5.0.16.96 MxSF/v3.2.1.1 <-------------> [Mar 19 09:35:10] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 0: SIP/2.0 200 OK (14) [Mar 19 09:35:10] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 1: Call-ID: 5ae556fa0d6ce8465937211b5dc64e02@10.4.119.245 (54) [Mar 19 09:35:10] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 2: CSeq: 102 NOTIFY (16) [Mar 19 09:35:10] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 3: From: "asterisk" ;tag=as1c1faf09 (59) [Mar 19 09:35:10] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 4: To: ;tag=183fac235d0603a (47) [Mar 19 09:35:10] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 5: Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK4d1e8572 (57) [Mar 19 09:35:10] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 6: Content-Length: 0 (17) [Mar 19 09:35:10] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 7: User-Agent: MxSipApp/5.0.16.96 MxSF/v3.2.1.1 (44) [Mar 19 09:35:10] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 8: (0) [Mar 19 09:35:10] --- (8 headers 0 lines) --- [Mar 19 09:35:10] DEBUG[30638]: chan_sip.c:2079 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #46 [Mar 19 09:35:10] DEBUG[30638]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '5ae556fa0d6ce8465937211b5dc64e02@10.4.119.245' of Request 102: Match Not Found [Mar 19 09:35:10] Really destroying SIP dialog '5ae556fa0d6ce8465937211b5dc64e02@10.4.119.245' Method: NOTIFY [Mar 19 09:35:10] <--- SIP read from 10.4.126.232:5060 ---> SIP/2.0 200 OK Call-ID: 78022b9a3e3c125d303840085572f701@10.4.119.245 CSeq: 102 NOTIFY From: "asterisk" ;tag=as1ead93f3 To: ;tag=5e7443d69756bbb Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK2630c1c8 Content-Length: 0 User-Agent: MxSipApp/5.0.16.99 MxSF/v3.2.1.1 <-------------> [Mar 19 09:35:10] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 0: SIP/2.0 200 OK (14) [Mar 19 09:35:10] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 1: Call-ID: 78022b9a3e3c125d303840085572f701@10.4.119.245 (54) [Mar 19 09:35:10] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 2: CSeq: 102 NOTIFY (16) [Mar 19 09:35:10] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 3: From: "asterisk" ;tag=as1ead93f3 (59) [Mar 19 09:35:10] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 4: To: ;tag=5e7443d69756bbb (47) [Mar 19 09:35:10] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 5: Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK2630c1c8 (57) [Mar 19 09:35:10] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 6: Content-Length: 0 (17) [Mar 19 09:35:10] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 7: User-Agent: MxSipApp/5.0.16.99 MxSF/v3.2.1.1 (44) [Mar 19 09:35:10] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 8: (0) [Mar 19 09:35:10] --- (8 headers 0 lines) --- [Mar 19 09:35:10] DEBUG[30638]: chan_sip.c:2079 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #48 [Mar 19 09:35:10] DEBUG[30638]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '78022b9a3e3c125d303840085572f701@10.4.119.245' of Request 102: Match Not Found [Mar 19 09:35:10] Really destroying SIP dialog '78022b9a3e3c125d303840085572f701@10.4.119.245' Method: NOTIFY [Mar 19 09:35:12] <--- SIP read from 10.4.126.232:5060 ---> SIP/2.0 500 Server Internal Error Call-ID: 437ca631f88d70553dbe5edc5ce7d949@10.4.119.245 CSeq: 104 INVITE From: sip:4321@10.4.119.245;tag=as3287914c To: Test1 ;tag=2e0ba312e07ed9f Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK1e2cf1f4 Content-Length: 0 Retry-After: 3 User-Agent: MxSipApp/5.0.16.99 MxSF/v3.2.1.1 <-------------> [Mar 19 09:35:12] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 0: SIP/2.0 500 Server Internal Error (33) [Mar 19 09:35:12] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 1: Call-ID: 437ca631f88d70553dbe5edc5ce7d949@10.4.119.245 (54) [Mar 19 09:35:12] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 2: CSeq: 104 INVITE (16) [Mar 19 09:35:12] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 3: From: sip:4321@10.4.119.245;tag=as3287914c (42) [Mar 19 09:35:12] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 4: To: Test1 ;tag=2e0ba312e07ed9f (53) [Mar 19 09:35:12] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 5: Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK1e2cf1f4 (57) [Mar 19 09:35:12] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 6: Content-Length: 0 (17) [Mar 19 09:35:12] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 7: Retry-After: 3 (14) [Mar 19 09:35:12] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 8: User-Agent: MxSipApp/5.0.16.99 MxSF/v3.2.1.1 (44) [Mar 19 09:35:12] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 9: (0) [Mar 19 09:35:12] --- (9 headers 0 lines) --- [Mar 19 09:35:12] DEBUG[30638]: chan_sip.c:14813 sipsock_read: Invalid SIP message - rejected , no callid, len 350 [Mar 19 09:35:13] <--- SIP read from 10.4.127.230:5060 ---> REGISTER sip:10.4.119.245 SIP/2.0 Via: SIP/2.0/UDP 10.4.127.230;branch=z9hG4bKe8875c490 Content-Length: 0 To: Test2 From: Test2 ;tag=2e630affdc2303e Call-ID: 80b03bc0fb36d588533571055b589d5a@10.4.119.245 CSeq: 1255483745 REGISTER Contact: Test2 User-Agent: MxSipApp/5.0.15.88 MxSF/v3.2.1.1 <-------------> [Mar 19 09:35:13] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 0: REGISTER sip:10.4.119.245 SIP/2.0 (33) [Mar 19 09:35:13] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 1: Via: SIP/2.0/UDP 10.4.127.230;branch=z9hG4bKe8875c490 (53) [Mar 19 09:35:13] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 2: Content-Length: 0 (17) [Mar 19 09:35:13] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 3: To: Test2 (33) [Mar 19 09:35:13] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 4: From: Test2 ;tag=2e630affdc2303e (55) [Mar 19 09:35:13] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 5: Call-ID: 80b03bc0fb36d588533571055b589d5a@10.4.119.245 (54) [Mar 19 09:35:13] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 6: CSeq: 1255483745 REGISTER (25) [Mar 19 09:35:13] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 7: Contact: Test2 (38) [Mar 19 09:35:13] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 8: User-Agent: MxSipApp/5.0.15.88 MxSF/v3.2.1.1 (44) [Mar 19 09:35:13] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 9: (0) [Mar 19 09:35:13] --- (9 headers 0 lines) --- [Mar 19 09:35:13] DEBUG[30638]: chan_sip.c:4310 sip_alloc: Allocating new SIP dialog for 80b03bc0fb36d588533571055b589d5a@10.4.119.245 - REGISTER (No RTP) [Mar 19 09:35:13] DEBUG[30638]: chan_sip.c:14629 handle_request: **** Received REGISTER (2) - Command in SIP REGISTER [Mar 19 09:35:13] Using latest REGISTER request as basis request [Mar 19 09:35:13] Sending to 10.4.127.230 : 5060 (no NAT) [Mar 19 09:35:13] <--- Transmitting (no NAT) to 10.4.127.230:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.4.127.230;branch=z9hG4bKe8875c490;received=10.4.127.230 From: Test2 ;tag=2e630affdc2303e To: Test2 Call-ID: 80b03bc0fb36d588533571055b589d5a@10.4.119.245 CSeq: 1255483745 REGISTER User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Mar 19 09:35:13] <--- Transmitting (no NAT) to 10.4.127.230:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.4.127.230;branch=z9hG4bKe8875c490;received=10.4.127.230 From: Test2 ;tag=2e630affdc2303e To: Test2 ;tag=as485f87fb Call-ID: 80b03bc0fb36d588533571055b589d5a@10.4.119.245 CSeq: 1255483745 REGISTER User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Expires: 120 Contact: ;expires=120 Date: Mon, 19 Mar 2007 13:35:13 GMT Content-Length: 0 <------------> [Mar 19 09:35:13] DEBUG[30638]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/4321 [Mar 19 09:35:13] Scheduling destruction of SIP dialog '80b03bc0fb36d588533571055b589d5a@10.4.119.245' in 32000 ms (Method: REGISTER) [Mar 19 09:35:13] DEBUG[30628]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 4321 [Mar 19 09:35:13] DEBUG[30628]: chan_sip.c:15240 sip_devicestate: Checking device state for peer 4321 [Mar 19 09:35:13] DEBUG[30628]: devicestate.c:287 do_state_change: Changing state for SIP/4321 - state 1 (Not in use) [Mar 19 09:35:13] DEBUG[30665]: app_queue.c:546 changethread: Device 'SIP/4321' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Mar 19 09:35:16] <--- SIP read from 10.4.126.232:5060 ---> SIP/2.0 500 Server Internal Error Call-ID: 437ca631f88d70553dbe5edc5ce7d949@10.4.119.245 CSeq: 104 INVITE From: sip:4321@10.4.119.245;tag=as3287914c To: Test1 ;tag=2e0ba312e07ed9f Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK1e2cf1f4 Content-Length: 0 Retry-After: 3 User-Agent: MxSipApp/5.0.16.99 MxSF/v3.2.1.1 <-------------> [Mar 19 09:35:16] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 0: SIP/2.0 500 Server Internal Error (33) [Mar 19 09:35:16] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 1: Call-ID: 437ca631f88d70553dbe5edc5ce7d949@10.4.119.245 (54) [Mar 19 09:35:16] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 2: CSeq: 104 INVITE (16) [Mar 19 09:35:16] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 3: From: sip:4321@10.4.119.245;tag=as3287914c (42) [Mar 19 09:35:16] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 4: To: Test1 ;tag=2e0ba312e07ed9f (53) [Mar 19 09:35:16] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 5: Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK1e2cf1f4 (57) [Mar 19 09:35:16] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 6: Content-Length: 0 (17) [Mar 19 09:35:16] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 7: Retry-After: 3 (14) [Mar 19 09:35:16] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 8: User-Agent: MxSipApp/5.0.16.99 MxSF/v3.2.1.1 (44) [Mar 19 09:35:16] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 9: (0) [Mar 19 09:35:16] --- (9 headers 0 lines) --- [Mar 19 09:35:16] DEBUG[30638]: chan_sip.c:14813 sipsock_read: Invalid SIP message - rejected , no callid, len 350 [Mar 19 09:35:20] <--- SIP read from 10.4.126.232:5060 ---> SIP/2.0 500 Server Internal Error Call-ID: 437ca631f88d70553dbe5edc5ce7d949@10.4.119.245 CSeq: 104 INVITE From: sip:4321@10.4.119.245;tag=as3287914c To: Test1 ;tag=2e0ba312e07ed9f Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK1e2cf1f4 Content-Length: 0 Retry-After: 3 User-Agent: MxSipApp/5.0.16.99 MxSF/v3.2.1.1 <-------------> [Mar 19 09:35:20] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 0: SIP/2.0 500 Server Internal Error (33) [Mar 19 09:35:20] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 1: Call-ID: 437ca631f88d70553dbe5edc5ce7d949@10.4.119.245 (54) [Mar 19 09:35:20] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 2: CSeq: 104 INVITE (16) [Mar 19 09:35:20] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 3: From: sip:4321@10.4.119.245;tag=as3287914c (42) [Mar 19 09:35:20] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 4: To: Test1 ;tag=2e0ba312e07ed9f (53) [Mar 19 09:35:20] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 5: Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK1e2cf1f4 (57) [Mar 19 09:35:20] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 6: Content-Length: 0 (17) [Mar 19 09:35:20] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 7: Retry-After: 3 (14) [Mar 19 09:35:20] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 8: User-Agent: MxSipApp/5.0.16.99 MxSF/v3.2.1.1 (44) [Mar 19 09:35:20] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 9: (0) [Mar 19 09:35:20] --- (9 headers 0 lines) --- [Mar 19 09:35:20] DEBUG[30638]: chan_sip.c:14813 sipsock_read: Invalid SIP message - rejected , no callid, len 350 [Mar 19 09:35:21] DEBUG[30638]: chan_sip.c:4310 sip_alloc: Allocating new SIP dialog for (No Call-ID) - NOTIFY (No RTP) [Mar 19 09:35:21] Scheduling destruction of SIP dialog '7af31c7b39bf0c106ad25ed448ce55f3@10.4.119.245' in 32000 ms (Method: NOTIFY) [Mar 19 09:35:21] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 0: NOTIFY sip:4321@10.4.127.230 SIP/2.0 (36) [Mar 19 09:35:21] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 1: Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK222998fd (57) [Mar 19 09:35:21] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 2: From: "asterisk" ;tag=as5d20261c (59) [Mar 19 09:35:21] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 3: To: (27) [Mar 19 09:35:21] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 4: Contact: (36) [Mar 19 09:35:21] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 5: Call-ID: 7af31c7b39bf0c106ad25ed448ce55f3@10.4.119.245 (54) [Mar 19 09:35:21] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 6: CSeq: 102 NOTIFY (16) [Mar 19 09:35:21] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 7: User-Agent: Asterisk PBX (24) [Mar 19 09:35:21] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 8: Max-Forwards: 70 (16) [Mar 19 09:35:21] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 9: Event: message-summary (22) [Mar 19 09:35:21] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 10: Content-Type: application/simple-message-summary (48) [Mar 19 09:35:21] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 11: Content-Length: 92 (18) [Mar 19 09:35:21] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 12: (0) [Mar 19 09:35:21] DEBUG[30638]: chan_sip.c:4605 parse_request: Line: Messages-Waiting: no (20) [Mar 19 09:35:21] DEBUG[30638]: chan_sip.c:4605 parse_request: Line: Message-Account: sip:asterisk@10.4.119.245 (42) [Mar 19 09:35:21] DEBUG[30638]: chan_sip.c:4605 parse_request: Line: Voice-Message: 0/0 (0/0) (24) [Mar 19 09:35:21] Reliably Transmitting (no NAT) to 10.4.127.230:5060: NOTIFY sip:4321@10.4.127.230 SIP/2.0 Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK222998fd From: "asterisk" ;tag=as5d20261c To: Contact: Call-ID: 7af31c7b39bf0c106ad25ed448ce55f3@10.4.119.245 CSeq: 102 NOTIFY User-Agent: Asterisk PBX Max-Forwards: 70 Event: message-summary Content-Type: application/simple-message-summary Content-Length: 92 Messages-Waiting: no Message-Account: sip:asterisk@10.4.119.245 Voice-Message: 0/0 (0/0) --- [Mar 19 09:35:21] DEBUG[30638]: chan_sip.c:1975 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #52 [Mar 19 09:35:21] <--- SIP read from 10.4.127.230:5060 ---> SIP/2.0 200 OK Call-ID: 7af31c7b39bf0c106ad25ed448ce55f3@10.4.119.245 CSeq: 102 NOTIFY From: "asterisk" ;tag=as5d20261c To: ;tag=7b34b79a0c86412 Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK222998fd Content-Length: 0 User-Agent: MxSipApp/5.0.15.88 MxSF/v3.2.1.1 <-------------> [Mar 19 09:35:21] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 0: SIP/2.0 200 OK (14) [Mar 19 09:35:21] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 1: Call-ID: 7af31c7b39bf0c106ad25ed448ce55f3@10.4.119.245 (54) [Mar 19 09:35:21] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 2: CSeq: 102 NOTIFY (16) [Mar 19 09:35:21] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 3: From: "asterisk" ;tag=as5d20261c (59) [Mar 19 09:35:21] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 4: To: ;tag=7b34b79a0c86412 (47) [Mar 19 09:35:21] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 5: Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK222998fd (57) [Mar 19 09:35:21] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 6: Content-Length: 0 (17) [Mar 19 09:35:21] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 7: User-Agent: MxSipApp/5.0.15.88 MxSF/v3.2.1.1 (44) [Mar 19 09:35:21] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 8: (0) [Mar 19 09:35:21] --- (8 headers 0 lines) --- [Mar 19 09:35:21] DEBUG[30638]: chan_sip.c:2079 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #52 [Mar 19 09:35:21] DEBUG[30638]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '7af31c7b39bf0c106ad25ed448ce55f3@10.4.119.245' of Request 102: Match Not Found [Mar 19 09:35:21] Really destroying SIP dialog '7af31c7b39bf0c106ad25ed448ce55f3@10.4.119.245' Method: NOTIFY [Mar 19 09:35:24] <--- SIP read from 10.4.126.232:5060 ---> SIP/2.0 500 Server Internal Error Call-ID: 437ca631f88d70553dbe5edc5ce7d949@10.4.119.245 CSeq: 104 INVITE From: sip:4321@10.4.119.245;tag=as3287914c To: Test1 ;tag=2e0ba312e07ed9f Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK1e2cf1f4 Content-Length: 0 Retry-After: 3 User-Agent: MxSipApp/5.0.16.99 MxSF/v3.2.1.1 <-------------> [Mar 19 09:35:24] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 0: SIP/2.0 500 Server Internal Error (33) [Mar 19 09:35:24] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 1: Call-ID: 437ca631f88d70553dbe5edc5ce7d949@10.4.119.245 (54) [Mar 19 09:35:24] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 2: CSeq: 104 INVITE (16) [Mar 19 09:35:24] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 3: From: sip:4321@10.4.119.245;tag=as3287914c (42) [Mar 19 09:35:24] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 4: To: Test1 ;tag=2e0ba312e07ed9f (53) [Mar 19 09:35:24] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 5: Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK1e2cf1f4 (57) [Mar 19 09:35:24] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 6: Content-Length: 0 (17) [Mar 19 09:35:24] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 7: Retry-After: 3 (14) [Mar 19 09:35:24] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 8: User-Agent: MxSipApp/5.0.16.99 MxSF/v3.2.1.1 (44) [Mar 19 09:35:24] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 9: (0) [Mar 19 09:35:24] --- (9 headers 0 lines) --- [Mar 19 09:35:24] DEBUG[30638]: chan_sip.c:14813 sipsock_read: Invalid SIP message - rejected , no callid, len 350 [Mar 19 09:35:28] <--- SIP read from 10.4.126.232:5060 ---> SIP/2.0 500 Server Internal Error Call-ID: 437ca631f88d70553dbe5edc5ce7d949@10.4.119.245 CSeq: 104 INVITE From: sip:4321@10.4.119.245;tag=as3287914c To: Test1 ;tag=2e0ba312e07ed9f Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK1e2cf1f4 Content-Length: 0 Retry-After: 3 User-Agent: MxSipApp/5.0.16.99 MxSF/v3.2.1.1 <-------------> [Mar 19 09:35:28] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 0: SIP/2.0 500 Server Internal Error (33) [Mar 19 09:35:28] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 1: Call-ID: 437ca631f88d70553dbe5edc5ce7d949@10.4.119.245 (54) [Mar 19 09:35:28] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 2: CSeq: 104 INVITE (16) [Mar 19 09:35:28] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 3: From: sip:4321@10.4.119.245;tag=as3287914c (42) [Mar 19 09:35:28] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 4: To: Test1 ;tag=2e0ba312e07ed9f (53) [Mar 19 09:35:28] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 5: Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK1e2cf1f4 (57) [Mar 19 09:35:28] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 6: Content-Length: 0 (17) [Mar 19 09:35:28] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 7: Retry-After: 3 (14) [Mar 19 09:35:28] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 8: User-Agent: MxSipApp/5.0.16.99 MxSF/v3.2.1.1 (44) [Mar 19 09:35:28] DEBUG[30638]: chan_sip.c:4573 parse_request: Header 9: (0) [Mar 19 09:35:28] --- (9 headers 0 lines) --- [Mar 19 09:35:28] DEBUG[30638]: chan_sip.c:14813 sipsock_read: Invalid SIP message - rejected , no callid, len 350 [Mar 19 09:35:32] DEBUG[30638]: chan_sip.c:2010 __sip_autodestruct: Auto destroying SIP dialog 'a86b58442719b96c033029da1651b6fb@10.4.119.245' [Mar 19 09:35:32] DEBUG[30638]: chan_sip.c:3109 sip_destroy: Destroying SIP dialog a86b58442719b96c033029da1651b6fb@10.4.119.245 [Mar 19 09:35:32] Really destroying SIP dialog 'a86b58442719b96c033029da1651b6fb@10.4.119.245' Method: REGISTER [Mar 19 09:35:33] DEBUG[30638]: chan_sip.c:2010 __sip_autodestruct: Auto destroying SIP dialog 'ca51fef242c670e33e7ef124f61fda18@10.4.119.245' [Mar 19 09:35:33] DEBUG[30638]: chan_sip.c:3109 sip_destroy: Destroying SIP dialog ca51fef242c670e33e7ef124f61fda18@10.4.119.245 [Mar 19 09:35:33] Really destroying SIP dialog 'ca51fef242c670e33e7ef124f61fda18@10.4.119.245' Method: REGISTER *CLI> [Mar 19 09:35:45] DEBUG[30638]: chan_sip.c:2010 __sip_autodestruct: Auto destroying SIP dialog '80b03bc0fb36d588533571055b589d5a@10.4.119.245' [Mar 19 09:35:45] DEBUG[30638]: chan_sip.c:3109 sip_destroy: Destroying SIP dialog 80b03bc0fb36d588533571055b589d5a@10.4.119.245 [Mar 19 09:35:45] Really destroying SIP dialog '80b03bc0fb36d588533571055b589d5a@10.4.119.245' Method: REGISTER