[Aug 27 08:10:26] Asterisk SVN-branch-1.4-r140115, Copyright (C) 1999 - 2008 Digium, Inc. and others. [Aug 27 08:10:26] Created by Mark Spencer [Aug 27 08:10:26] Asterisk comes with ABSOLUTELY NO WARRANTY; type 'core show warranty' for details. [Aug 27 08:10:26] This is free software, with components licensed under the GNU General Public [Aug 27 08:10:26] License version 2 and other licenses; you are welcome to redistribute it under [Aug 27 08:10:26] certain conditions. Type 'core show license' for details. [Aug 27 08:10:26] ========================================================================= [Aug 27 08:10:27] Asterisk Ready. SIP Debugging enabled The 'sip debug' command is deprecated and will be removed in a future release. Please use 'sip set debug' instead. *CLI> [Aug 27 08:10:30] DEBUG[17493]: chan_sip.c:4577 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Aug 27 08:10:30] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 0: OPTIONS sip:4567@10.4.119.185 SIP/2.0 (37) [Aug 27 08:10:30] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 1: Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK68c5b34d;rport (63) [Aug 27 08:10:30] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 2: From: "asterisk" ;tag=as686541d2 (59) [Aug 27 08:10:30] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 3: To: (27) [Aug 27 08:10:30] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 4: Contact: (36) [Aug 27 08:10:30] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 5: Call-ID: 52861e2019685da32ea93f3606c27d91@10.4.119.245 (54) [Aug 27 08:10:30] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 6: CSeq: 102 OPTIONS (17) [Aug 27 08:10:30] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 7: User-Agent: Asterisk PBX (24) [Aug 27 08:10:30] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 8: Max-Forwards: 70 (16) [Aug 27 08:10:30] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 9: Date: Wed, 27 Aug 2008 12:10:30 GMT (35) [Aug 27 08:10:30] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Aug 27 08:10:30] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 11: Supported: replaces (19) [Aug 27 08:10:30] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 12: Content-Length: 0 (17) [Aug 27 08:10:30] Reliably Transmitting (no NAT) to 10.4.119.185:5060: OPTIONS sip:4567@10.4.119.185 SIP/2.0 Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK68c5b34d;rport From: "asterisk" ;tag=as686541d2 To: Contact: Call-ID: 52861e2019685da32ea93f3606c27d91@10.4.119.245 CSeq: 102 OPTIONS User-Agent: Asterisk PBX Max-Forwards: 70 Date: Wed, 27 Aug 2008 12:10:30 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 --- [Aug 27 08:10:30] DEBUG[17493]: chan_sip.c:2051 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #-1 [Aug 27 08:10:30] <--- SIP read from 10.4.119.185:5060 ---> SIP/2.0 405 Method Not Allowed Call-ID: 52861e2019685da32ea93f3606c27d91@10.4.119.245 CSeq: 102 OPTIONS From: "asterisk" ;tag=as686541d2 To: ;tag=9ea5cae672c8c2c Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK68c5b34d;rport Content-Length: 0 Allow: INVITE, ACK, BYE, CANCEL, REFER, NOTIFY User-Agent: MxSipApp/5.0.23.153 MxSF/v3.2.2.4 <-------------> [Aug 27 08:10:30] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 0: SIP/2.0 405 Method Not Allowed (30) [Aug 27 08:10:30] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 1: Call-ID: 52861e2019685da32ea93f3606c27d91@10.4.119.245 (54) [Aug 27 08:10:30] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 2: CSeq: 102 OPTIONS (17) [Aug 27 08:10:30] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 3: From: "asterisk" ;tag=as686541d2 (59) [Aug 27 08:10:30] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 4: To: ;tag=9ea5cae672c8c2c (47) [Aug 27 08:10:30] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 5: Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK68c5b34d;rport (63) [Aug 27 08:10:30] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 6: Content-Length: 0 (17) [Aug 27 08:10:30] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 7: Allow: INVITE, ACK, BYE, CANCEL, REFER, NOTIFY (46) [Aug 27 08:10:30] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 8: User-Agent: MxSipApp/5.0.23.153 MxSF/v3.2.2.4 (45) [Aug 27 08:10:30] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 9: (0) [Aug 27 08:10:30] --- (9 headers 0 lines) --- [Aug 27 08:10:30] DEBUG[17493]: chan_sip.c:4630 find_call: = Found Their Call ID: 52861e2019685da32ea93f3606c27d91@10.4.119.245 Their Tag Our tag: as686541d2 [Aug 27 08:10:30] DEBUG[17493]: chan_sip.c:2174 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #55 [Aug 27 08:10:30] DEBUG[17493]: chan_sip.c:2200 __sip_ack: Stopping retransmission on '52861e2019685da32ea93f3606c27d91@10.4.119.245' of Request 102: Match Found [Aug 27 08:10:30] NOTICE[17493]: chan_sip.c:12703 handle_response_peerpoke: Peer '4567' is now Reachable. (30ms / 2000ms) [Aug 27 08:10:30] DEBUG[17493]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/4567 [Aug 27 08:10:30] DEBUG[17483]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 4567 [Aug 27 08:10:30] DEBUG[17483]: chan_sip.c:16345 sip_devicestate: Checking device state for peer 4567 [Aug 27 08:10:30] DEBUG[17483]: devicestate.c:287 do_state_change: Changing state for SIP/4567 - state 1 (Not in use) [Aug 27 08:10:30] Really destroying SIP dialog '52861e2019685da32ea93f3606c27d91@10.4.119.245' Method: OPTIONS [Aug 27 08:10:30] DEBUG[17492]: app_queue.c:661 handle_statechange: Device 'SIP/4567' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Aug 27 08:10:30] DEBUG[17493]: chan_sip.c:4577 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Aug 27 08:10:30] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 0: OPTIONS sip:3456@10.4.119.185 SIP/2.0 (37) [Aug 27 08:10:30] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 1: Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK7a441dd8;rport (63) [Aug 27 08:10:30] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 2: From: "asterisk" ;tag=as3b864ca7 (59) [Aug 27 08:10:30] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 3: To: (27) [Aug 27 08:10:30] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 4: Contact: (36) [Aug 27 08:10:30] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 5: Call-ID: 040392322fc576964904c2830de13244@10.4.119.245 (54) [Aug 27 08:10:30] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 6: CSeq: 102 OPTIONS (17) [Aug 27 08:10:30] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 7: User-Agent: Asterisk PBX (24) [Aug 27 08:10:30] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 8: Max-Forwards: 70 (16) [Aug 27 08:10:30] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 9: Date: Wed, 27 Aug 2008 12:10:30 GMT (35) [Aug 27 08:10:30] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Aug 27 08:10:30] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 11: Supported: replaces (19) [Aug 27 08:10:30] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 12: Content-Length: 0 (17) [Aug 27 08:10:30] Reliably Transmitting (no NAT) to 10.4.119.185:5060: OPTIONS sip:3456@10.4.119.185 SIP/2.0 Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK7a441dd8;rport From: "asterisk" ;tag=as3b864ca7 To: Contact: Call-ID: 040392322fc576964904c2830de13244@10.4.119.245 CSeq: 102 OPTIONS User-Agent: Asterisk PBX Max-Forwards: 70 Date: Wed, 27 Aug 2008 12:10:30 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 --- [Aug 27 08:10:30] DEBUG[17493]: chan_sip.c:2051 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #-1 [Aug 27 08:10:30] <--- SIP read from 10.4.119.185:5060 ---> SIP/2.0 405 Method Not Allowed Call-ID: 040392322fc576964904c2830de13244@10.4.119.245 CSeq: 102 OPTIONS From: "asterisk" ;tag=as3b864ca7 To: ;tag=b76e8ce300e104a Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK7a441dd8;rport Content-Length: 0 Allow: INVITE, ACK, BYE, CANCEL, REFER, NOTIFY User-Agent: MxSipApp/5.0.23.153 MxSF/v3.2.2.4 <-------------> [Aug 27 08:10:30] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 0: SIP/2.0 405 Method Not Allowed (30) [Aug 27 08:10:30] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 1: Call-ID: 040392322fc576964904c2830de13244@10.4.119.245 (54) [Aug 27 08:10:30] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 2: CSeq: 102 OPTIONS (17) [Aug 27 08:10:30] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 3: From: "asterisk" ;tag=as3b864ca7 (59) [Aug 27 08:10:30] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 4: To: ;tag=b76e8ce300e104a (47) [Aug 27 08:10:30] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 5: Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK7a441dd8;rport (63) [Aug 27 08:10:30] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 6: Content-Length: 0 (17) [Aug 27 08:10:30] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 7: Allow: INVITE, ACK, BYE, CANCEL, REFER, NOTIFY (46) [Aug 27 08:10:30] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 8: User-Agent: MxSipApp/5.0.23.153 MxSF/v3.2.2.4 (45) [Aug 27 08:10:30] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 9: (0) [Aug 27 08:10:30] --- (9 headers 0 lines) --- [Aug 27 08:10:30] DEBUG[17493]: chan_sip.c:4630 find_call: = Found Their Call ID: 040392322fc576964904c2830de13244@10.4.119.245 Their Tag Our tag: as3b864ca7 [Aug 27 08:10:30] DEBUG[17493]: chan_sip.c:2174 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #58 [Aug 27 08:10:30] DEBUG[17493]: chan_sip.c:2200 __sip_ack: Stopping retransmission on '040392322fc576964904c2830de13244@10.4.119.245' of Request 102: Match Found [Aug 27 08:10:30] NOTICE[17493]: chan_sip.c:12703 handle_response_peerpoke: Peer '3456' is now Reachable. (31ms / 2000ms) [Aug 27 08:10:30] DEBUG[17493]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/3456 [Aug 27 08:10:30] DEBUG[17483]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 3456 [Aug 27 08:10:30] DEBUG[17483]: chan_sip.c:16345 sip_devicestate: Checking device state for peer 3456 [Aug 27 08:10:30] DEBUG[17483]: devicestate.c:287 do_state_change: Changing state for SIP/3456 - state 1 (Not in use) [Aug 27 08:10:30] DEBUG[17492]: app_queue.c:661 handle_statechange: Device 'SIP/3456' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Aug 27 08:10:30] Really destroying SIP dialog '040392322fc576964904c2830de13244@10.4.119.245' Method: OPTIONS [Aug 27 08:10:42] <--- SIP read from 10.4.119.185:5060 ---> INVITE sip:4567@10.4.119.245 SIP/2.0 Via: SIP/2.0/UDP 10.4.119.185;branch=z9hG4bKdece8b233 Content-Length: 243 To: sip:4567@10.4.119.245 From: sip:3456@10.4.119.245;tag=675a4ef80a8f1ed Call-ID: c2a0ecd08c201f6fc5d89eff8dc7ecb1@10.4.119.245 CSeq: 188001316 INVITE Supported: timer Min-SE: 1800 Session-Expires: 3600 Allow: INVITE, ACK, BYE, CANCEL, REFER, NOTIFY Content-Type: application/sdp Contact: sip:3456@10.4.119.185 Supported: replaces User-Agent: MxSipApp/5.0.23.153 MxSF/v3.2.2.4 v=0 o=MxSIP 153769626663182367 2020175608213136251 IN IP4 10.4.119.185 s=- c=IN IP4 10.4.119.185 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 <-------------> [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 0: INVITE sip:4567@10.4.119.245 SIP/2.0 (36) [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 1: Via: SIP/2.0/UDP 10.4.119.185;branch=z9hG4bKdece8b233 (53) [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 2: Content-Length: 243 (19) [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 3: To: sip:4567@10.4.119.245 (25) [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 4: From: sip:3456@10.4.119.245;tag=675a4ef80a8f1ed (47) [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 5: Call-ID: c2a0ecd08c201f6fc5d89eff8dc7ecb1@10.4.119.245 (54) [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 6: CSeq: 188001316 INVITE (22) [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 7: Supported: timer (16) [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 8: Min-SE: 1800 (12) [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 9: Session-Expires: 3600 (21) [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 10: Allow: INVITE, ACK, BYE, CANCEL, REFER, NOTIFY (46) [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 11: Content-Type: application/sdp (29) [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 12: Contact: sip:3456@10.4.119.185 (30) [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 13: Supported: replaces (19) [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 14: User-Agent: MxSipApp/5.0.23.153 MxSF/v3.2.2.4 (45) [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 15: (0) [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4872 parse_request: Line: v=0 (3) [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4872 parse_request: Line: o=MxSIP 153769626663182367 2020175608213136251 IN IP4 10.4.119.185 (66) [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4872 parse_request: Line: s=- (3) [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4872 parse_request: Line: c=IN IP4 10.4.119.185 (21) [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4872 parse_request: Line: t=0 0 (5) [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4872 parse_request: Line: a=sendrecv (10) [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4872 parse_request: Line: m=audio 5004 RTP/AVP 0 18 4 8 13 (32) [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4872 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4872 parse_request: Line: a=rtpmap:18 G729/8000 (21) [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4872 parse_request: Line: a=rtpmap:4 G723/8000 (20) [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4872 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Aug 27 08:10:42] --- (15 headers 11 lines) --- [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:2762 do_setnat: Setting NAT on RTP to Off [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:2772 do_setnat: Setting NAT on UDPTL to Off [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4577 sip_alloc: Allocating new SIP dialog for c2a0ecd08c201f6fc5d89eff8dc7ecb1@10.4.119.245 - INVITE (With RTP) [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:15667 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:1711 parse_sip_options: Begin: parsing SIP "Supported: timer" [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:1719 parse_sip_options: Found SIP option: -timer- [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:1725 parse_sip_options: Matched SIP option: timer [Aug 27 08:10:42] Sending to 10.4.119.185 : 5060 (no NAT) [Aug 27 08:10:42] Using INVITE request as basis request - c2a0ecd08c201f6fc5d89eff8dc7ecb1@10.4.119.245 [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:2762 do_setnat: Setting NAT on RTP to Off [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:2772 do_setnat: Setting NAT on UDPTL to Off [Aug 27 08:10:42] <--- Reliably Transmitting (no NAT) to 10.4.119.185:5060 ---> SIP/2.0 407 Proxy Authentication Required Via: SIP/2.0/UDP 10.4.119.185;branch=z9hG4bKdece8b233;received=10.4.119.185 From: sip:3456@10.4.119.245;tag=675a4ef80a8f1ed To: sip:4567@10.4.119.245;tag=as4ee861f2 Call-ID: c2a0ecd08c201f6fc5d89eff8dc7ecb1@10.4.119.245 CSeq: 188001316 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Proxy-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="2722cad8" Content-Length: 0 <------------> [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:2051 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #-1 [Aug 27 08:10:42] Scheduling destruction of SIP dialog 'c2a0ecd08c201f6fc5d89eff8dc7ecb1@10.4.119.245' in 32000 ms (Method: INVITE) [Aug 27 08:10:42] Found user '3456' [Aug 27 08:10:42] <--- SIP read from 10.4.119.185:5060 ---> ACK sip:4567@10.4.119.245 SIP/2.0 Via: SIP/2.0/UDP 10.4.119.185;branch=z9hG4bKdece8b233 Content-Length: 0 To: sip:4567@10.4.119.245;tag=as4ee861f2 From: sip:3456@10.4.119.245;tag=675a4ef80a8f1ed Call-ID: c2a0ecd08c201f6fc5d89eff8dc7ecb1@10.4.119.245 CSeq: 188001316 ACK User-Agent: MxSipApp/5.0.23.153 MxSF/v3.2.2.4 <-------------> [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 0: ACK sip:4567@10.4.119.245 SIP/2.0 (33) [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 1: Via: SIP/2.0/UDP 10.4.119.185;branch=z9hG4bKdece8b233 (53) [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 2: Content-Length: 0 (17) [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 3: To: sip:4567@10.4.119.245;tag=as4ee861f2 (40) [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 4: From: sip:3456@10.4.119.245;tag=675a4ef80a8f1ed (47) [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 5: Call-ID: c2a0ecd08c201f6fc5d89eff8dc7ecb1@10.4.119.245 (54) [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 6: CSeq: 188001316 ACK (19) [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 7: User-Agent: MxSipApp/5.0.23.153 MxSF/v3.2.2.4 (45) [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 8: (0) [Aug 27 08:10:42] --- (8 headers 0 lines) --- [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4630 find_call: = Found Their Call ID: c2a0ecd08c201f6fc5d89eff8dc7ecb1@10.4.119.245 Their Tag 675a4ef80a8f1ed Our tag: as4ee861f2 [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:15667 handle_request: **** Received ACK (6) - Command in SIP ACK [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:2174 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #61 [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:2200 __sip_ack: Stopping retransmission on 'c2a0ecd08c201f6fc5d89eff8dc7ecb1@10.4.119.245' of Response 188001316: Match Found [Aug 27 08:10:42] <--- SIP read from 10.4.119.185:5060 ---> INVITE sip:4567@10.4.119.245 SIP/2.0 Via: SIP/2.0/UDP 10.4.119.185;branch=z9hG4bK78073e993 Content-Length: 243 To: sip:4567@10.4.119.245 From: sip:3456@10.4.119.245;tag=675a4ef80a8f1ed Call-ID: c2a0ecd08c201f6fc5d89eff8dc7ecb1@10.4.119.245 CSeq: 188001317 INVITE Supported: timer Min-SE: 1800 Session-Expires: 3600 Allow: INVITE, ACK, BYE, CANCEL, REFER, NOTIFY Contact: sip:3456@10.4.119.185 Content-Type: application/sdp Proxy-Authorization:Digest response="6ae0995aa94dbe6d802090633a213170",username="3456",realm="asterisk",nonce="2722cad8",algorithm=MD5,uri="sip:4567@10.4.119.245" Supported: replaces User-Agent: MxSipApp/5.0.23.153 MxSF/v3.2.2.4 v=0 o=MxSIP 153769626663182367 2020175608213136251 IN IP4 10.4.119.185 s=- c=IN IP4 10.4.119.185 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 <-------------> [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 0: INVITE sip:4567@10.4.119.245 SIP/2.0 (36) [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 1: Via: SIP/2.0/UDP 10.4.119.185;branch=z9hG4bK78073e993 (53) [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 2: Content-Length: 243 (19) [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 3: To: sip:4567@10.4.119.245 (25) [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 4: From: sip:3456@10.4.119.245;tag=675a4ef80a8f1ed (47) [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 5: Call-ID: c2a0ecd08c201f6fc5d89eff8dc7ecb1@10.4.119.245 (54) [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 6: CSeq: 188001317 INVITE (22) [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 7: Supported: timer (16) [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 8: Min-SE: 1800 (12) [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 9: Session-Expires: 3600 (21) [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 10: Allow: INVITE, ACK, BYE, CANCEL, REFER, NOTIFY (46) [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 11: Contact: sip:3456@10.4.119.185 (30) [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 12: Content-Type: application/sdp (29) [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 13: Proxy-Authorization:Digest response="6ae0995aa94dbe6d802090633a213170",username="3456",realm="asterisk",nonce="2722cad8",algorithm=MD5,uri="sip:4567@10.4.119.245" (162) [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 14: Supported: replaces (19) [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 15: User-Agent: MxSipApp/5.0.23.153 MxSF/v3.2.2.4 (45) [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 16: (0) [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4872 parse_request: Line: v=0 (3) [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4872 parse_request: Line: o=MxSIP 153769626663182367 2020175608213136251 IN IP4 10.4.119.185 (66) [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4872 parse_request: Line: s=- (3) [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4872 parse_request: Line: c=IN IP4 10.4.119.185 (21) [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4872 parse_request: Line: t=0 0 (5) [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4872 parse_request: Line: a=sendrecv (10) [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4872 parse_request: Line: m=audio 5004 RTP/AVP 0 18 4 8 13 (32) [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4872 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4872 parse_request: Line: a=rtpmap:18 G729/8000 (21) [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4872 parse_request: Line: a=rtpmap:4 G723/8000 (20) [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4872 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Aug 27 08:10:42] --- (16 headers 11 lines) --- [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4630 find_call: = Found Their Call ID: c2a0ecd08c201f6fc5d89eff8dc7ecb1@10.4.119.245 Their Tag 675a4ef80a8f1ed Our tag: as4ee861f2 [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:15667 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Aug 27 08:10:42] Sending to 10.4.119.185 : 5060 (no NAT) [Aug 27 08:10:42] Using INVITE request as basis request - c2a0ecd08c201f6fc5d89eff8dc7ecb1@10.4.119.245 [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:2762 do_setnat: Setting NAT on RTP to Off [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:2772 do_setnat: Setting NAT on UDPTL to Off [Aug 27 08:10:42] Found user '3456' [Aug 27 08:10:42] Found RTP audio format 0 [Aug 27 08:10:42] Found RTP audio format 18 [Aug 27 08:10:42] Found RTP audio format 4 [Aug 27 08:10:42] Found RTP audio format 8 [Aug 27 08:10:42] Found RTP audio format 13 [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:5236 process_sdp: Peer doesn't provide T.38 UDPTL [Aug 27 08:10:42] Peer audio RTP is at port 10.4.119.185:5004 [Aug 27 08:10:42] Found audio description format PCMU for ID 0 [Aug 27 08:10:42] Found audio description format G729 for ID 18 [Aug 27 08:10:42] Found audio description format G723 for ID 4 [Aug 27 08:10:42] Found audio description format PCMA for ID 8 [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:5492 process_sdp: T38 state changed to 0 on channel [Aug 27 08:10:42] Capabilities: us - 0x4 (ulaw), peer - audio=0x10d (g723|ulaw|alaw|g729)/video=0x0 (nothing), combined - 0x4 (ulaw) [Aug 27 08:10:42] Non-codec capabilities (dtmf): us - 0x0 (nothing), peer - 0x2 (CN), combined - 0x0 (nothing) [Aug 27 08:10:42] Peer audio RTP is at port 10.4.119.185:5004 [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:5572 process_sdp: We're settling with these formats: 0x4 (ulaw) [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:14332 handle_request_invite: Checking SIP call limits for device 3456 [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:3219 update_call_counter: Updating call counter for incoming call [Aug 27 08:10:42] Looking for 4567 in default (domain 10.4.119.245) [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4054 sip_new: *** Our native formats are 0x4 (ulaw) [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4055 sip_new: *** Joint capabilities are 0x4 (ulaw) [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4056 sip_new: *** Our capabilities are 0x4 (ulaw) [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4057 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4080 sip_new: This channel will not be able to handle video. [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:8402 build_route: build_route: Contact hop: sip:3456@10.4.119.185 [Aug 27 08:10:42] list_route: hop: [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:14415 handle_request_invite: SIP/3456-08f562f0: New call is still down.... Trying... [Aug 27 08:10:42] <--- Transmitting (no NAT) to 10.4.119.185:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.4.119.185;branch=z9hG4bK78073e993;received=10.4.119.185 From: sip:3456@10.4.119.245;tag=675a4ef80a8f1ed To: sip:4567@10.4.119.245 Call-ID: c2a0ecd08c201f6fc5d89eff8dc7ecb1@10.4.119.245 CSeq: 188001317 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Aug 27 08:10:42] DEBUG[17493]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/3456 [Aug 27 08:10:42] DEBUG[17483]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 3456 [Aug 27 08:10:42] DEBUG[17483]: chan_sip.c:16345 sip_devicestate: Checking device state for peer 3456 [Aug 27 08:10:42] DEBUG[17483]: devicestate.c:287 do_state_change: Changing state for SIP/3456 - state 1 (Not in use) [Aug 27 08:10:42] DEBUG[17492]: app_queue.c:661 handle_statechange: Device 'SIP/3456' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Aug 27 08:10:42] DEBUG[17510]: pbx.c:1842 pbx_extension_helper: Launching 'Answer' [Aug 27 08:10:42] -- Executing [4567@default:1] Answer("SIP/3456-08f562f0", "") in new stack [Aug 27 08:10:42] DEBUG[17510]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/3456 [Aug 27 08:10:42] DEBUG[17483]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 3456 [Aug 27 08:10:42] DEBUG[17483]: chan_sip.c:16345 sip_devicestate: Checking device state for peer 3456 [Aug 27 08:10:42] DEBUG[17483]: devicestate.c:287 do_state_change: Changing state for SIP/3456 - state 1 (Not in use) [Aug 27 08:10:42] DEBUG[17492]: app_queue.c:661 handle_statechange: Device 'SIP/3456' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Aug 27 08:10:42] DEBUG[17510]: chan_sip.c:3693 sip_answer: SIP answering channel: SIP/3456-08f562f0 [Aug 27 08:10:42] DEBUG[17510]: chan_sip.c:6774 transmit_response_with_sdp: Setting framing from config on incoming call [Aug 27 08:10:42] DEBUG[17510]: chan_sip.c:6538 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True [Aug 27 08:10:42] DEBUG[17510]: chan_sip.c:6539 add_sdp: ** Our prefcodec: 0x0 (nothing) [Aug 27 08:10:42] Audio is at 10.4.119.245 port 12140 [Aug 27 08:10:42] Adding codec 0x4 (ulaw) to SDP [Aug 27 08:10:42] DEBUG[17510]: chan_sip.c:6670 add_sdp: -- Done with adding codecs to SDP [Aug 27 08:10:42] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:42] DEBUG[17510]: chan_sip.c:6715 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw) [Aug 27 08:10:42] <--- Reliably Transmitting (no NAT) to 10.4.119.185:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.4.119.185;branch=z9hG4bK78073e993;received=10.4.119.185 From: sip:3456@10.4.119.245;tag=675a4ef80a8f1ed To: sip:4567@10.4.119.245;tag=as5d80deaf Call-ID: c2a0ecd08c201f6fc5d89eff8dc7ecb1@10.4.119.245 CSeq: 188001317 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 184 v=0 o=root 17477 17477 IN IP4 10.4.119.245 s=session c=IN IP4 10.4.119.245 t=0 0 m=audio 12140 RTP/AVP 0 a=rtpmap:0 PCMU/8000 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv <------------> [Aug 27 08:10:42] DEBUG[17510]: chan_sip.c:2051 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #-1 [Aug 27 08:10:42] DEBUG[17510]: pbx.c:1842 pbx_extension_helper: Launching 'Dial' [Aug 27 08:10:42] -- Executing [4567@default:2] Dial("SIP/3456-08f562f0", "SIP/4567|20") in new stack [Aug 27 08:10:42] DEBUG[17510]: chan_sip.c:16421 sip_request_call: Asked to create a SIP channel with formats: 0x4 (ulaw) [Aug 27 08:10:42] DEBUG[17510]: chan_sip.c:4577 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Aug 27 08:10:42] DEBUG[17510]: chan_sip.c:2808 create_addr_from_peer: Our T38 capability (3872) [Aug 27 08:10:42] DEBUG[17510]: chan_sip.c:2762 do_setnat: Setting NAT on RTP to Off [Aug 27 08:10:42] DEBUG[17510]: chan_sip.c:2772 do_setnat: Setting NAT on UDPTL to Off [Aug 27 08:10:42] DEBUG[17510]: chan_sip.c:4054 sip_new: *** Our native formats are 0x4 (ulaw) [Aug 27 08:10:42] DEBUG[17510]: chan_sip.c:4055 sip_new: *** Joint capabilities are 0x0 (nothing) [Aug 27 08:10:42] DEBUG[17510]: chan_sip.c:4056 sip_new: *** Our capabilities are 0x4 (ulaw) [Aug 27 08:10:42] DEBUG[17510]: chan_sip.c:4057 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Aug 27 08:10:42] DEBUG[17510]: chan_sip.c:4059 sip_new: *** Our preferred formats from the incoming channel are 0x4 (ulaw) [Aug 27 08:10:42] DEBUG[17510]: chan_sip.c:4080 sip_new: This channel will not be able to handle video. [Aug 27 08:10:42] DEBUG[17510]: channel.c:3345 ast_channel_inherit_variables: Not copying variable SIPCALLID. [Aug 27 08:10:42] DEBUG[17510]: channel.c:3345 ast_channel_inherit_variables: Not copying variable SIPUSERAGENT. [Aug 27 08:10:42] DEBUG[17510]: channel.c:3345 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [Aug 27 08:10:42] DEBUG[17510]: channel.c:3345 ast_channel_inherit_variables: Not copying variable SIPURI. [Aug 27 08:10:42] DEBUG[17510]: chan_sip.c:3021 sip_call: Outgoing Call for 4567 [Aug 27 08:10:42] DEBUG[17510]: chan_sip.c:3219 update_call_counter: Updating call counter for outgoing call [Aug 27 08:10:42] DEBUG[17510]: chan_sip.c:3036 sip_call: Our T38 capability (3872), joint T38 capability (3872) [Aug 27 08:10:42] DEBUG[17510]: chan_sip.c:6538 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: False [Aug 27 08:10:42] DEBUG[17510]: chan_sip.c:6539 add_sdp: ** Our prefcodec: 0x4 (ulaw) [Aug 27 08:10:42] Audio is at 10.4.119.245 port 11112 [Aug 27 08:10:42] Adding codec 0x4 (ulaw) to SDP [Aug 27 08:10:42] DEBUG[17510]: chan_sip.c:6670 add_sdp: -- Done with adding codecs to SDP [Aug 27 08:10:42] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:42] DEBUG[17510]: chan_sip.c:6715 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw) [Aug 27 08:10:42] DEBUG[17510]: chan_sip.c:4840 parse_request: Header 0: INVITE sip:4567@10.4.119.185 SIP/2.0 (36) [Aug 27 08:10:42] DEBUG[17510]: chan_sip.c:4840 parse_request: Header 1: Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK102075c8;rport (63) [Aug 27 08:10:42] DEBUG[17510]: chan_sip.c:4840 parse_request: Header 2: From: "3456" ;tag=as2ef5c824 (51) [Aug 27 08:10:42] DEBUG[17510]: chan_sip.c:4840 parse_request: Header 3: To: (27) [Aug 27 08:10:42] DEBUG[17510]: chan_sip.c:4840 parse_request: Header 4: Contact: (32) [Aug 27 08:10:42] DEBUG[17510]: chan_sip.c:4840 parse_request: Header 5: Call-ID: 3f0aedd05a010de95fe9a78a3e658faf@10.4.119.245 (54) [Aug 27 08:10:42] DEBUG[17510]: chan_sip.c:4840 parse_request: Header 6: CSeq: 102 INVITE (16) [Aug 27 08:10:42] DEBUG[17510]: chan_sip.c:4840 parse_request: Header 7: User-Agent: Asterisk PBX (24) [Aug 27 08:10:42] DEBUG[17510]: chan_sip.c:4840 parse_request: Header 8: Max-Forwards: 70 (16) [Aug 27 08:10:42] DEBUG[17510]: chan_sip.c:4840 parse_request: Header 9: Date: Wed, 27 Aug 2008 12:10:42 GMT (35) [Aug 27 08:10:42] DEBUG[17510]: chan_sip.c:4840 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Aug 27 08:10:42] DEBUG[17510]: chan_sip.c:4840 parse_request: Header 11: Supported: replaces (19) [Aug 27 08:10:42] DEBUG[17510]: chan_sip.c:4840 parse_request: Header 12: Content-Type: application/sdp (29) [Aug 27 08:10:42] DEBUG[17510]: chan_sip.c:4840 parse_request: Header 13: Content-Length: 184 (19) [Aug 27 08:10:42] DEBUG[17510]: chan_sip.c:4840 parse_request: Header 14: (0) [Aug 27 08:10:42] DEBUG[17510]: chan_sip.c:4872 parse_request: Line: v=0 (3) [Aug 27 08:10:42] DEBUG[17510]: chan_sip.c:4872 parse_request: Line: o=root 17477 17477 IN IP4 10.4.119.245 (38) [Aug 27 08:10:42] DEBUG[17510]: chan_sip.c:4872 parse_request: Line: s=session (9) [Aug 27 08:10:42] DEBUG[17510]: chan_sip.c:4872 parse_request: Line: c=IN IP4 10.4.119.245 (21) [Aug 27 08:10:42] DEBUG[17510]: chan_sip.c:4872 parse_request: Line: t=0 0 (5) [Aug 27 08:10:42] DEBUG[17510]: chan_sip.c:4872 parse_request: Line: m=audio 11112 RTP/AVP 0 (23) [Aug 27 08:10:42] DEBUG[17510]: chan_sip.c:4872 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Aug 27 08:10:42] DEBUG[17510]: chan_sip.c:4872 parse_request: Line: a=silenceSupp:off - - - - (25) [Aug 27 08:10:42] DEBUG[17510]: chan_sip.c:4872 parse_request: Line: a=ptime:20 (10) [Aug 27 08:10:42] DEBUG[17510]: chan_sip.c:4872 parse_request: Line: a=sendrecv (10) [Aug 27 08:10:42] Reliably Transmitting (no NAT) to 10.4.119.185:5060: INVITE sip:4567@10.4.119.185 SIP/2.0 Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK102075c8;rport From: "3456" ;tag=as2ef5c824 To: Contact: Call-ID: 3f0aedd05a010de95fe9a78a3e658faf@10.4.119.245 CSeq: 102 INVITE User-Agent: Asterisk PBX Max-Forwards: 70 Date: Wed, 27 Aug 2008 12:10:42 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Type: application/sdp Content-Length: 184 v=0 o=root 17477 17477 IN IP4 10.4.119.245 s=session c=IN IP4 10.4.119.245 t=0 0 m=audio 11112 RTP/AVP 0 a=rtpmap:0 PCMU/8000 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv --- [Aug 27 08:10:42] DEBUG[17510]: chan_sip.c:2051 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #-1 [Aug 27 08:10:42] -- Called 4567 [Aug 27 08:10:42] <--- SIP read from 10.4.119.185:5060 ---> ACK sip:4567@10.4.119.245 SIP/2.0 Via: SIP/2.0/UDP 10.4.119.185;branch=z9hG4bKcdca8891f Content-Length: 0 To: sip:4567@10.4.119.245;tag=as5d80deaf From: sip:3456@10.4.119.245;tag=675a4ef80a8f1ed Call-ID: c2a0ecd08c201f6fc5d89eff8dc7ecb1@10.4.119.245 CSeq: 188001317 ACK Contact: sip:3456@10.4.119.185 Proxy-Authorization:Digest response="6ae0995aa94dbe6d802090633a213170",username="3456",realm="asterisk",nonce="2722cad8",algorithm=MD5,uri="sip:4567@10.4.119.245" User-Agent: MxSipApp/5.0.23.153 MxSF/v3.2.2.4 <-------------> [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 0: ACK sip:4567@10.4.119.245 SIP/2.0 (33) [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 1: Via: SIP/2.0/UDP 10.4.119.185;branch=z9hG4bKcdca8891f (53) [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 2: Content-Length: 0 (17) [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 3: To: sip:4567@10.4.119.245;tag=as5d80deaf (40) [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 4: From: sip:3456@10.4.119.245;tag=675a4ef80a8f1ed (47) [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 5: Call-ID: c2a0ecd08c201f6fc5d89eff8dc7ecb1@10.4.119.245 (54) [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 6: CSeq: 188001317 ACK (19) [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 7: Contact: sip:3456@10.4.119.185 (30) [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 8: Proxy-Authorization:Digest response="6ae0995aa94dbe6d802090633a213170",username="3456",realm="asterisk",nonce="2722cad8",algorithm=MD5,uri="sip:4567@10.4.119.245" (162) [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 9: User-Agent: MxSipApp/5.0.23.153 MxSF/v3.2.2.4 (45) [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 10: (0) [Aug 27 08:10:42] --- (10 headers 0 lines) --- [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4630 find_call: = No match Their Call ID: 3f0aedd05a010de95fe9a78a3e658faf@10.4.119.245 Their Tag Our tag: as2ef5c824 [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4630 find_call: = Found Their Call ID: c2a0ecd08c201f6fc5d89eff8dc7ecb1@10.4.119.245 Their Tag 675a4ef80a8f1ed Our tag: as5d80deaf [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:15667 handle_request: **** Received ACK (6) - Command in SIP ACK [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:2174 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #63 [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:2200 __sip_ack: Stopping retransmission on 'c2a0ecd08c201f6fc5d89eff8dc7ecb1@10.4.119.245' of Response 188001317: Match Found [Aug 27 08:10:42] <--- SIP read from 10.4.119.185:5060 ---> SIP/2.0 100 Trying Call-ID: 3f0aedd05a010de95fe9a78a3e658faf@10.4.119.245 CSeq: 102 INVITE From: "3456" ;tag=as2ef5c824 To: ;tag=d42dbfe2b2544b5 Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK102075c8;rport Content-Length: 0 User-Agent: MxSipApp/5.0.23.153 MxSF/v3.2.2.4 <-------------> [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 0: SIP/2.0 100 Trying (18) [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 1: Call-ID: 3f0aedd05a010de95fe9a78a3e658faf@10.4.119.245 (54) [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 2: CSeq: 102 INVITE (16) [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 3: From: "3456" ;tag=as2ef5c824 (51) [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 4: To: ;tag=d42dbfe2b2544b5 (47) [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 5: Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK102075c8;rport (63) [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 6: Content-Length: 0 (17) [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 7: User-Agent: MxSipApp/5.0.23.153 MxSF/v3.2.2.4 (45) [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 8: (0) [Aug 27 08:10:42] --- (8 headers 0 lines) --- [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4630 find_call: = Found Their Call ID: 3f0aedd05a010de95fe9a78a3e658faf@10.4.119.245 Their Tag Our tag: as2ef5c824 [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:2233 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #64 - INVITE (got response) [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:2241 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '3f0aedd05a010de95fe9a78a3e658faf@10.4.119.245' Request 102: Found [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:12170 handle_response_invite: SIP response 100 to standard invite [Aug 27 08:10:42] <--- SIP read from 10.4.119.185:5060 ---> SIP/2.0 180 Ringing Call-ID: 3f0aedd05a010de95fe9a78a3e658faf@10.4.119.245 CSeq: 102 INVITE From: "3456" ;tag=as2ef5c824 To: ;tag=d42dbfe2b2544b5 Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK102075c8;rport Content-Length: 0 Contact: sip:4567@10.4.119.185 User-Agent: MxSipApp/5.0.23.153 MxSF/v3.2.2.4 <-------------> [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 0: SIP/2.0 180 Ringing (19) [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 1: Call-ID: 3f0aedd05a010de95fe9a78a3e658faf@10.4.119.245 (54) [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 2: CSeq: 102 INVITE (16) [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 3: From: "3456" ;tag=as2ef5c824 (51) [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 4: To: ;tag=d42dbfe2b2544b5 (47) [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 5: Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK102075c8;rport (63) [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 6: Content-Length: 0 (17) [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 7: Contact: sip:4567@10.4.119.185 (30) [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 8: User-Agent: MxSipApp/5.0.23.153 MxSF/v3.2.2.4 (45) [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 9: (0) [Aug 27 08:10:42] --- (9 headers 0 lines) --- [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:4630 find_call: = Found Their Call ID: 3f0aedd05a010de95fe9a78a3e658faf@10.4.119.245 Their Tag d42dbfe2b2544b5 Our tag: as2ef5c824 [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:2241 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '3f0aedd05a010de95fe9a78a3e658faf@10.4.119.245' Request 102: Found [Aug 27 08:10:42] DEBUG[17493]: chan_sip.c:12170 handle_response_invite: SIP response 180 to standard invite [Aug 27 08:10:42] DEBUG[17493]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/4567 [Aug 27 08:10:42] -- SIP/4567-08f062c0 is ringing [Aug 27 08:10:42] DEBUG[17510]: channel.c:2423 ast_indicate_data: Driver for channel 'SIP/3456-08f562f0' does not support indication 3, emulating it [Aug 27 08:10:42] DEBUG[17510]: channel.c:2837 set_format: Set channel SIP/3456-08f562f0 to write format slin [Aug 27 08:10:42] DEBUG[17483]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 4567 [Aug 27 08:10:42] DEBUG[17483]: chan_sip.c:16345 sip_devicestate: Checking device state for peer 4567 [Aug 27 08:10:42] DEBUG[17483]: devicestate.c:287 do_state_change: Changing state for SIP/4567 - state 1 (Not in use) [Aug 27 08:10:42] DEBUG[17492]: app_queue.c:661 handle_statechange: Device 'SIP/4567' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Aug 27 08:10:42] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:42] DEBUG[17510]: rtp.c:2774 ast_rtp_write: Ooh, format changed from unknown to ulaw [Aug 27 08:10:42] DEBUG[17510]: rtp.c:2791 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160 [Aug 27 08:10:42] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:42] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:42] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:42] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:42] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:42] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:42] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:42] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:42] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:42] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:42] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:42] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:42] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:42] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:42] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:42] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:42] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:42] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:42] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:42] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:42] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:42] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:42] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:42] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:42] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:42] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:42] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:42] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:42] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:42] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:43] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:43] DEBUG[17510]: rtp.c:2637 ast_rtp_raw_write: Difference is 1232, ms is 174 [Aug 27 08:10:43] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:43] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:43] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:43] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:43] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:43] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:43] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:43] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:43] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:43] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:43] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:43] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:43] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:43] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:43] DEBUG[17510]: rtp.c:2637 ast_rtp_raw_write: Difference is 1192, ms is 169 [Aug 27 08:10:43] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:43] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:43] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:43] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:43] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:43] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:43] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:43] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:43] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:43] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:43] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:43] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:43] DEBUG[17510]: rtp.c:2637 ast_rtp_raw_write: Difference is 1080, ms is 155 [Aug 27 08:10:43] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:44] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:44] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:44] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:44] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:44] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:44] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:44] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:44] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:44] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:44] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:44] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:44] DEBUG[17510]: rtp.c:2637 ast_rtp_raw_write: Difference is 1192, ms is 169 [Aug 27 08:10:44] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:44] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:44] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:44] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:44] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:44] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:44] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:44] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:44] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:44] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:44] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:44] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:44] DEBUG[17510]: rtp.c:2637 ast_rtp_raw_write: Difference is 1352, ms is 189 [Aug 27 08:10:44] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:44] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:44] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:44] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:44] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:44] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:44] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:45] <--- SIP read from 10.4.119.185:5060 ---> INFO sip:4567@10.4.119.245 SIP/2.0 Via: SIP/2.0/UDP 10.4.119.185;branch=z9hG4bK2ec7aae5d Content-Length: 26 To: sip:4567@10.4.119.245;tag=as5d80deaf From: sip:3456@10.4.119.245;tag=675a4ef80a8f1ed Call-ID: c2a0ecd08c201f6fc5d89eff8dc7ecb1@10.4.119.245 CSeq: 188001318 INFO Supported: timer Content-Type: application/dtmf-relay Proxy-Authorization:Digest response="c754df698d267424e98638816c76879b",username="3456",realm="asterisk",nonce="2722cad8",algorithm=MD5,uri="sip:4567@10.4.119.245" Supported: replaces User-Agent: MxSipApp/5.0.23.153 MxSF/v3.2.2.4 Signal= 1 Duration= 100 <-------------> [Aug 27 08:10:45] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 0: INFO sip:4567@10.4.119.245 SIP/2.0 (34) [Aug 27 08:10:45] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 1: Via: SIP/2.0/UDP 10.4.119.185;branch=z9hG4bK2ec7aae5d (53) [Aug 27 08:10:45] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 2: Content-Length: 26 (18) [Aug 27 08:10:45] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 3: To: sip:4567@10.4.119.245;tag=as5d80deaf (40) [Aug 27 08:10:45] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 4: From: sip:3456@10.4.119.245;tag=675a4ef80a8f1ed (47) [Aug 27 08:10:45] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 5: Call-ID: c2a0ecd08c201f6fc5d89eff8dc7ecb1@10.4.119.245 (54) [Aug 27 08:10:45] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 6: CSeq: 188001318 INFO (20) [Aug 27 08:10:45] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 7: Supported: timer (16) [Aug 27 08:10:45] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 8: Content-Type: application/dtmf-relay (36) [Aug 27 08:10:45] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 9: Proxy-Authorization:Digest response="c754df698d267424e98638816c76879b",username="3456",realm="asterisk",nonce="2722cad8",algorithm=MD5,uri="sip:4567@10.4.119.245" (162) [Aug 27 08:10:45] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 10: Supported: replaces (19) [Aug 27 08:10:45] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 11: User-Agent: MxSipApp/5.0.23.153 MxSF/v3.2.2.4 (45) [Aug 27 08:10:45] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 12: (0) [Aug 27 08:10:45] DEBUG[17493]: chan_sip.c:4872 parse_request: Line: Signal= 1 (9) [Aug 27 08:10:45] DEBUG[17493]: chan_sip.c:4872 parse_request: Line: Duration= 100 (13) [Aug 27 08:10:45] --- (12 headers 2 lines) --- [Aug 27 08:10:45] DEBUG[17493]: chan_sip.c:4630 find_call: = No match Their Call ID: 3f0aedd05a010de95fe9a78a3e658faf@10.4.119.245 Their Tag d42dbfe2b2544b5 Our tag: as2ef5c824 [Aug 27 08:10:45] DEBUG[17493]: chan_sip.c:4630 find_call: = Found Their Call ID: c2a0ecd08c201f6fc5d89eff8dc7ecb1@10.4.119.245 Their Tag 675a4ef80a8f1ed Our tag: as5d80deaf [Aug 27 08:10:45] DEBUG[17493]: chan_sip.c:15667 handle_request: **** Received INFO (13) - Command in SIP INFO [Aug 27 08:10:45] Receiving INFO! [Aug 27 08:10:45] * DTMF-relay event received: 1 [Aug 27 08:10:45] <--- Transmitting (no NAT) to 10.4.119.185:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.4.119.185;branch=z9hG4bK2ec7aae5d;received=10.4.119.185 From: sip:3456@10.4.119.245;tag=675a4ef80a8f1ed To: sip:4567@10.4.119.245;tag=as5d80deaf Call-ID: c2a0ecd08c201f6fc5d89eff8dc7ecb1@10.4.119.245 CSeq: 188001318 INFO User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Aug 27 08:10:45] Reliably Transmitting (no NAT) to 10.4.119.185:5060: INFO sip:4567@10.4.119.185 SIP/2.0 Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK4747e4d8;rport From: "3456" ;tag=as2ef5c824 To: ;tag=d42dbfe2b2544b5 Contact: Call-ID: 3f0aedd05a010de95fe9a78a3e658faf@10.4.119.245 CSeq: 103 INFO User-Agent: Asterisk PBX Max-Forwards: 70 Content-Type: application/dtmf-relay Content-Length: 24 Signal=1 Duration=457 --- [Aug 27 08:10:45] DEBUG[17510]: chan_sip.c:2051 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #-1 [Aug 27 08:10:45] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:45] DEBUG[17510]: rtp.c:2637 ast_rtp_raw_write: Difference is 4832, ms is 624 [Aug 27 08:10:45] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:45] <--- SIP read from 10.4.119.185:5060 ---> SIP/2.0 200 OK Call-ID: 3f0aedd05a010de95fe9a78a3e658faf@10.4.119.245 CSeq: 103 INFO From: "3456" ;tag=as2ef5c824 To: ;tag=d42dbfe2b2544b5 Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK4747e4d8;rport Content-Length: 0 Supported: replaces User-Agent: MxSipApp/5.0.23.153 MxSF/v3.2.2.4 <-------------> [Aug 27 08:10:45] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 0: SIP/2.0 200 OK (14) [Aug 27 08:10:45] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 1: Call-ID: 3f0aedd05a010de95fe9a78a3e658faf@10.4.119.245 (54) [Aug 27 08:10:45] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 2: CSeq: 103 INFO (14) [Aug 27 08:10:45] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 3: From: "3456" ;tag=as2ef5c824 (51) [Aug 27 08:10:45] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 4: To: ;tag=d42dbfe2b2544b5 (47) [Aug 27 08:10:45] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 5: Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK4747e4d8;rport (63) [Aug 27 08:10:45] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 6: Content-Length: 0 (17) [Aug 27 08:10:45] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 7: Supported: replaces (19) [Aug 27 08:10:45] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 8: User-Agent: MxSipApp/5.0.23.153 MxSF/v3.2.2.4 (45) [Aug 27 08:10:45] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 9: (0) [Aug 27 08:10:45] --- (9 headers 0 lines) --- [Aug 27 08:10:45] DEBUG[17493]: chan_sip.c:4630 find_call: = Found Their Call ID: 3f0aedd05a010de95fe9a78a3e658faf@10.4.119.245 Their Tag d42dbfe2b2544b5 Our tag: as2ef5c824 [Aug 27 08:10:45] DEBUG[17493]: chan_sip.c:2174 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #67 [Aug 27 08:10:45] DEBUG[17493]: chan_sip.c:2200 __sip_ack: Stopping retransmission on '3f0aedd05a010de95fe9a78a3e658faf@10.4.119.245' of Request 103: Match Found [Aug 27 08:10:45] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:45] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:45] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:45] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:45] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:45] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:45] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:45] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:45] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:45] DEBUG[17510]: rtp.c:2637 ast_rtp_raw_write: Difference is 1432, ms is 199 [Aug 27 08:10:45] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:45] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:45] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:45] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:46] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:46] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:46] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:46] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:46] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:46] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:46] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:46] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:46] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:46] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:46] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:46] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:46] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:46] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:46] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:46] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:46] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:46] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:46] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:46] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:46] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:46] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:46] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:46] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:46] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:46] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:46] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:46] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:46] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:46] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:46] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:46] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:46] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:46] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:46] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:46] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:46] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:46] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:46] DEBUG[17510]: rtp.c:879 ast_rtcp_read: Got RTCP report of 80 bytes [Aug 27 08:10:46] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:46] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:46] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:46] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:46] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:46] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:46] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:46] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:46] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:46] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:46] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:46] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:47] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:47] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:47] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:47] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:47] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:47] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:47] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:47] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:47] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:47] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:47] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:47] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:47] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:47] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:47] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:47] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:47] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:47] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:47] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:47] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:47] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:47] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:47] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:47] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:47] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:47] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:47] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:47] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:47] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:47] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:47] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:48] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:48] DEBUG[17510]: rtp.c:2637 ast_rtp_raw_write: Difference is 3032, ms is 399 [Aug 27 08:10:48] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:48] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:48] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:48] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:48] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:48] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:48] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:48] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:48] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:48] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:48] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:48] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:48] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:48] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:48] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:48] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:48] DEBUG[17510]: rtp.c:2637 ast_rtp_raw_write: Difference is 1472, ms is 204 [Aug 27 08:10:48] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:48] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:48] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:48] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:48] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:48] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:48] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:48] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:48] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:48] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:48] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:48] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:48] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:48] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:48] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:48] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:48] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:48] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:48] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:48] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:48] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:48] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:48] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:48] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:49] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:49] DEBUG[17510]: channel.c:2369 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=-1) [Aug 27 08:10:49] <--- SIP read from 10.4.119.185:5060 ---> BYE sip:4567@10.4.119.245 SIP/2.0 Via: SIP/2.0/UDP 10.4.119.185;branch=z9hG4bKbc1355fa9 Content-Length: 0 To: sip:4567@10.4.119.245;tag=as5d80deaf From: sip:3456@10.4.119.245;tag=675a4ef80a8f1ed Call-ID: c2a0ecd08c201f6fc5d89eff8dc7ecb1@10.4.119.245 CSeq: 188001319 BYE Supported: timer Proxy-Authorization:Digest response="c74365a88e41ec0459f220c2c58d165e",username="3456",realm="asterisk",nonce="2722cad8",algorithm=MD5,uri="sip:4567@10.4.119.245" Supported: replaces User-Agent: MxSipApp/5.0.23.153 MxSF/v3.2.2.4 <-------------> [Aug 27 08:10:49] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 0: BYE sip:4567@10.4.119.245 SIP/2.0 (33) [Aug 27 08:10:49] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 1: Via: SIP/2.0/UDP 10.4.119.185;branch=z9hG4bKbc1355fa9 (53) [Aug 27 08:10:49] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 2: Content-Length: 0 (17) [Aug 27 08:10:49] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 3: To: sip:4567@10.4.119.245;tag=as5d80deaf (40) [Aug 27 08:10:49] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 4: From: sip:3456@10.4.119.245;tag=675a4ef80a8f1ed (47) [Aug 27 08:10:49] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 5: Call-ID: c2a0ecd08c201f6fc5d89eff8dc7ecb1@10.4.119.245 (54) [Aug 27 08:10:49] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 6: CSeq: 188001319 BYE (19) [Aug 27 08:10:49] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 7: Supported: timer (16) [Aug 27 08:10:49] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 8: Proxy-Authorization:Digest response="c74365a88e41ec0459f220c2c58d165e",username="3456",realm="asterisk",nonce="2722cad8",algorithm=MD5,uri="sip:4567@10.4.119.245" (162) [Aug 27 08:10:49] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 9: Supported: replaces (19) [Aug 27 08:10:49] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 10: User-Agent: MxSipApp/5.0.23.153 MxSF/v3.2.2.4 (45) [Aug 27 08:10:49] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 11: (0) [Aug 27 08:10:49] --- (11 headers 0 lines) --- [Aug 27 08:10:49] DEBUG[17493]: chan_sip.c:4630 find_call: = No match Their Call ID: 3f0aedd05a010de95fe9a78a3e658faf@10.4.119.245 Their Tag d42dbfe2b2544b5 Our tag: as2ef5c824 [Aug 27 08:10:49] DEBUG[17493]: chan_sip.c:4630 find_call: = Found Their Call ID: c2a0ecd08c201f6fc5d89eff8dc7ecb1@10.4.119.245 Their Tag 675a4ef80a8f1ed Our tag: as5d80deaf [Aug 27 08:10:49] DEBUG[17493]: chan_sip.c:15667 handle_request: **** Received BYE (8) - Command in SIP BYE [Aug 27 08:10:49] Sending to 10.4.119.185 : 5060 (no NAT) [Aug 27 08:10:49] DEBUG[17493]: chan_sip.c:1664 sip_alreadygone: Setting SIP_ALREADYGONE on dialog c2a0ecd08c201f6fc5d89eff8dc7ecb1@10.4.119.245 [Aug 27 08:10:49] DEBUG[17493]: chan_sip.c:15207 handle_request_bye: Received bye, issuing owner hangup [Aug 27 08:10:49] <--- Transmitting (no NAT) to 10.4.119.185:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.4.119.185;branch=z9hG4bKbc1355fa9;received=10.4.119.185 From: sip:3456@10.4.119.245;tag=675a4ef80a8f1ed To: sip:4567@10.4.119.245;tag=as5d80deaf Call-ID: c2a0ecd08c201f6fc5d89eff8dc7ecb1@10.4.119.245 CSeq: 188001319 BYE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Aug 27 08:10:49] DEBUG[17510]: channel.c:2837 set_format: Set channel SIP/3456-08f562f0 to write format ulaw [Aug 27 08:10:49] DEBUG[17510]: rtp.c:1510 ast_rtp_early_bridge: Channel '' has no RTP, not doing anything [Aug 27 08:10:49] DEBUG[17510]: channel.c:1500 ast_hangup: Hanging up channel 'SIP/4567-08f062c0' [Aug 27 08:10:49] DEBUG[17510]: chan_sip.c:3532 sip_hangup: Hangup call SIP/4567-08f062c0, SIP callid 3f0aedd05a010de95fe9a78a3e658faf@10.4.119.245) [Aug 27 08:10:49] DEBUG[17510]: chan_sip.c:3555 sip_hangup: Hanging up channel in state Ringing (not UP) [Aug 27 08:10:49] Scheduling destruction of SIP dialog '3f0aedd05a010de95fe9a78a3e658faf@10.4.119.245' in 6400 ms (Method: INVITE) [Aug 27 08:10:49] DEBUG[17510]: chan_sip.c:2166 __sip_ack: Acked pending invite 102 [Aug 27 08:10:49] DEBUG[17510]: chan_sip.c:2200 __sip_ack: Stopping retransmission on '3f0aedd05a010de95fe9a78a3e658faf@10.4.119.245' of Request 102: Match Found [Aug 27 08:10:49] Reliably Transmitting (no NAT) to 10.4.119.185:5060: CANCEL sip:4567@10.4.119.185 SIP/2.0 Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK4747e4d8;rport From: "3456" ;tag=as2ef5c824 To: Call-ID: 3f0aedd05a010de95fe9a78a3e658faf@10.4.119.245 CSeq: 102 CANCEL User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- [Aug 27 08:10:49] DEBUG[17510]: chan_sip.c:2051 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #-1 [Aug 27 08:10:49] Scheduling destruction of SIP dialog '3f0aedd05a010de95fe9a78a3e658faf@10.4.119.245' in 6400 ms (Method: INVITE) [Aug 27 08:10:49] DEBUG[17510]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/4567 [Aug 27 08:10:49] DEBUG[17510]: app_dial.c:1815 dial_exec_full: Exiting with DIALSTATUS=CANCEL. [Aug 27 08:10:49] DEBUG[17510]: pbx.c:2425 __ast_pbx_run: Spawn extension (default,4567,2) exited non-zero on 'SIP/3456-08f562f0' [Aug 27 08:10:49] == Spawn extension (default, 4567, 2) exited non-zero on 'SIP/3456-08f562f0' [Aug 27 08:10:49] DEBUG[17510]: channel.c:1407 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/3456-08f562f0' [Aug 27 08:10:49] DEBUG[17510]: channel.c:1500 ast_hangup: Hanging up channel 'SIP/3456-08f562f0' [Aug 27 08:10:49] DEBUG[17510]: chan_sip.c:3532 sip_hangup: Hangup call SIP/3456-08f562f0, SIP callid c2a0ecd08c201f6fc5d89eff8dc7ecb1@10.4.119.245) [Aug 27 08:10:49] DEBUG[17510]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '3456' [Aug 27 08:10:49] DEBUG[17510]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '3456' [Aug 27 08:10:49] DEBUG[17510]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '4567' [Aug 27 08:10:49] DEBUG[17510]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is 'default' [Aug 27 08:10:49] DEBUG[17510]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is 'SIP/3456-08f562f0' [Aug 27 08:10:49] DEBUG[17510]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is 'SIP/4567-08f062c0' [Aug 27 08:10:49] DEBUG[17510]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is 'Dial' [Aug 27 08:10:49] DEBUG[17510]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is 'SIP/4567|20' [Aug 27 08:10:49] DEBUG[17510]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '2008-08-27 08:10:42' [Aug 27 08:10:49] DEBUG[17510]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '2008-08-27 08:10:42' [Aug 27 08:10:49] DEBUG[17510]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '2008-08-27 08:10:49' [Aug 27 08:10:49] DEBUG[17510]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '7' [Aug 27 08:10:49] DEBUG[17510]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '7' [Aug 27 08:10:49] DEBUG[17510]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is 'ANSWERED' [Aug 27 08:10:49] DEBUG[17510]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' [Aug 27 08:10:49] DEBUG[17510]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '' [Aug 27 08:10:49] DEBUG[17510]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '1219839042.0' [Aug 27 08:10:49] DEBUG[17510]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '' [Aug 27 08:10:49] DEBUG[17510]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/3456 [Aug 27 08:10:49] DEBUG[17483]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 4567 [Aug 27 08:10:49] DEBUG[17483]: chan_sip.c:16345 sip_devicestate: Checking device state for peer 4567 [Aug 27 08:10:49] DEBUG[17483]: devicestate.c:287 do_state_change: Changing state for SIP/4567 - state 1 (Not in use) [Aug 27 08:10:49] DEBUG[17483]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 3456 [Aug 27 08:10:49] DEBUG[17483]: chan_sip.c:16345 sip_devicestate: Checking device state for peer 3456 [Aug 27 08:10:49] DEBUG[17483]: devicestate.c:287 do_state_change: Changing state for SIP/3456 - state 1 (Not in use) [Aug 27 08:10:49] DEBUG[17492]: app_queue.c:661 handle_statechange: Device 'SIP/4567' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Aug 27 08:10:49] DEBUG[17492]: app_queue.c:661 handle_statechange: Device 'SIP/3456' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Aug 27 08:10:49] <--- SIP read from 10.4.119.185:5060 ---> SIP/2.0 200 OK Call-ID: 3f0aedd05a010de95fe9a78a3e658faf@10.4.119.245 CSeq: 102 CANCEL From: "3456" ;tag=as2ef5c824 To: ;tag=0308ab171239884 Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK4747e4d8;rport Content-Length: 0 Allow: INVITE, ACK, BYE, CANCEL, REFER, NOTIFY User-Agent: MxSipApp/5.0.23.153 MxSF/v3.2.2.4 <-------------> [Aug 27 08:10:49] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 0: SIP/2.0 200 OK (14) [Aug 27 08:10:49] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 1: Call-ID: 3f0aedd05a010de95fe9a78a3e658faf@10.4.119.245 (54) [Aug 27 08:10:49] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 2: CSeq: 102 CANCEL (16) [Aug 27 08:10:49] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 3: From: "3456" ;tag=as2ef5c824 (51) [Aug 27 08:10:49] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 4: To: ;tag=0308ab171239884 (47) [Aug 27 08:10:49] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 5: Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK4747e4d8;rport (63) [Aug 27 08:10:49] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 6: Content-Length: 0 (17) [Aug 27 08:10:49] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 7: Allow: INVITE, ACK, BYE, CANCEL, REFER, NOTIFY (46) [Aug 27 08:10:49] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 8: User-Agent: MxSipApp/5.0.23.153 MxSF/v3.2.2.4 (45) [Aug 27 08:10:49] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 9: (0) [Aug 27 08:10:49] --- (9 headers 0 lines) --- [Aug 27 08:10:49] DEBUG[17493]: chan_sip.c:4630 find_call: = Found Their Call ID: 3f0aedd05a010de95fe9a78a3e658faf@10.4.119.245 Their Tag d42dbfe2b2544b5 Our tag: as2ef5c824 [Aug 27 08:10:49] Really destroying SIP dialog 'c2a0ecd08c201f6fc5d89eff8dc7ecb1@10.4.119.245' Method: BYE [Aug 27 08:10:50] DEBUG[17493]: chan_sip.c:1921 retrans_pkt: SIP TIMER: Rescheduling retransmission #69 (1) CANCEL - 14 [Aug 27 08:10:50] DEBUG[17493]: chan_sip.c:1935 retrans_pkt: ** SIP timers: Rescheduling retransmission 2 to 200 ms (t1 100 ms (Retrans id #69)) [Aug 27 08:10:50] Retransmitting #1 (no NAT) to 10.4.119.185:5060: CANCEL sip:4567@10.4.119.185 SIP/2.0 Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK4747e4d8;rport From: "3456" ;tag=as2ef5c824 To: Call-ID: 3f0aedd05a010de95fe9a78a3e658faf@10.4.119.245 CSeq: 102 CANCEL User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- [Aug 27 08:10:50] <--- SIP read from 10.4.119.185:5060 ---> SIP/2.0 200 OK Call-ID: 3f0aedd05a010de95fe9a78a3e658faf@10.4.119.245 CSeq: 102 CANCEL From: "3456" ;tag=as2ef5c824 To: ;tag=0308ab171239884 Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK4747e4d8;rport Content-Length: 0 Allow: INVITE, ACK, BYE, CANCEL, REFER, NOTIFY User-Agent: MxSipApp/5.0.23.153 MxSF/v3.2.2.4 <-------------> [Aug 27 08:10:50] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 0: SIP/2.0 200 OK (14) [Aug 27 08:10:50] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 1: Call-ID: 3f0aedd05a010de95fe9a78a3e658faf@10.4.119.245 (54) [Aug 27 08:10:50] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 2: CSeq: 102 CANCEL (16) [Aug 27 08:10:50] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 3: From: "3456" ;tag=as2ef5c824 (51) [Aug 27 08:10:50] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 4: To: ;tag=0308ab171239884 (47) [Aug 27 08:10:50] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 5: Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK4747e4d8;rport (63) [Aug 27 08:10:50] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 6: Content-Length: 0 (17) [Aug 27 08:10:50] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 7: Allow: INVITE, ACK, BYE, CANCEL, REFER, NOTIFY (46) [Aug 27 08:10:50] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 8: User-Agent: MxSipApp/5.0.23.153 MxSF/v3.2.2.4 (45) [Aug 27 08:10:50] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 9: (0) [Aug 27 08:10:50] --- (9 headers 0 lines) --- [Aug 27 08:10:50] DEBUG[17493]: chan_sip.c:4630 find_call: = Found Their Call ID: 3f0aedd05a010de95fe9a78a3e658faf@10.4.119.245 Their Tag d42dbfe2b2544b5 Our tag: as2ef5c824 [Aug 27 08:10:50] DEBUG[17493]: chan_sip.c:1921 retrans_pkt: SIP TIMER: Rescheduling retransmission #69 (2) CANCEL - 14 [Aug 27 08:10:50] DEBUG[17493]: chan_sip.c:1935 retrans_pkt: ** SIP timers: Rescheduling retransmission 3 to 400 ms (t1 100 ms (Retrans id #69)) [Aug 27 08:10:50] Retransmitting #2 (no NAT) to 10.4.119.185:5060: CANCEL sip:4567@10.4.119.185 SIP/2.0 Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK4747e4d8;rport From: "3456" ;tag=as2ef5c824 To: Call-ID: 3f0aedd05a010de95fe9a78a3e658faf@10.4.119.245 CSeq: 102 CANCEL User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- [Aug 27 08:10:50] <--- SIP read from 10.4.119.185:5060 ---> SIP/2.0 200 OK Call-ID: 3f0aedd05a010de95fe9a78a3e658faf@10.4.119.245 CSeq: 102 CANCEL From: "3456" ;tag=as2ef5c824 To: ;tag=0308ab171239884 Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK4747e4d8;rport Content-Length: 0 Allow: INVITE, ACK, BYE, CANCEL, REFER, NOTIFY User-Agent: MxSipApp/5.0.23.153 MxSF/v3.2.2.4 <-------------> [Aug 27 08:10:50] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 0: SIP/2.0 200 OK (14) [Aug 27 08:10:50] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 1: Call-ID: 3f0aedd05a010de95fe9a78a3e658faf@10.4.119.245 (54) [Aug 27 08:10:50] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 2: CSeq: 102 CANCEL (16) [Aug 27 08:10:50] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 3: From: "3456" ;tag=as2ef5c824 (51) [Aug 27 08:10:50] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 4: To: ;tag=0308ab171239884 (47) [Aug 27 08:10:50] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 5: Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK4747e4d8;rport (63) [Aug 27 08:10:50] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 6: Content-Length: 0 (17) [Aug 27 08:10:50] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 7: Allow: INVITE, ACK, BYE, CANCEL, REFER, NOTIFY (46) [Aug 27 08:10:50] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 8: User-Agent: MxSipApp/5.0.23.153 MxSF/v3.2.2.4 (45) [Aug 27 08:10:50] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 9: (0) [Aug 27 08:10:50] --- (9 headers 0 lines) --- [Aug 27 08:10:50] DEBUG[17493]: chan_sip.c:4630 find_call: = Found Their Call ID: 3f0aedd05a010de95fe9a78a3e658faf@10.4.119.245 Their Tag d42dbfe2b2544b5 Our tag: as2ef5c824 [Aug 27 08:10:50] DEBUG[17493]: chan_sip.c:1921 retrans_pkt: SIP TIMER: Rescheduling retransmission #69 (3) CANCEL - 14 [Aug 27 08:10:50] DEBUG[17493]: chan_sip.c:1935 retrans_pkt: ** SIP timers: Rescheduling retransmission 4 to 800 ms (t1 100 ms (Retrans id #69)) [Aug 27 08:10:50] Retransmitting #3 (no NAT) to 10.4.119.185:5060: CANCEL sip:4567@10.4.119.185 SIP/2.0 Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK4747e4d8;rport From: "3456" ;tag=as2ef5c824 To: Call-ID: 3f0aedd05a010de95fe9a78a3e658faf@10.4.119.245 CSeq: 102 CANCEL User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- [Aug 27 08:10:50] <--- SIP read from 10.4.119.185:5060 ---> SIP/2.0 200 OK Call-ID: 3f0aedd05a010de95fe9a78a3e658faf@10.4.119.245 CSeq: 102 CANCEL From: "3456" ;tag=as2ef5c824 To: ;tag=0308ab171239884 Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK4747e4d8;rport Content-Length: 0 Allow: INVITE, ACK, BYE, CANCEL, REFER, NOTIFY User-Agent: MxSipApp/5.0.23.153 MxSF/v3.2.2.4 <-------------> [Aug 27 08:10:50] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 0: SIP/2.0 200 OK (14) [Aug 27 08:10:50] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 1: Call-ID: 3f0aedd05a010de95fe9a78a3e658faf@10.4.119.245 (54) [Aug 27 08:10:50] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 2: CSeq: 102 CANCEL (16) [Aug 27 08:10:50] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 3: From: "3456" ;tag=as2ef5c824 (51) [Aug 27 08:10:50] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 4: To: ;tag=0308ab171239884 (47) [Aug 27 08:10:50] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 5: Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK4747e4d8;rport (63) [Aug 27 08:10:50] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 6: Content-Length: 0 (17) [Aug 27 08:10:50] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 7: Allow: INVITE, ACK, BYE, CANCEL, REFER, NOTIFY (46) [Aug 27 08:10:50] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 8: User-Agent: MxSipApp/5.0.23.153 MxSF/v3.2.2.4 (45) [Aug 27 08:10:50] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 9: (0) [Aug 27 08:10:50] --- (9 headers 0 lines) --- [Aug 27 08:10:50] DEBUG[17493]: chan_sip.c:4630 find_call: = Found Their Call ID: 3f0aedd05a010de95fe9a78a3e658faf@10.4.119.245 Their Tag d42dbfe2b2544b5 Our tag: as2ef5c824 [Aug 27 08:10:51] DEBUG[17493]: chan_sip.c:1921 retrans_pkt: SIP TIMER: Rescheduling retransmission #69 (4) CANCEL - 14 [Aug 27 08:10:51] DEBUG[17493]: chan_sip.c:1935 retrans_pkt: ** SIP timers: Rescheduling retransmission 5 to 1600 ms (t1 100 ms (Retrans id #69)) [Aug 27 08:10:51] Retransmitting #4 (no NAT) to 10.4.119.185:5060: CANCEL sip:4567@10.4.119.185 SIP/2.0 Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK4747e4d8;rport From: "3456" ;tag=as2ef5c824 To: Call-ID: 3f0aedd05a010de95fe9a78a3e658faf@10.4.119.245 CSeq: 102 CANCEL User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- [Aug 27 08:10:51] <--- SIP read from 10.4.119.185:5060 ---> SIP/2.0 200 OK Call-ID: 3f0aedd05a010de95fe9a78a3e658faf@10.4.119.245 CSeq: 102 CANCEL From: "3456" ;tag=as2ef5c824 To: ;tag=0308ab171239884 Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK4747e4d8;rport Content-Length: 0 Allow: INVITE, ACK, BYE, CANCEL, REFER, NOTIFY User-Agent: MxSipApp/5.0.23.153 MxSF/v3.2.2.4 <-------------> [Aug 27 08:10:51] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 0: SIP/2.0 200 OK (14) [Aug 27 08:10:51] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 1: Call-ID: 3f0aedd05a010de95fe9a78a3e658faf@10.4.119.245 (54) [Aug 27 08:10:51] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 2: CSeq: 102 CANCEL (16) [Aug 27 08:10:51] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 3: From: "3456" ;tag=as2ef5c824 (51) [Aug 27 08:10:51] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 4: To: ;tag=0308ab171239884 (47) [Aug 27 08:10:51] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 5: Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK4747e4d8;rport (63) [Aug 27 08:10:51] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 6: Content-Length: 0 (17) [Aug 27 08:10:51] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 7: Allow: INVITE, ACK, BYE, CANCEL, REFER, NOTIFY (46) [Aug 27 08:10:51] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 8: User-Agent: MxSipApp/5.0.23.153 MxSF/v3.2.2.4 (45) [Aug 27 08:10:51] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 9: (0) [Aug 27 08:10:51] --- (9 headers 0 lines) --- [Aug 27 08:10:51] DEBUG[17493]: chan_sip.c:4630 find_call: = Found Their Call ID: 3f0aedd05a010de95fe9a78a3e658faf@10.4.119.245 Their Tag d42dbfe2b2544b5 Our tag: as2ef5c824 [Aug 27 08:10:53] DEBUG[17493]: chan_sip.c:1921 retrans_pkt: SIP TIMER: Rescheduling retransmission #69 (5) CANCEL - 14 [Aug 27 08:10:53] DEBUG[17493]: chan_sip.c:1935 retrans_pkt: ** SIP timers: Rescheduling retransmission 6 to 3200 ms (t1 100 ms (Retrans id #69)) [Aug 27 08:10:53] Retransmitting #5 (no NAT) to 10.4.119.185:5060: CANCEL sip:4567@10.4.119.185 SIP/2.0 Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK4747e4d8;rport From: "3456" ;tag=as2ef5c824 To: Call-ID: 3f0aedd05a010de95fe9a78a3e658faf@10.4.119.245 CSeq: 102 CANCEL User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- [Aug 27 08:10:53] <--- SIP read from 10.4.119.185:5060 ---> SIP/2.0 200 OK Call-ID: 3f0aedd05a010de95fe9a78a3e658faf@10.4.119.245 CSeq: 102 CANCEL From: "3456" ;tag=as2ef5c824 To: ;tag=0308ab171239884 Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK4747e4d8;rport Content-Length: 0 Allow: INVITE, ACK, BYE, CANCEL, REFER, NOTIFY User-Agent: MxSipApp/5.0.23.153 MxSF/v3.2.2.4 <-------------> [Aug 27 08:10:53] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 0: SIP/2.0 200 OK (14) [Aug 27 08:10:53] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 1: Call-ID: 3f0aedd05a010de95fe9a78a3e658faf@10.4.119.245 (54) [Aug 27 08:10:53] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 2: CSeq: 102 CANCEL (16) [Aug 27 08:10:53] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 3: From: "3456" ;tag=as2ef5c824 (51) [Aug 27 08:10:53] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 4: To: ;tag=0308ab171239884 (47) [Aug 27 08:10:53] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 5: Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK4747e4d8;rport (63) [Aug 27 08:10:53] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 6: Content-Length: 0 (17) [Aug 27 08:10:53] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 7: Allow: INVITE, ACK, BYE, CANCEL, REFER, NOTIFY (46) [Aug 27 08:10:53] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 8: User-Agent: MxSipApp/5.0.23.153 MxSF/v3.2.2.4 (45) [Aug 27 08:10:53] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 9: (0) [Aug 27 08:10:53] --- (9 headers 0 lines) --- [Aug 27 08:10:53] DEBUG[17493]: chan_sip.c:4630 find_call: = Found Their Call ID: 3f0aedd05a010de95fe9a78a3e658faf@10.4.119.245 Their Tag d42dbfe2b2544b5 Our tag: as2ef5c824 [Aug 27 08:10:54] <--- SIP read from 10.4.119.185:5060 ---> REGISTER sip:10.4.119.245 SIP/2.0 Via: SIP/2.0/UDP 10.4.119.185;branch=z9hG4bKcdf88ee73 Content-Length: 0 To: sip:3456@10.4.119.245 From: sip:3456@10.4.119.245;tag=642a56e1e3a9a33 Call-ID: 57d1eeae36baecaf4bdbe3bf4b15dfcf@10.4.119.245 CSeq: 1704278852 REGISTER Contact: sip:3456@10.4.119.185 Authorization:Digest response="5ccdb991dcfd4c8d877c89c1faf16a5a",username="3456",realm="asterisk",nonce="01f3c18f",algorithm=MD5,uri="sip:10.4.119.245" User-Agent: MxSipApp/5.0.23.153 MxSF/v3.2.2.4 <-------------> [Aug 27 08:10:54] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 0: REGISTER sip:10.4.119.245 SIP/2.0 (33) [Aug 27 08:10:54] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 1: Via: SIP/2.0/UDP 10.4.119.185;branch=z9hG4bKcdf88ee73 (53) [Aug 27 08:10:54] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 2: Content-Length: 0 (17) [Aug 27 08:10:54] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 3: To: sip:3456@10.4.119.245 (25) [Aug 27 08:10:54] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 4: From: sip:3456@10.4.119.245;tag=642a56e1e3a9a33 (47) [Aug 27 08:10:54] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 5: Call-ID: 57d1eeae36baecaf4bdbe3bf4b15dfcf@10.4.119.245 (54) [Aug 27 08:10:54] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 6: CSeq: 1704278852 REGISTER (25) [Aug 27 08:10:54] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 7: Contact: sip:3456@10.4.119.185 (30) [Aug 27 08:10:54] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 8: Authorization:Digest response="5ccdb991dcfd4c8d877c89c1faf16a5a",username="3456",realm="asterisk",nonce="01f3c18f",algorithm=MD5,uri="sip:10.4.119.245" (151) [Aug 27 08:10:54] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 9: User-Agent: MxSipApp/5.0.23.153 MxSF/v3.2.2.4 (45) [Aug 27 08:10:54] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 10: (0) [Aug 27 08:10:54] --- (10 headers 0 lines) --- [Aug 27 08:10:54] DEBUG[17493]: chan_sip.c:4630 find_call: = No match Their Call ID: 3f0aedd05a010de95fe9a78a3e658faf@10.4.119.245 Their Tag d42dbfe2b2544b5 Our tag: as2ef5c824 [Aug 27 08:10:54] DEBUG[17493]: chan_sip.c:4577 sip_alloc: Allocating new SIP dialog for 57d1eeae36baecaf4bdbe3bf4b15dfcf@10.4.119.245 - REGISTER (No RTP) [Aug 27 08:10:54] DEBUG[17493]: chan_sip.c:15667 handle_request: **** Received REGISTER (2) - Command in SIP REGISTER [Aug 27 08:10:54] Using latest REGISTER request as basis request [Aug 27 08:10:54] Sending to 10.4.119.185 : 5060 (no NAT) [Aug 27 08:10:54] <--- Transmitting (no NAT) to 10.4.119.185:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.4.119.185;branch=z9hG4bKcdf88ee73;received=10.4.119.185 From: sip:3456@10.4.119.245;tag=642a56e1e3a9a33 To: sip:3456@10.4.119.245 Call-ID: 57d1eeae36baecaf4bdbe3bf4b15dfcf@10.4.119.245 CSeq: 1704278852 REGISTER User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Aug 27 08:10:54] <--- Transmitting (no NAT) to 10.4.119.185:5060 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 10.4.119.185;branch=z9hG4bKcdf88ee73;received=10.4.119.185 From: sip:3456@10.4.119.245;tag=642a56e1e3a9a33 To: sip:3456@10.4.119.245;tag=as5a6f79cc Call-ID: 57d1eeae36baecaf4bdbe3bf4b15dfcf@10.4.119.245 CSeq: 1704278852 REGISTER User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="3862d53b" Content-Length: 0 <------------> [Aug 27 08:10:54] Scheduling destruction of SIP dialog '57d1eeae36baecaf4bdbe3bf4b15dfcf@10.4.119.245' in 32000 ms (Method: REGISTER) [Aug 27 08:10:54] <--- SIP read from 10.4.119.185:5060 ---> REGISTER sip:10.4.119.245 SIP/2.0 Via: SIP/2.0/UDP 10.4.119.185;branch=z9hG4bK5835d8a6a Content-Length: 0 To: sip:4567@10.4.119.245 From: sip:4567@10.4.119.245;tag=9ac6c46621c17ab Call-ID: 38d5236af2114d261f5b5971a858a3ed@10.4.119.245 CSeq: 1481611036 REGISTER Contact: sip:4567@10.4.119.185 Authorization:Digest response="be4b1bd4288a6356fd729b297f2de73b",username="4567",realm="asterisk",nonce="3903caa1",algorithm=MD5,uri="sip:10.4.119.245" User-Agent: MxSipApp/5.0.23.153 MxSF/v3.2.2.4 <-------------> [Aug 27 08:10:54] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 0: REGISTER sip:10.4.119.245 SIP/2.0 (33) [Aug 27 08:10:54] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 1: Via: SIP/2.0/UDP 10.4.119.185;branch=z9hG4bK5835d8a6a (53) [Aug 27 08:10:54] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 2: Content-Length: 0 (17) [Aug 27 08:10:54] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 3: To: sip:4567@10.4.119.245 (25) [Aug 27 08:10:54] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 4: From: sip:4567@10.4.119.245;tag=9ac6c46621c17ab (47) [Aug 27 08:10:54] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 5: Call-ID: 38d5236af2114d261f5b5971a858a3ed@10.4.119.245 (54) [Aug 27 08:10:54] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 6: CSeq: 1481611036 REGISTER (25) [Aug 27 08:10:54] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 7: Contact: sip:4567@10.4.119.185 (30) [Aug 27 08:10:54] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 8: Authorization:Digest response="be4b1bd4288a6356fd729b297f2de73b",username="4567",realm="asterisk",nonce="3903caa1",algorithm=MD5,uri="sip:10.4.119.245" (151) [Aug 27 08:10:54] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 9: User-Agent: MxSipApp/5.0.23.153 MxSF/v3.2.2.4 (45) [Aug 27 08:10:54] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 10: (0) [Aug 27 08:10:54] --- (10 headers 0 lines) --- [Aug 27 08:10:54] DEBUG[17493]: chan_sip.c:4630 find_call: = No match Their Call ID: 57d1eeae36baecaf4bdbe3bf4b15dfcf@10.4.119.245 Their Tag 642a56e1e3a9a33 Our tag: as5a6f79cc [Aug 27 08:10:54] DEBUG[17493]: chan_sip.c:4630 find_call: = No match Their Call ID: 3f0aedd05a010de95fe9a78a3e658faf@10.4.119.245 Their Tag d42dbfe2b2544b5 Our tag: as2ef5c824 [Aug 27 08:10:54] DEBUG[17493]: chan_sip.c:4577 sip_alloc: Allocating new SIP dialog for 38d5236af2114d261f5b5971a858a3ed@10.4.119.245 - REGISTER (No RTP) [Aug 27 08:10:54] DEBUG[17493]: chan_sip.c:15667 handle_request: **** Received REGISTER (2) - Command in SIP REGISTER [Aug 27 08:10:54] Using latest REGISTER request as basis request [Aug 27 08:10:54] Sending to 10.4.119.185 : 5060 (no NAT) [Aug 27 08:10:54] <--- Transmitting (no NAT) to 10.4.119.185:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.4.119.185;branch=z9hG4bK5835d8a6a;received=10.4.119.185 From: sip:4567@10.4.119.245;tag=9ac6c46621c17ab To: sip:4567@10.4.119.245 Call-ID: 38d5236af2114d261f5b5971a858a3ed@10.4.119.245 CSeq: 1481611036 REGISTER User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Aug 27 08:10:54] <--- Transmitting (no NAT) to 10.4.119.185:5060 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 10.4.119.185;branch=z9hG4bK5835d8a6a;received=10.4.119.185 From: sip:4567@10.4.119.245;tag=9ac6c46621c17ab To: sip:4567@10.4.119.245;tag=as1ae2828b Call-ID: 38d5236af2114d261f5b5971a858a3ed@10.4.119.245 CSeq: 1481611036 REGISTER User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="048d9549" Content-Length: 0 <------------> [Aug 27 08:10:54] Scheduling destruction of SIP dialog '38d5236af2114d261f5b5971a858a3ed@10.4.119.245' in 32000 ms (Method: REGISTER) [Aug 27 08:10:54] <--- SIP read from 10.4.119.185:5060 ---> REGISTER sip:10.4.119.245 SIP/2.0 Via: SIP/2.0/UDP 10.4.119.185;branch=z9hG4bKbeac32fd8 Content-Length: 0 To: sip:3456@10.4.119.245 From: sip:3456@10.4.119.245;tag=642a56e1e3a9a33 Call-ID: 57d1eeae36baecaf4bdbe3bf4b15dfcf@10.4.119.245 CSeq: 1704278853 REGISTER Contact: sip:3456@10.4.119.185 Authorization:Digest response="19144572810ed3aacfd48b170cb31a4f",username="3456",realm="asterisk",nonce="3862d53b",algorithm=MD5,uri="sip:10.4.119.245" User-Agent: MxSipApp/5.0.23.153 MxSF/v3.2.2.4 <-------------> [Aug 27 08:10:54] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 0: REGISTER sip:10.4.119.245 SIP/2.0 (33) [Aug 27 08:10:54] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 1: Via: SIP/2.0/UDP 10.4.119.185;branch=z9hG4bKbeac32fd8 (53) [Aug 27 08:10:54] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 2: Content-Length: 0 (17) [Aug 27 08:10:54] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 3: To: sip:3456@10.4.119.245 (25) [Aug 27 08:10:54] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 4: From: sip:3456@10.4.119.245;tag=642a56e1e3a9a33 (47) [Aug 27 08:10:54] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 5: Call-ID: 57d1eeae36baecaf4bdbe3bf4b15dfcf@10.4.119.245 (54) [Aug 27 08:10:54] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 6: CSeq: 1704278853 REGISTER (25) [Aug 27 08:10:54] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 7: Contact: sip:3456@10.4.119.185 (30) [Aug 27 08:10:54] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 8: Authorization:Digest response="19144572810ed3aacfd48b170cb31a4f",username="3456",realm="asterisk",nonce="3862d53b",algorithm=MD5,uri="sip:10.4.119.245" (151) [Aug 27 08:10:54] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 9: User-Agent: MxSipApp/5.0.23.153 MxSF/v3.2.2.4 (45) [Aug 27 08:10:54] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 10: (0) [Aug 27 08:10:54] --- (10 headers 0 lines) --- [Aug 27 08:10:54] DEBUG[17493]: chan_sip.c:4630 find_call: = No match Their Call ID: 38d5236af2114d261f5b5971a858a3ed@10.4.119.245 Their Tag 9ac6c46621c17ab Our tag: as1ae2828b [Aug 27 08:10:54] DEBUG[17493]: chan_sip.c:4630 find_call: = Found Their Call ID: 57d1eeae36baecaf4bdbe3bf4b15dfcf@10.4.119.245 Their Tag 642a56e1e3a9a33 Our tag: as5a6f79cc [Aug 27 08:10:54] DEBUG[17493]: chan_sip.c:15667 handle_request: **** Received REGISTER (2) - Command in SIP REGISTER [Aug 27 08:10:54] Using latest REGISTER request as basis request [Aug 27 08:10:54] Sending to 10.4.119.185 : 5060 (no NAT) [Aug 27 08:10:54] <--- Transmitting (no NAT) to 10.4.119.185:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.4.119.185;branch=z9hG4bKbeac32fd8;received=10.4.119.185 From: sip:3456@10.4.119.245;tag=642a56e1e3a9a33 To: sip:3456@10.4.119.245 Call-ID: 57d1eeae36baecaf4bdbe3bf4b15dfcf@10.4.119.245 CSeq: 1704278853 REGISTER User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Aug 27 08:10:54] -- Saved useragent "MxSipApp/5.0.23.153 MxSF/v3.2.2.4" for peer 3456 [Aug 27 08:10:54] <--- Transmitting (no NAT) to 10.4.119.185:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.4.119.185;branch=z9hG4bKbeac32fd8;received=10.4.119.185 From: sip:3456@10.4.119.245;tag=642a56e1e3a9a33 To: sip:3456@10.4.119.245;tag=as5a6f79cc Call-ID: 57d1eeae36baecaf4bdbe3bf4b15dfcf@10.4.119.245 CSeq: 1704278853 REGISTER User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Expires: 120 Contact: ;expires=120 Date: Wed, 27 Aug 2008 12:10:54 GMT Content-Length: 0 <------------> [Aug 27 08:10:54] DEBUG[17493]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/3456 [Aug 27 08:10:54] Scheduling destruction of SIP dialog '57d1eeae36baecaf4bdbe3bf4b15dfcf@10.4.119.245' in 32000 ms (Method: REGISTER) [Aug 27 08:10:54] <--- SIP read from 10.4.119.185:5060 ---> REGISTER sip:10.4.119.245 SIP/2.0 Via: SIP/2.0/UDP 10.4.119.185;branch=z9hG4bKf6d4b12cf Content-Length: 0 To: sip:4567@10.4.119.245 From: sip:4567@10.4.119.245;tag=9ac6c46621c17ab Call-ID: 38d5236af2114d261f5b5971a858a3ed@10.4.119.245 CSeq: 1481611037 REGISTER Contact: sip:4567@10.4.119.185 Authorization:Digest response="e6c144e854c5dc4a3feea863ad28935c",username="4567",realm="asterisk",nonce="048d9549",algorithm=MD5,uri="sip:10.4.119.245" User-Agent: MxSipApp/5.0.23.153 MxSF/v3.2.2.4 <-------------> [Aug 27 08:10:54] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 0: REGISTER sip:10.4.119.245 SIP/2.0 (33) [Aug 27 08:10:54] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 1: Via: SIP/2.0/UDP 10.4.119.185;branch=z9hG4bKf6d4b12cf (53) [Aug 27 08:10:54] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 2: Content-Length: 0 (17) [Aug 27 08:10:54] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 3: To: sip:4567@10.4.119.245 (25) [Aug 27 08:10:54] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 4: From: sip:4567@10.4.119.245;tag=9ac6c46621c17ab (47) [Aug 27 08:10:54] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 5: Call-ID: 38d5236af2114d261f5b5971a858a3ed@10.4.119.245 (54) [Aug 27 08:10:54] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 6: CSeq: 1481611037 REGISTER (25) [Aug 27 08:10:54] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 7: Contact: sip:4567@10.4.119.185 (30) [Aug 27 08:10:54] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 8: Authorization:Digest response="e6c144e854c5dc4a3feea863ad28935c",username="4567",realm="asterisk",nonce="048d9549",algorithm=MD5,uri="sip:10.4.119.245" (151) [Aug 27 08:10:54] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 9: User-Agent: MxSipApp/5.0.23.153 MxSF/v3.2.2.4 (45) [Aug 27 08:10:54] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 10: (0) [Aug 27 08:10:54] --- (10 headers 0 lines) --- [Aug 27 08:10:54] DEBUG[17493]: chan_sip.c:4630 find_call: = Found Their Call ID: 38d5236af2114d261f5b5971a858a3ed@10.4.119.245 Their Tag 9ac6c46621c17ab Our tag: as1ae2828b [Aug 27 08:10:54] DEBUG[17493]: chan_sip.c:15667 handle_request: **** Received REGISTER (2) - Command in SIP REGISTER [Aug 27 08:10:54] Using latest REGISTER request as basis request [Aug 27 08:10:54] Sending to 10.4.119.185 : 5060 (no NAT) [Aug 27 08:10:54] <--- Transmitting (no NAT) to 10.4.119.185:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.4.119.185;branch=z9hG4bKf6d4b12cf;received=10.4.119.185 From: sip:4567@10.4.119.245;tag=9ac6c46621c17ab To: sip:4567@10.4.119.245 Call-ID: 38d5236af2114d261f5b5971a858a3ed@10.4.119.245 CSeq: 1481611037 REGISTER User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Aug 27 08:10:54] DEBUG[17483]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 3456 [Aug 27 08:10:54] DEBUG[17483]: chan_sip.c:16345 sip_devicestate: Checking device state for peer 3456 [Aug 27 08:10:54] DEBUG[17483]: devicestate.c:287 do_state_change: Changing state for SIP/3456 - state 1 (Not in use) [Aug 27 08:10:54] DEBUG[17492]: app_queue.c:661 handle_statechange: Device 'SIP/3456' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Aug 27 08:10:54] -- Saved useragent "MxSipApp/5.0.23.153 MxSF/v3.2.2.4" for peer 4567 [Aug 27 08:10:54] <--- Transmitting (no NAT) to 10.4.119.185:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.4.119.185;branch=z9hG4bKf6d4b12cf;received=10.4.119.185 From: sip:4567@10.4.119.245;tag=9ac6c46621c17ab To: sip:4567@10.4.119.245;tag=as1ae2828b Call-ID: 38d5236af2114d261f5b5971a858a3ed@10.4.119.245 CSeq: 1481611037 REGISTER User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Expires: 120 Contact: ;expires=120 Date: Wed, 27 Aug 2008 12:10:54 GMT Content-Length: 0 <------------> [Aug 27 08:10:54] DEBUG[17493]: devicestate.c:302 ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/4567 [Aug 27 08:10:54] Scheduling destruction of SIP dialog '38d5236af2114d261f5b5971a858a3ed@10.4.119.245' in 32000 ms (Method: REGISTER) [Aug 27 08:10:54] DEBUG[17483]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 4567 [Aug 27 08:10:54] DEBUG[17483]: chan_sip.c:16345 sip_devicestate: Checking device state for peer 4567 [Aug 27 08:10:54] DEBUG[17483]: devicestate.c:287 do_state_change: Changing state for SIP/4567 - state 1 (Not in use) [Aug 27 08:10:54] DEBUG[17492]: app_queue.c:661 handle_statechange: Device 'SIP/4567' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Aug 27 08:10:56] DEBUG[17493]: chan_sip.c:1921 retrans_pkt: SIP TIMER: Rescheduling retransmission #69 (6) CANCEL - 14 [Aug 27 08:10:56] DEBUG[17493]: chan_sip.c:1935 retrans_pkt: ** SIP timers: Rescheduling retransmission 7 to 4000 ms (t1 100 ms (Retrans id #69)) [Aug 27 08:10:56] Retransmitting #6 (no NAT) to 10.4.119.185:5060: CANCEL sip:4567@10.4.119.185 SIP/2.0 Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK4747e4d8;rport From: "3456" ;tag=as2ef5c824 To: Call-ID: 3f0aedd05a010de95fe9a78a3e658faf@10.4.119.245 CSeq: 102 CANCEL User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- [Aug 27 08:10:56] DEBUG[17493]: chan_sip.c:2090 __sip_autodestruct: Re-scheduled destruction of SIP call 3f0aedd05a010de95fe9a78a3e658faf@10.4.119.245 [Aug 27 08:10:56] <--- SIP read from 10.4.119.185:5060 ---> SIP/2.0 200 OK Call-ID: 3f0aedd05a010de95fe9a78a3e658faf@10.4.119.245 CSeq: 102 CANCEL From: "3456" ;tag=as2ef5c824 To: ;tag=0308ab171239884 Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK4747e4d8;rport Content-Length: 0 Allow: INVITE, ACK, BYE, CANCEL, REFER, NOTIFY User-Agent: MxSipApp/5.0.23.153 MxSF/v3.2.2.4 <-------------> [Aug 27 08:10:56] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 0: SIP/2.0 200 OK (14) [Aug 27 08:10:56] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 1: Call-ID: 3f0aedd05a010de95fe9a78a3e658faf@10.4.119.245 (54) [Aug 27 08:10:56] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 2: CSeq: 102 CANCEL (16) [Aug 27 08:10:56] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 3: From: "3456" ;tag=as2ef5c824 (51) [Aug 27 08:10:56] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 4: To: ;tag=0308ab171239884 (47) [Aug 27 08:10:56] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 5: Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK4747e4d8;rport (63) [Aug 27 08:10:56] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 6: Content-Length: 0 (17) [Aug 27 08:10:56] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 7: Allow: INVITE, ACK, BYE, CANCEL, REFER, NOTIFY (46) [Aug 27 08:10:56] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 8: User-Agent: MxSipApp/5.0.23.153 MxSF/v3.2.2.4 (45) [Aug 27 08:10:56] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 9: (0) [Aug 27 08:10:56] --- (9 headers 0 lines) --- [Aug 27 08:10:56] DEBUG[17493]: chan_sip.c:4630 find_call: = No match Their Call ID: 38d5236af2114d261f5b5971a858a3ed@10.4.119.245 Their Tag 9ac6c46621c17ab Our tag: as1ae2828b [Aug 27 08:10:56] DEBUG[17493]: chan_sip.c:4630 find_call: = No match Their Call ID: 57d1eeae36baecaf4bdbe3bf4b15dfcf@10.4.119.245 Their Tag 642a56e1e3a9a33 Our tag: as5a6f79cc [Aug 27 08:10:56] DEBUG[17493]: chan_sip.c:4630 find_call: = Found Their Call ID: 3f0aedd05a010de95fe9a78a3e658faf@10.4.119.245 Their Tag d42dbfe2b2544b5 Our tag: as2ef5c824 [Aug 27 08:10:59] DEBUG[17493]: chan_sip.c:4577 sip_alloc: Allocating new SIP dialog for (No Call-ID) - NOTIFY (No RTP) [Aug 27 08:10:59] Scheduling destruction of SIP dialog '4e0573ff0c65d2b374cb1486599e4319@10.4.119.245' in 6400 ms (Method: NOTIFY) [Aug 27 08:10:59] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 0: NOTIFY sip:4567@10.4.119.185 SIP/2.0 (36) [Aug 27 08:10:59] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 1: Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK2372607a;rport (63) [Aug 27 08:10:59] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 2: From: "asterisk" ;tag=as489a3097 (59) [Aug 27 08:10:59] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 3: To: (27) [Aug 27 08:10:59] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 4: Contact: (36) [Aug 27 08:10:59] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 5: Call-ID: 4e0573ff0c65d2b374cb1486599e4319@10.4.119.245 (54) [Aug 27 08:10:59] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 6: CSeq: 102 NOTIFY (16) [Aug 27 08:10:59] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 7: User-Agent: Asterisk PBX (24) [Aug 27 08:10:59] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 8: Max-Forwards: 70 (16) [Aug 27 08:10:59] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 9: Event: message-summary (22) [Aug 27 08:10:59] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 10: Content-Type: application/simple-message-summary (48) [Aug 27 08:10:59] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 11: Content-Length: 92 (18) [Aug 27 08:10:59] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 12: (0) [Aug 27 08:10:59] DEBUG[17493]: chan_sip.c:4872 parse_request: Line: Messages-Waiting: no (20) [Aug 27 08:10:59] DEBUG[17493]: chan_sip.c:4872 parse_request: Line: Message-Account: sip:asterisk@10.4.119.245 (42) [Aug 27 08:10:59] DEBUG[17493]: chan_sip.c:4872 parse_request: Line: Voice-Message: 0/0 (0/0) (24) [Aug 27 08:10:59] Reliably Transmitting (no NAT) to 10.4.119.185:5060: NOTIFY sip:4567@10.4.119.185 SIP/2.0 Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK2372607a;rport From: "asterisk" ;tag=as489a3097 To: Contact: Call-ID: 4e0573ff0c65d2b374cb1486599e4319@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) --- [Aug 27 08:10:59] DEBUG[17493]: chan_sip.c:2051 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #-1 [Aug 27 08:10:59] DEBUG[17493]: chan_sip.c:4577 sip_alloc: Allocating new SIP dialog for (No Call-ID) - NOTIFY (No RTP) [Aug 27 08:10:59] Scheduling destruction of SIP dialog '65a482963c4a708f6a11000b25974cb2@10.4.119.245' in 6400 ms (Method: NOTIFY) [Aug 27 08:10:59] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 0: NOTIFY sip:3456@10.4.119.185 SIP/2.0 (36) [Aug 27 08:10:59] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 1: Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK5e998ebf;rport (63) [Aug 27 08:10:59] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 2: From: "asterisk" ;tag=as42199f42 (59) [Aug 27 08:10:59] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 3: To: (27) [Aug 27 08:10:59] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 4: Contact: (36) [Aug 27 08:10:59] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 5: Call-ID: 65a482963c4a708f6a11000b25974cb2@10.4.119.245 (54) [Aug 27 08:10:59] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 6: CSeq: 102 NOTIFY (16) [Aug 27 08:10:59] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 7: User-Agent: Asterisk PBX (24) [Aug 27 08:10:59] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 8: Max-Forwards: 70 (16) [Aug 27 08:10:59] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 9: Event: message-summary (22) [Aug 27 08:10:59] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 10: Content-Type: application/simple-message-summary (48) [Aug 27 08:10:59] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 11: Content-Length: 92 (18) [Aug 27 08:10:59] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 12: (0) [Aug 27 08:10:59] DEBUG[17493]: chan_sip.c:4872 parse_request: Line: Messages-Waiting: no (20) [Aug 27 08:10:59] DEBUG[17493]: chan_sip.c:4872 parse_request: Line: Message-Account: sip:asterisk@10.4.119.245 (42) [Aug 27 08:10:59] DEBUG[17493]: chan_sip.c:4872 parse_request: Line: Voice-Message: 0/0 (0/0) (24) [Aug 27 08:10:59] Reliably Transmitting (no NAT) to 10.4.119.185:5060: NOTIFY sip:3456@10.4.119.185 SIP/2.0 Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK5e998ebf;rport From: "asterisk" ;tag=as42199f42 To: Contact: Call-ID: 65a482963c4a708f6a11000b25974cb2@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) --- [Aug 27 08:10:59] DEBUG[17493]: chan_sip.c:2051 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #-1 [Aug 27 08:10:59] <--- SIP read from 10.4.119.185:5060 ---> SIP/2.0 200 OK Call-ID: 4e0573ff0c65d2b374cb1486599e4319@10.4.119.245 CSeq: 102 NOTIFY From: "asterisk" ;tag=as489a3097 To: ;tag=e0b9e306ea310d0 Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK2372607a;rport Content-Length: 0 User-Agent: MxSipApp/5.0.23.153 MxSF/v3.2.2.4 <-------------> [Aug 27 08:10:59] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 0: SIP/2.0 200 OK (14) [Aug 27 08:10:59] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 1: Call-ID: 4e0573ff0c65d2b374cb1486599e4319@10.4.119.245 (54) [Aug 27 08:10:59] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 2: CSeq: 102 NOTIFY (16) [Aug 27 08:10:59] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 3: From: "asterisk" ;tag=as489a3097 (59) [Aug 27 08:10:59] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 4: To: ;tag=e0b9e306ea310d0 (47) [Aug 27 08:10:59] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 5: Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK2372607a;rport (63) [Aug 27 08:10:59] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 6: Content-Length: 0 (17) [Aug 27 08:10:59] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 7: User-Agent: MxSipApp/5.0.23.153 MxSF/v3.2.2.4 (45) [Aug 27 08:10:59] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 8: (0) [Aug 27 08:10:59] --- (8 headers 0 lines) --- [Aug 27 08:10:59] DEBUG[17493]: chan_sip.c:4630 find_call: = No match Their Call ID: 65a482963c4a708f6a11000b25974cb2@10.4.119.245 Their Tag Our tag: as42199f42 [Aug 27 08:10:59] DEBUG[17493]: chan_sip.c:4630 find_call: = Found Their Call ID: 4e0573ff0c65d2b374cb1486599e4319@10.4.119.245 Their Tag Our tag: as489a3097 [Aug 27 08:10:59] DEBUG[17493]: chan_sip.c:2174 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #78 [Aug 27 08:10:59] DEBUG[17493]: chan_sip.c:2200 __sip_ack: Stopping retransmission on '4e0573ff0c65d2b374cb1486599e4319@10.4.119.245' of Request 102: Match Found [Aug 27 08:10:59] Really destroying SIP dialog '4e0573ff0c65d2b374cb1486599e4319@10.4.119.245' Method: NOTIFY [Aug 27 08:10:59] <--- SIP read from 10.4.119.185:5060 ---> SIP/2.0 200 OK Call-ID: 65a482963c4a708f6a11000b25974cb2@10.4.119.245 CSeq: 102 NOTIFY From: "asterisk" ;tag=as42199f42 To: ;tag=ec6d11e36e4ae5c Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK5e998ebf;rport Content-Length: 0 User-Agent: MxSipApp/5.0.23.153 MxSF/v3.2.2.4 <-------------> [Aug 27 08:10:59] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 0: SIP/2.0 200 OK (14) [Aug 27 08:10:59] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 1: Call-ID: 65a482963c4a708f6a11000b25974cb2@10.4.119.245 (54) [Aug 27 08:10:59] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 2: CSeq: 102 NOTIFY (16) [Aug 27 08:10:59] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 3: From: "asterisk" ;tag=as42199f42 (59) [Aug 27 08:10:59] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 4: To: ;tag=ec6d11e36e4ae5c (47) [Aug 27 08:10:59] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 5: Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK5e998ebf;rport (63) [Aug 27 08:10:59] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 6: Content-Length: 0 (17) [Aug 27 08:10:59] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 7: User-Agent: MxSipApp/5.0.23.153 MxSF/v3.2.2.4 (45) [Aug 27 08:10:59] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 8: (0) [Aug 27 08:10:59] --- (8 headers 0 lines) --- [Aug 27 08:10:59] DEBUG[17493]: chan_sip.c:4630 find_call: = Found Their Call ID: 65a482963c4a708f6a11000b25974cb2@10.4.119.245 Their Tag Our tag: as42199f42 [Aug 27 08:10:59] DEBUG[17493]: chan_sip.c:2174 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #80 [Aug 27 08:10:59] DEBUG[17493]: chan_sip.c:2200 __sip_ack: Stopping retransmission on '65a482963c4a708f6a11000b25974cb2@10.4.119.245' of Request 102: Match Found [Aug 27 08:10:59] Really destroying SIP dialog '65a482963c4a708f6a11000b25974cb2@10.4.119.245' Method: NOTIFY [Aug 27 08:11:00] WARNING[17493]: chan_sip.c:1957 retrans_pkt: Maximum retries exceeded on transmission 3f0aedd05a010de95fe9a78a3e658faf@10.4.119.245 for seqno 102 (Non-critical Request) -- See doc/sip-retransmit.txt. [Aug 27 08:11:02] DEBUG[17493]: chan_sip.c:2103 __sip_autodestruct: Auto destroying SIP dialog '3f0aedd05a010de95fe9a78a3e658faf@10.4.119.245' [Aug 27 08:11:02] DEBUG[17493]: chan_sip.c:3328 sip_destroy: Destroying SIP dialog 3f0aedd05a010de95fe9a78a3e658faf@10.4.119.245 [Aug 27 08:11:02] Really destroying SIP dialog '3f0aedd05a010de95fe9a78a3e658faf@10.4.119.245' Method: INVITE [Aug 27 08:11:09] <--- SIP read from 10.4.119.185:5060 ---> SIP/2.0 200 OK Call-ID: 3f0aedd05a010de95fe9a78a3e658faf@10.4.119.245 CSeq: 102 INVITE From: "3456" ;tag=as2ef5c824 To: ;tag=d42dbfe2b2544b5 Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK102075c8;rport Content-Length: 166 Session-Expires: 3600;refresher=uas Allow: INVITE, ACK, BYE, CANCEL, REFER, NOTIFY Content-Type: application/sdp Supported: replaces Contact: sip:4567@10.4.119.185 User-Agent: MxSipApp/5.0.23.153 MxSF/v3.2.2.4 v=0 o=MxSIP 722671107143209825 1614369397284502047 IN IP4 10.4.119.185 s=- c=IN IP4 10.4.119.185 t=0 0 a=sendrecv m=audio 5006 RTP/AVP 0 a=rtpmap:0 PCMU/8000 <-------------> [Aug 27 08:11:09] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 0: SIP/2.0 200 OK (14) [Aug 27 08:11:09] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 1: Call-ID: 3f0aedd05a010de95fe9a78a3e658faf@10.4.119.245 (54) [Aug 27 08:11:09] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 2: CSeq: 102 INVITE (16) [Aug 27 08:11:09] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 3: From: "3456" ;tag=as2ef5c824 (51) [Aug 27 08:11:09] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 4: To: ;tag=d42dbfe2b2544b5 (47) [Aug 27 08:11:09] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 5: Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK102075c8;rport (63) [Aug 27 08:11:09] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 6: Content-Length: 166 (19) [Aug 27 08:11:09] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 7: Session-Expires: 3600;refresher=uas (35) [Aug 27 08:11:09] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 8: Allow: INVITE, ACK, BYE, CANCEL, REFER, NOTIFY (46) [Aug 27 08:11:09] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 9: Content-Type: application/sdp (29) [Aug 27 08:11:09] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 10: Supported: replaces (19) [Aug 27 08:11:09] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 11: Contact: sip:4567@10.4.119.185 (30) [Aug 27 08:11:09] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 12: User-Agent: MxSipApp/5.0.23.153 MxSF/v3.2.2.4 (45) [Aug 27 08:11:09] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 13: (0) [Aug 27 08:11:09] DEBUG[17493]: chan_sip.c:4872 parse_request: Line: v=0 (3) [Aug 27 08:11:09] DEBUG[17493]: chan_sip.c:4872 parse_request: Line: o=MxSIP 722671107143209825 1614369397284502047 IN IP4 10.4.119.185 (66) [Aug 27 08:11:09] DEBUG[17493]: chan_sip.c:4872 parse_request: Line: s=- (3) [Aug 27 08:11:09] DEBUG[17493]: chan_sip.c:4872 parse_request: Line: c=IN IP4 10.4.119.185 (21) [Aug 27 08:11:09] DEBUG[17493]: chan_sip.c:4872 parse_request: Line: t=0 0 (5) [Aug 27 08:11:09] DEBUG[17493]: chan_sip.c:4872 parse_request: Line: a=sendrecv (10) [Aug 27 08:11:09] DEBUG[17493]: chan_sip.c:4872 parse_request: Line: m=audio 5006 RTP/AVP 0 (22) [Aug 27 08:11:09] DEBUG[17493]: chan_sip.c:4872 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Aug 27 08:11:09] --- (13 headers 8 lines) --- [Aug 27 08:11:09] DEBUG[17493]: chan_sip.c:4630 find_call: = No match Their Call ID: 38d5236af2114d261f5b5971a858a3ed@10.4.119.245 Their Tag 9ac6c46621c17ab Our tag: as1ae2828b [Aug 27 08:11:09] DEBUG[17493]: chan_sip.c:4630 find_call: = No match Their Call ID: 57d1eeae36baecaf4bdbe3bf4b15dfcf@10.4.119.245 Their Tag 642a56e1e3a9a33 Our tag: as5a6f79cc [Aug 27 08:11:09] DEBUG[17493]: chan_sip.c:15857 sipsock_read: Invalid SIP message - rejected , no callid, len 662 [Aug 27 08:11:09] <--- SIP read from 10.4.119.185:5060 ---> SIP/2.0 200 OK Call-ID: 3f0aedd05a010de95fe9a78a3e658faf@10.4.119.245 CSeq: 102 INVITE From: "3456" ;tag=as2ef5c824 To: ;tag=d42dbfe2b2544b5 Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK102075c8;rport Content-Length: 166 Session-Expires: 3600;refresher=uas Allow: INVITE, ACK, BYE, CANCEL, REFER, NOTIFY Content-Type: application/sdp Supported: replaces Contact: sip:4567@10.4.119.185 User-Agent: MxSipApp/5.0.23.153 MxSF/v3.2.2.4 v=0 o=MxSIP 722671107143209825 1614369397284502047 IN IP4 10.4.119.185 s=- c=IN IP4 10.4.119.185 t=0 0 a=sendrecv m=audio 5006 RTP/AVP 0 a=rtpmap:0 PCMU/8000 <-------------> [Aug 27 08:11:09] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 0: SIP/2.0 200 OK (14) [Aug 27 08:11:09] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 1: Call-ID: 3f0aedd05a010de95fe9a78a3e658faf@10.4.119.245 (54) [Aug 27 08:11:09] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 2: CSeq: 102 INVITE (16) [Aug 27 08:11:09] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 3: From: "3456" ;tag=as2ef5c824 (51) [Aug 27 08:11:09] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 4: To: ;tag=d42dbfe2b2544b5 (47) [Aug 27 08:11:09] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 5: Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK102075c8;rport (63) [Aug 27 08:11:09] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 6: Content-Length: 166 (19) [Aug 27 08:11:09] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 7: Session-Expires: 3600;refresher=uas (35) [Aug 27 08:11:09] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 8: Allow: INVITE, ACK, BYE, CANCEL, REFER, NOTIFY (46) [Aug 27 08:11:09] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 9: Content-Type: application/sdp (29) [Aug 27 08:11:09] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 10: Supported: replaces (19) [Aug 27 08:11:09] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 11: Contact: sip:4567@10.4.119.185 (30) [Aug 27 08:11:09] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 12: User-Agent: MxSipApp/5.0.23.153 MxSF/v3.2.2.4 (45) [Aug 27 08:11:09] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 13: (0) [Aug 27 08:11:09] DEBUG[17493]: chan_sip.c:4872 parse_request: Line: v=0 (3) [Aug 27 08:11:09] DEBUG[17493]: chan_sip.c:4872 parse_request: Line: o=MxSIP 722671107143209825 1614369397284502047 IN IP4 10.4.119.185 (66) [Aug 27 08:11:09] DEBUG[17493]: chan_sip.c:4872 parse_request: Line: s=- (3) [Aug 27 08:11:09] DEBUG[17493]: chan_sip.c:4872 parse_request: Line: c=IN IP4 10.4.119.185 (21) [Aug 27 08:11:09] DEBUG[17493]: chan_sip.c:4872 parse_request: Line: t=0 0 (5) [Aug 27 08:11:09] DEBUG[17493]: chan_sip.c:4872 parse_request: Line: a=sendrecv (10) [Aug 27 08:11:09] DEBUG[17493]: chan_sip.c:4872 parse_request: Line: m=audio 5006 RTP/AVP 0 (22) [Aug 27 08:11:09] DEBUG[17493]: chan_sip.c:4872 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Aug 27 08:11:09] --- (13 headers 8 lines) --- [Aug 27 08:11:09] DEBUG[17493]: chan_sip.c:4630 find_call: = No match Their Call ID: 38d5236af2114d261f5b5971a858a3ed@10.4.119.245 Their Tag 9ac6c46621c17ab Our tag: as1ae2828b [Aug 27 08:11:09] DEBUG[17493]: chan_sip.c:4630 find_call: = No match Their Call ID: 57d1eeae36baecaf4bdbe3bf4b15dfcf@10.4.119.245 Their Tag 642a56e1e3a9a33 Our tag: as5a6f79cc [Aug 27 08:11:09] DEBUG[17493]: chan_sip.c:15857 sipsock_read: Invalid SIP message - rejected , no callid, len 662 [Aug 27 08:11:10] <--- SIP read from 10.4.119.185:5060 ---> SIP/2.0 200 OK Call-ID: 3f0aedd05a010de95fe9a78a3e658faf@10.4.119.245 CSeq: 102 INVITE From: "3456" ;tag=as2ef5c824 To: ;tag=d42dbfe2b2544b5 Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK102075c8;rport Content-Length: 166 Session-Expires: 3600;refresher=uas Allow: INVITE, ACK, BYE, CANCEL, REFER, NOTIFY Content-Type: application/sdp Supported: replaces Contact: sip:4567@10.4.119.185 User-Agent: MxSipApp/5.0.23.153 MxSF/v3.2.2.4 v=0 o=MxSIP 722671107143209825 1614369397284502047 IN IP4 10.4.119.185 s=- c=IN IP4 10.4.119.185 t=0 0 a=sendrecv m=audio 5006 RTP/AVP 0 a=rtpmap:0 PCMU/8000 <-------------> [Aug 27 08:11:10] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 0: SIP/2.0 200 OK (14) [Aug 27 08:11:10] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 1: Call-ID: 3f0aedd05a010de95fe9a78a3e658faf@10.4.119.245 (54) [Aug 27 08:11:10] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 2: CSeq: 102 INVITE (16) [Aug 27 08:11:10] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 3: From: "3456" ;tag=as2ef5c824 (51) [Aug 27 08:11:10] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 4: To: ;tag=d42dbfe2b2544b5 (47) [Aug 27 08:11:10] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 5: Via: SIP/2.0/UDP 10.4.119.245:5060;branch=z9hG4bK102075c8;rport (63) [Aug 27 08:11:10] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 6: Content-Length: 166 (19) [Aug 27 08:11:10] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 7: Session-Expires: 3600;refresher=uas (35) [Aug 27 08:11:10] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 8: Allow: INVITE, ACK, BYE, CANCEL, REFER, NOTIFY (46) [Aug 27 08:11:10] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 9: Content-Type: application/sdp (29) [Aug 27 08:11:10] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 10: Supported: replaces (19) [Aug 27 08:11:10] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 11: Contact: sip:4567@10.4.119.185 (30) [Aug 27 08:11:10] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 12: User-Agent: MxSipApp/5.0.23.153 MxSF/v3.2.2.4 (45) [Aug 27 08:11:10] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 13: (0) [Aug 27 08:11:10] DEBUG[17493]: chan_sip.c:4872 parse_request: Line: v=0 (3) [Aug 27 08:11:10] DEBUG[17493]: chan_sip.c:4872 parse_request: Line: o=MxSIP 722671107143209825 1614369397284502047 IN IP4 10.4.119.185 (66) [Aug 27 08:11:10] DEBUG[17493]: chan_sip.c:4872 parse_request: Line: s=- (3) [Aug 27 08:11:10] DEBUG[17493]: chan_sip.c:4872 parse_request: Line: c=IN IP4 10.4.119.185 (21) [Aug 27 08:11:10] DEBUG[17493]: chan_sip.c:4872 parse_request: Line: t=0 0 (5) [Aug 27 08:11:10] DEBUG[17493]: chan_sip.c:4872 parse_request: Line: a=sendrecv (10) [Aug 27 08:11:10] DEBUG[17493]: chan_sip.c:4872 parse_request: Line: m=audio 5006 RTP/AVP 0 (22) [Aug 27 08:11:10] DEBUG[17493]: chan_sip.c:4872 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Aug 27 08:11:10] --- (13 headers 8 lines) --- [Aug 27 08:11:10] DEBUG[17493]: chan_sip.c:4630 find_call: = No match Their Call ID: 38d5236af2114d261f5b5971a858a3ed@10.4.119.245 Their Tag 9ac6c46621c17ab Our tag: as1ae2828b [Aug 27 08:11:10] DEBUG[17493]: chan_sip.c:4630 find_call: = No match Their Call ID: 57d1eeae36baecaf4bdbe3bf4b15dfcf@10.4.119.245 Their Tag 642a56e1e3a9a33 Our tag: as5a6f79cc [Aug 27 08:11:10] DEBUG[17493]: chan_sip.c:15857 sipsock_read: Invalid SIP message - rejected , no callid, len 662 [Aug 27 08:11:10] <--- SIP read from 10.4.119.185:5060 ---> BYE sip:3456@10.4.119.245 SIP/2.0 Via: SIP/2.0/UDP 10.4.119.185;branch=z9hG4bK974818b49 Content-Length: 0 To: "3456" ;tag=as2ef5c824 From: ;tag=d42dbfe2b2544b5 Call-ID: 3f0aedd05a010de95fe9a78a3e658faf@10.4.119.245 CSeq: 2146246955 BYE Supported: timer Supported: replaces User-Agent: MxSipApp/5.0.23.153 MxSF/v3.2.2.4 <-------------> [Aug 27 08:11:10] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 0: BYE sip:3456@10.4.119.245 SIP/2.0 (33) [Aug 27 08:11:10] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 1: Via: SIP/2.0/UDP 10.4.119.185;branch=z9hG4bK974818b49 (53) [Aug 27 08:11:10] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 2: Content-Length: 0 (17) [Aug 27 08:11:10] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 3: To: "3456" ;tag=as2ef5c824 (49) [Aug 27 08:11:10] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 4: From: ;tag=d42dbfe2b2544b5 (49) [Aug 27 08:11:10] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 5: Call-ID: 3f0aedd05a010de95fe9a78a3e658faf@10.4.119.245 (54) [Aug 27 08:11:10] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 6: CSeq: 2146246955 BYE (20) [Aug 27 08:11:10] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 7: Supported: timer (16) [Aug 27 08:11:10] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 8: Supported: replaces (19) [Aug 27 08:11:10] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 9: User-Agent: MxSipApp/5.0.23.153 MxSF/v3.2.2.4 (45) [Aug 27 08:11:10] DEBUG[17493]: chan_sip.c:4840 parse_request: Header 10: (0) [Aug 27 08:11:10] --- (10 headers 0 lines) --- [Aug 27 08:11:10] DEBUG[17493]: chan_sip.c:4630 find_call: = No match Their Call ID: 38d5236af2114d261f5b5971a858a3ed@10.4.119.245 Their Tag 9ac6c46621c17ab Our tag: as1ae2828b [Aug 27 08:11:10] DEBUG[17493]: chan_sip.c:4630 find_call: = No match Their Call ID: 57d1eeae36baecaf4bdbe3bf4b15dfcf@10.4.119.245 Their Tag 642a56e1e3a9a33 Our tag: as5a6f79cc [Aug 27 08:11:10] Sending to 10.4.119.185 : 5060 (no NAT) [Aug 27 08:11:10] <--- Transmitting (no NAT) to 10.4.119.185:5060 ---> SIP/2.0 481 Call leg/transaction does not exist Via: SIP/2.0/UDP 10.4.119.185;branch=z9hG4bK974818b49;received=10.4.119.185 From: ;tag=d42dbfe2b2544b5 To: "3456" ;tag=as2ef5c824 Call-ID: 3f0aedd05a010de95fe9a78a3e658faf@10.4.119.245 CSeq: 2146246955 BYE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 <------------> [Aug 27 08:11:10] DEBUG[17493]: chan_sip.c:15857 sipsock_read: Invalid SIP message - rejected , no callid, len 377