pbx*CLI> <--- SIP read from 71.52.101.157:5060 ---> INVITE sip:15559942999@pbx.elephantoutlook.com SIP/2.0 Via: SIP/2.0/UDP 192.168.22.22:5060;branch=z9hG4bK-e9b67a65 From: "Jon" ;tag=dcfcb54af05ff81do0 To: Call-ID: ededa8e-5e7073a9@192.168.22.22 CSeq: 101 INVITE Max-Forwards: 70 Contact: "Jon" Expires: 240 User-Agent: Sipura/SPA941-4.1.8 Content-Length: 403 Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER Content-Type: application/sdp v=0 o=- 329124448 329124448 IN IP4 192.168.22.22 s=- c=IN IP4 192.168.22.22 t=0 0 m=audio 16458 RTP/AVP 0 2 4 8 18 96 97 98 101 a=rtpmap:0 PCMU/8000 a=rtpmap:2 G726-32/8000 a=rtpmap:4 G723/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:18 G729a/8000 a=rtpmap:96 G726-40/8000 a=rtpmap:97 G726-24/8000 a=rtpmap:98 G726-16/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:30 a=sendrecv <-------------> [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 0: INVITE sip:15559942999@pbx.elephantoutlook.com SIP/2.0 (54) [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.22.22:5060;branch=z9hG4bK-e9b67a65 (59) [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 2: From: "Jon" ;tag=dcfcb54af05ff81do0 (76) [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 3: To: (45) [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 4: Call-ID: ededa8e-5e7073a9@192.168.22.22 (39) [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 5: CSeq: 101 INVITE (16) [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 6: Max-Forwards: 70 (16) [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 7: Contact: "Jon" (51) [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 8: Expires: 240 (12) [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 9: User-Agent: Sipura/SPA941-4.1.8 (31) [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 10: Content-Length: 403 (19) [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 11: Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER (61) [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 12: Content-Type: application/sdp (29) [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 13: (0) [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:4747 parse_request: Line: v=0 (3) [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:4747 parse_request: Line: o=- 329124448 329124448 IN IP4 192.168.22.22 (44) [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:4747 parse_request: Line: s=- (3) [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:4747 parse_request: Line: c=IN IP4 192.168.22.22 (22) [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:4747 parse_request: Line: t=0 0 (5) [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:4747 parse_request: Line: m=audio 16458 RTP/AVP 0 2 4 8 18 96 97 98 101 (45) [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:4747 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:4747 parse_request: Line: a=rtpmap:2 G726-32/8000 (23) [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:4747 parse_request: Line: a=rtpmap:4 G723/8000 (20) [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:4747 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:4747 parse_request: Line: a=rtpmap:18 G729a/8000 (22) [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:4747 parse_request: Line: a=rtpmap:96 G726-40/8000 (24) [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:4747 parse_request: Line: a=rtpmap:97 G726-24/8000 (24) [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:4747 parse_request: Line: a=rtpmap:98 G726-16/8000 (24) [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:4747 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:4747 parse_request: Line: a=fmtp:101 0-15 (15) [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:4747 parse_request: Line: a=ptime:30 (10) [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:4747 parse_request: Line: a=sendrecv (10) --- (13 headers 18 lines) --- [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:2695 do_setnat: Setting NAT on RTP to Off [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:2700 do_setnat: Setting NAT on VRTP to Off [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:4450 sip_alloc: Allocating new SIP dialog for ededa8e-5e7073a9@192.168.22.22 - INVITE (With RTP) [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:14944 handle_request: **** Received INVITE (5) - Command in SIP INVITE Sending to 192.168.22.22 : 5060 (no NAT) Using INVITE request as basis request - ededa8e-5e7073a9@192.168.22.22 [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:2695 do_setnat: Setting NAT on RTP to On [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:2700 do_setnat: Setting NAT on VRTP to On <--- Reliably Transmitting (NAT) to 71.52.101.157:5060 ---> SIP/2.0 407 Proxy Authentication Required Via: SIP/2.0/UDP 192.168.22.22:5060;branch=z9hG4bK-e9b67a65;received=71.52.101.157 From: "Jon" ;tag=dcfcb54af05ff81do0 To: ;tag=as65a84993 Call-ID: ededa8e-5e7073a9@192.168.22.22 CSeq: 101 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Proxy-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="39375bd1" Content-Length: 0 <------------> [Oct 1 10:47:48] DEBUG[26204]: sched.c:284 ast_sched_del: Attempted to delete nonexistent schedule entry 0! [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:2037 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #88922 Scheduling destruction of SIP dialog 'ededa8e-5e7073a9@192.168.22.22' in 32000 ms (Method: INVITE) Found user 'jon' pbx*CLI> <--- SIP read from 71.52.101.157:5060 ---> ACK sip:15559942999@pbx.elephantoutlook.com SIP/2.0 Via: SIP/2.0/UDP 192.168.22.22:5060;branch=z9hG4bK-e9b67a65 From: "Jon" ;tag=dcfcb54af05ff81do0 To: ;tag=as65a84993 Call-ID: ededa8e-5e7073a9@192.168.22.22 CSeq: 101 ACK Max-Forwards: 70 Contact: "Jon" User-Agent: Sipura/SPA941-4.1.8 Content-Length: 0 <-------------> [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 0: ACK sip:15559942999@pbx.elephantoutlook.com SIP/2.0 (51) [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.22.22:5060;branch=z9hG4bK-e9b67a65 (59) [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 2: From: "Jon" ;tag=dcfcb54af05ff81do0 (76) [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 3: To: ;tag=as65a84993 (60) [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 4: Call-ID: ededa8e-5e7073a9@192.168.22.22 (39) [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 5: CSeq: 101 ACK (13) [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 6: Max-Forwards: 70 (16) [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 7: Contact: "Jon" (51) [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 8: User-Agent: Sipura/SPA941-4.1.8 (31) [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 9: Content-Length: 0 (17) [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 10: (0) --- (10 headers 0 lines) --- [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:4503 find_call: = Found Their Call ID: ededa8e-5e7073a9@192.168.22.22 Their Tag dcfcb54af05ff81do0 Our tag: as65a84993 [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:14944 handle_request: **** Received ACK (6) - Command in SIP ACK [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:2148 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #88922 [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:2158 __sip_ack: Stopping retransmission on 'ededa8e-5e7073a9@192.168.22.22' of Response 101: Match Not Found pbx*CLI> <--- SIP read from 71.52.101.157:5060 ---> INVITE sip:15559942999@pbx.elephantoutlook.com SIP/2.0 Via: SIP/2.0/UDP 192.168.22.22:5060;branch=z9hG4bK-cbfbb1b6 From: "Jon" ;tag=dcfcb54af05ff81do0 To: Call-ID: ededa8e-5e7073a9@192.168.22.22 CSeq: 102 INVITE Max-Forwards: 70 Proxy-Authorization: Digest username="jon",realm="asterisk",nonce="39375bd1",uri="sip:15559942999@pbx.elephantoutlook.com",algorithm=MD5,response="57d45d7845d009cbd30e28d1485b4ca1" Contact: "Jon" Expires: 240 User-Agent: Sipura/SPA941-4.1.8 Content-Length: 403 Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER Content-Type: application/sdp v=0 o=- 329124448 329124448 IN IP4 192.168.22.22 s=- c=IN IP4 192.168.22.22 t=0 0 m=audio 16458 RTP/AVP 0 2 4 8 18 96 97 98 101 a=rtpmap:0 PCMU/8000 a=rtpmap:2 G726-32/8000 a=rtpmap:4 G723/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:18 G729a/8000 a=rtpmap:96 G726-40/8000 a=rtpmap:97 G726-24/8000 a=rtpmap:98 G726-16/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:30 a=sendrecv <-------------> [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 0: INVITE sip:15559942999@pbx.elephantoutlook.com SIP/2.0 (54) [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.22.22:5060;branch=z9hG4bK-cbfbb1b6 (59) [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 2: From: "Jon" ;tag=dcfcb54af05ff81do0 (76) [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 3: To: (45) [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 4: Call-ID: ededa8e-5e7073a9@192.168.22.22 (39) [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 5: CSeq: 102 INVITE (16) [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 6: Max-Forwards: 70 (16) [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 7: Proxy-Authorization: Digest username="jon",realm="asterisk",nonce="39375bd1",uri="sip:15559942999@pbx.elephantoutlook.com",algorithm=MD5,response="57d45d7845d009cbd30e28d1485b4ca1" (180) [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 8: Contact: "Jon" (51) [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 9: Expires: 240 (12) [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 10: User-Agent: Sipura/SPA941-4.1.8 (31) [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 11: Content-Length: 403 (19) [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 12: Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER (61) [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 13: Content-Type: application/sdp (29) [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 14: (0) [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:4747 parse_request: Line: v=0 (3) [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:4747 parse_request: Line: o=- 329124448 329124448 IN IP4 192.168.22.22 (44) [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:4747 parse_request: Line: s=- (3) [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:4747 parse_request: Line: c=IN IP4 192.168.22.22 (22) [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:4747 parse_request: Line: t=0 0 (5) [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:4747 parse_request: Line: m=audio 16458 RTP/AVP 0 2 4 8 18 96 97 98 101 (45) [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:4747 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:4747 parse_request: Line: a=rtpmap:2 G726-32/8000 (23) [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:4747 parse_request: Line: a=rtpmap:4 G723/8000 (20) [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:4747 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:4747 parse_request: Line: a=rtpmap:18 G729a/8000 (22) [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:4747 parse_request: Line: a=rtpmap:96 G726-40/8000 (24) [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:4747 parse_request: Line: a=rtpmap:97 G726-24/8000 (24) [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:4747 parse_request: Line: a=rtpmap:98 G726-16/8000 (24) [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:4747 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:4747 parse_request: Line: a=fmtp:101 0-15 (15) [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:4747 parse_request: Line: a=ptime:30 (10) [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:4747 parse_request: Line: a=sendrecv (10) --- (14 headers 18 lines) --- [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:4503 find_call: = Found Their Call ID: ededa8e-5e7073a9@192.168.22.22 Their Tag dcfcb54af05ff81do0 Our tag: as65a84993 [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:14944 handle_request: **** Received INVITE (5) - Command in SIP INVITE Sending to 71.52.101.157 : 5060 (NAT) Using INVITE request as basis request - ededa8e-5e7073a9@192.168.22.22 [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:2695 do_setnat: Setting NAT on RTP to On [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:2700 do_setnat: Setting NAT on VRTP to On Found user 'jon' Found RTP audio format 0 Found RTP audio format 2 Found RTP audio format 4 Found RTP audio format 8 Found RTP audio format 18 Found RTP audio format 96 Found RTP audio format 97 Found RTP audio format 98 Found RTP audio format 101 Peer audio RTP is at port 192.168.22.22:16458 Found description format PCMU for ID 0 Found description format G726-32 for ID 2 Found description format G723 for ID 4 Found description format PCMA for ID 8 Found description format G729a for ID 18 Found description format G726-40 for ID 96 Found description format G726-24 for ID 97 Found description format G726-16 for ID 98 Found description format telephone-event for ID 101 Got unsupported a:fmtp in SDP offer [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:5301 process_sdp: T38 state changed to 0 on channel Capabilities: us - 0x80006 (gsm|ulaw|h263), peer - audio=0xd0d (g723|ulaw|alaw|g726|g729|ilbc)/video=0x0 (nothing), combined - 0x4 (ulaw) Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) Peer audio RTP is at port 192.168.22.22:16458 Peer video RTP is at port 192.168.22.22:39862 [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:5381 process_sdp: We're settling with these formats: 0x4 (ulaw) [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:13626 handle_request_invite: Checking SIP call limits for device jon [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:3133 update_call_counter: Updating call counter for incoming call [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:3210 update_call_counter: Call from peer 'jon' is 1 out of 100 [Oct 1 10:47:48] DEBUG[26204]: devicestate.c:306 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/jon Looking for 15559942999 in local (domain pbx.elephantoutlook.com) [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:3944 sip_new: *** Our native formats are 0x4 (ulaw) [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:3945 sip_new: *** Joint capabilities are 0x4 (ulaw) [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:3946 sip_new: *** Our capabilities are 0x80006 (gsm|ulaw|h263) [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:3947 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:3970 sip_new: This channel will not be able to handle video. [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:8140 build_route: build_route: Contact hop: "Jon" list_route: hop: [Oct 1 10:47:48] DEBUG[26204]: chan_sip.c:13701 handle_request_invite: SIP/jon-08331348: New call is still down.... Trying... <--- Transmitting (NAT) to 71.52.101.157:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.22.22:5060;branch=z9hG4bK-cbfbb1b6;received=71.52.101.157 From: "Jon" ;tag=dcfcb54af05ff81do0 To: Call-ID: ededa8e-5e7073a9@192.168.22.22 CSeq: 102 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Oct 1 10:47:48] DEBUG[26204]: devicestate.c:306 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/jon-08331348 [Oct 1 10:47:48] DEBUG[4077]: pbx.c:1809 pbx_extension_helper: Launching 'Goto' -- Executing [15559942999@local:1] Goto("SIP/jon-08331348", "515559942999|1") in new stack -- Goto (local,515559942999,1) [Oct 1 10:47:48] DEBUG[4077]: pbx.c:1809 pbx_extension_helper: Launching 'Set' -- Executing [515559942999@local:1] Set("SIP/jon-08331348", "DIALSTRING=15559942999") in new stack [Oct 1 10:47:48] DEBUG[4077]: pbx.c:1809 pbx_extension_helper: Launching 'Goto' -- Executing [515559942999@local:2] Goto("SIP/jon-08331348", "provider-5|1") in new stack -- Goto (local,provider-5,1) [Oct 1 10:47:48] DEBUG[4077]: pbx.c:1809 pbx_extension_helper: Launching 'Set' -- Executing [provider-5@local:1] Set("SIP/jon-08331348", "TRUNK=SIP/bandwidth/+") in new stack [Oct 1 10:47:48] DEBUG[4077]: pbx.c:1809 pbx_extension_helper: Launching 'Goto' -- Executing [provider-5@local:2] Goto("SIP/jon-08331348", "dial-15559942999|1") in new stack -- Goto (local,dial-15559942999,1) [Oct 1 10:47:48] DEBUG[4077]: pbx.c:1809 pbx_extension_helper: Launching 'NoOp' -- Executing [dial-15559942999@local:1] NoOp("SIP/jon-08331348", "outging call on: SIP/bandwidth/+") in new stack [Oct 1 10:47:48] DEBUG[4077]: pbx.c:1809 pbx_extension_helper: Launching 'Set' -- Executing [dial-15559942999@local:2] Set("SIP/jon-08331348", "SPYGROUP=2000") in new stack [Oct 1 10:47:48] DEBUG[4077]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is 'jon-08331348' [Oct 1 10:47:48] DEBUG[4077]: pbx.c:1809 pbx_extension_helper: Launching 'Set' -- Executing [dial-15559942999@local:3] Set("SIP/jon-08331348", "SIP_USER=jon-08331348") in new stack [Oct 1 10:47:48] DEBUG[4077]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is 'jon' [Oct 1 10:47:48] DEBUG[4077]: pbx.c:1809 pbx_extension_helper: Launching 'Set' -- Executing [dial-15559942999@local:4] Set("SIP/jon-08331348", "CDR(userfield)=jon") in new stack [Oct 1 10:47:48] DEBUG[4077]: pbx.c:1809 pbx_extension_helper: Launching 'Set' -- Executing [dial-15559942999@local:5] Set("SIP/jon-08331348", "CALLERID(all)="Elephant Outlook" <+18638774177>") in new stack [Oct 1 10:47:48] DEBUG[4077]: pbx.c:1809 pbx_extension_helper: Launching 'Dial' -- Executing [dial-15559942999@local:6] Dial("SIP/jon-08331348", "SIP/bandwidth/+15559942999") in new stack [Oct 1 10:47:48] DEBUG[4077]: chan_sip.c:15640 sip_request_call: Asked to create a SIP channel with formats: 0x4 (ulaw) [Oct 1 10:47:48] DEBUG[4077]: chan_sip.c:4450 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Oct 1 10:47:48] DEBUG[4077]: chan_sip.c:2695 do_setnat: Setting NAT on RTP to Off [Oct 1 10:47:48] DEBUG[4077]: chan_sip.c:2700 do_setnat: Setting NAT on VRTP to Off [Oct 1 10:47:48] DEBUG[4077]: chan_sip.c:3944 sip_new: *** Our native formats are 0x4 (ulaw) [Oct 1 10:47:48] DEBUG[4077]: chan_sip.c:3945 sip_new: *** Joint capabilities are 0x0 (nothing) [Oct 1 10:47:48] DEBUG[4077]: chan_sip.c:3946 sip_new: *** Our capabilities are 0x80006 (gsm|ulaw|h263) [Oct 1 10:47:48] DEBUG[4077]: chan_sip.c:3947 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Oct 1 10:47:48] DEBUG[4077]: chan_sip.c:3949 sip_new: *** Our preferred formats from the incoming channel are 0x4 (ulaw) [Oct 1 10:47:48] DEBUG[4077]: chan_sip.c:3970 sip_new: This channel will not be able to handle video. [Oct 1 10:47:48] DEBUG[4077]: channel.c:3538 ast_channel_inherit_variables: Not copying variable STACK-local-dial-15559942999-6. [Oct 1 10:47:48] DEBUG[4077]: channel.c:3538 ast_channel_inherit_variables: Not copying variable STACK-local-dial-15559942999-5. [Oct 1 10:47:48] DEBUG[4077]: channel.c:3538 ast_channel_inherit_variables: Not copying variable STACK-local-dial-15559942999-4. [Oct 1 10:47:49] DEBUG[4077]: channel.c:3538 ast_channel_inherit_variables: Not copying variable SIP_USER. [Oct 1 10:47:49] DEBUG[4077]: channel.c:3538 ast_channel_inherit_variables: Not copying variable STACK-local-dial-15559942999-3. [Oct 1 10:47:49] DEBUG[4077]: channel.c:3538 ast_channel_inherit_variables: Not copying variable SPYGROUP. [Oct 1 10:47:49] DEBUG[4077]: channel.c:3538 ast_channel_inherit_variables: Not copying variable STACK-local-dial-15559942999-2. [Oct 1 10:47:49] DEBUG[4077]: channel.c:3538 ast_channel_inherit_variables: Not copying variable STACK-local-dial-15559942999-1. [Oct 1 10:47:49] DEBUG[4077]: channel.c:3538 ast_channel_inherit_variables: Not copying variable STACK-local-provider-5-2. [Oct 1 10:47:49] DEBUG[4077]: channel.c:3538 ast_channel_inherit_variables: Not copying variable TRUNK. [Oct 1 10:47:49] DEBUG[4077]: channel.c:3538 ast_channel_inherit_variables: Not copying variable STACK-local-provider-5-1. [Oct 1 10:47:49] DEBUG[4077]: channel.c:3538 ast_channel_inherit_variables: Not copying variable STACK-local-515559942999-2. [Oct 1 10:47:49] DEBUG[4077]: channel.c:3538 ast_channel_inherit_variables: Not copying variable DIALSTRING. [Oct 1 10:47:49] DEBUG[4077]: channel.c:3538 ast_channel_inherit_variables: Not copying variable STACK-local-515559942999-1. [Oct 1 10:47:49] DEBUG[4077]: channel.c:3538 ast_channel_inherit_variables: Not copying variable STACK-local-15559942999-1. [Oct 1 10:47:49] DEBUG[4077]: channel.c:3538 ast_channel_inherit_variables: Not copying variable SIPCALLID. [Oct 1 10:47:49] DEBUG[4077]: channel.c:3538 ast_channel_inherit_variables: Not copying variable SIPUSERAGENT. [Oct 1 10:47:49] DEBUG[4077]: channel.c:3538 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [Oct 1 10:47:49] DEBUG[4077]: channel.c:3538 ast_channel_inherit_variables: Not copying variable SIPURI. [Oct 1 10:47:49] DEBUG[4077]: chan_sip.c:2953 sip_call: Outgoing Call for +15559942999 [Oct 1 10:47:49] DEBUG[4077]: chan_sip.c:3133 update_call_counter: Updating call counter for outgoing call [Oct 1 10:47:49] DEBUG[4077]: chan_sip.c:2968 sip_call: Our T38 capability (0), joint T38 capability (0) [Oct 1 10:47:49] DEBUG[4077]: chan_sip.c:6338 add_sdp: ** Our capability: 0x80006 (gsm|ulaw|h263) Video flag: False [Oct 1 10:47:49] DEBUG[4077]: chan_sip.c:6339 add_sdp: ** Our prefcodec: 0x4 (ulaw) [Oct 1 10:47:49] DEBUG[4077]: chan_sip.c:6354 add_sdp: This call needs video offers! Video is at 66.192.107.225 port 14468 Audio is at 66.192.107.225 port 10836 Adding codec 0x4 (ulaw) to SDP Adding codec 0x2 (gsm) to SDP Adding codec 0x80000 (h263) to SDP Adding non-codec 0x1 (telephone-event) to SDP [Oct 1 10:47:49] DEBUG[4077]: chan_sip.c:6470 add_sdp: -- Done with adding codecs to SDP [Oct 1 10:47:49] DEBUG[4077]: channel.c:2562 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Oct 1 10:47:49] DEBUG[4077]: chan_sip.c:6515 add_sdp: Done building SDP. Settling with this capability: 0x80006 (gsm|ulaw|h263) [Oct 1 10:47:49] DEBUG[4077]: chan_sip.c:4715 parse_request: Header 0: INVITE sip:+15559942999@216.82.224.202 SIP/2.0 (46) [Oct 1 10:47:49] DEBUG[4077]: chan_sip.c:4715 parse_request: Header 1: Via: SIP/2.0/UDP 66.192.107.225:5060;branch=z9hG4bK08a8c632;rport (65) [Oct 1 10:47:49] DEBUG[4077]: chan_sip.c:4715 parse_request: Header 2: From: "Elephant Outlook" ;tag=as111394d8 (71) [Oct 1 10:47:49] DEBUG[4077]: chan_sip.c:4715 parse_request: Header 3: To: (37) [Oct 1 10:47:49] DEBUG[4077]: chan_sip.c:4715 parse_request: Header 4: Contact: (42) [Oct 1 10:47:49] DEBUG[4077]: chan_sip.c:4715 parse_request: Header 5: Call-ID: 448732f666f0d30a344f7fa537d298d4@4.68.250.148 (54) [Oct 1 10:47:49] DEBUG[4077]: chan_sip.c:4715 parse_request: Header 6: CSeq: 102 INVITE (16) [Oct 1 10:47:49] DEBUG[4077]: chan_sip.c:4715 parse_request: Header 7: User-Agent: Asterisk PBX (24) [Oct 1 10:47:49] DEBUG[4077]: chan_sip.c:4715 parse_request: Header 8: Max-Forwards: 70 (16) [Oct 1 10:47:49] DEBUG[4077]: chan_sip.c:4715 parse_request: Header 9: Date: Mon, 01 Oct 2007 14:47:49 GMT (35) [Oct 1 10:47:49] DEBUG[4077]: chan_sip.c:4715 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Oct 1 10:47:49] DEBUG[4077]: chan_sip.c:4715 parse_request: Header 11: Supported: replaces (19) [Oct 1 10:47:49] DEBUG[4077]: chan_sip.c:4715 parse_request: Header 12: Content-Type: application/sdp (29) [Oct 1 10:47:49] DEBUG[4077]: chan_sip.c:4715 parse_request: Header 13: Content-Length: 339 (19) [Oct 1 10:47:49] DEBUG[4077]: chan_sip.c:4715 parse_request: Header 14: (0) [Oct 1 10:47:49] DEBUG[4077]: chan_sip.c:4747 parse_request: Line: v=0 (3) [Oct 1 10:47:49] DEBUG[4077]: chan_sip.c:4747 parse_request: Line: o=root 26169 26169 IN IP4 66.192.107.225 (40) [Oct 1 10:47:49] DEBUG[4077]: chan_sip.c:4747 parse_request: Line: s=session (9) [Oct 1 10:47:49] DEBUG[4077]: chan_sip.c:4747 parse_request: Line: c=IN IP4 66.192.107.225 (23) [Oct 1 10:47:49] DEBUG[4077]: chan_sip.c:4747 parse_request: Line: b=CT:384 (8) [Oct 1 10:47:49] DEBUG[4077]: chan_sip.c:4747 parse_request: Line: t=0 0 (5) [Oct 1 10:47:49] DEBUG[4077]: chan_sip.c:4747 parse_request: Line: m=audio 10836 RTP/AVP 0 3 101 (29) [Oct 1 10:47:49] DEBUG[4077]: chan_sip.c:4747 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Oct 1 10:47:49] DEBUG[4077]: chan_sip.c:4747 parse_request: Line: a=rtpmap:3 GSM/8000 (19) [Oct 1 10:47:49] DEBUG[4077]: chan_sip.c:4747 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Oct 1 10:47:49] DEBUG[4077]: chan_sip.c:4747 parse_request: Line: a=fmtp:101 0-16 (15) [Oct 1 10:47:49] DEBUG[4077]: chan_sip.c:4747 parse_request: Line: a=silenceSupp:off - - - - (25) [Oct 1 10:47:49] DEBUG[4077]: chan_sip.c:4747 parse_request: Line: a=ptime:20 (10) [Oct 1 10:47:49] DEBUG[4077]: chan_sip.c:4747 parse_request: Line: a=sendrecv (10) [Oct 1 10:47:49] DEBUG[4077]: chan_sip.c:4747 parse_request: Line: m=video 14468 RTP/AVP 34 (24) [Oct 1 10:47:49] DEBUG[4077]: chan_sip.c:4747 parse_request: Line: a=rtpmap:34 H263/90000 (22) [Oct 1 10:47:49] DEBUG[4077]: chan_sip.c:4747 parse_request: Line: a=sendrecv (10) Reliably Transmitting (no NAT) to 216.82.224.202:5060: INVITE sip:+15559942999@216.82.224.202 SIP/2.0 Via: SIP/2.0/UDP 66.192.107.225:5060;branch=z9hG4bK08a8c632;rport From: "Elephant Outlook" ;tag=as111394d8 To: Contact: Call-ID: 448732f666f0d30a344f7fa537d298d4@4.68.250.148 CSeq: 102 INVITE User-Agent: Asterisk PBX Max-Forwards: 70 Date: Mon, 01 Oct 2007 14:47:49 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Type: application/sdp Content-Length: 339 v=0 o=root 26169 26169 IN IP4 66.192.107.225 s=session c=IN IP4 66.192.107.225 b=CT:384 t=0 0 m=audio 10836 RTP/AVP 0 3 101 a=rtpmap:0 PCMU/8000 a=rtpmap:3 GSM/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv m=video 14468 RTP/AVP 34 a=rtpmap:34 H263/90000 a=sendrecv --- [Oct 1 10:47:49] DEBUG[4077]: sched.c:284 ast_sched_del: Attempted to delete nonexistent schedule entry 0! [Oct 1 10:47:49] DEBUG[4077]: chan_sip.c:2037 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #88924 -- Called bandwidth/+15559942999 [Oct 1 10:47:49] DEBUG[26175]: devicestate.c:163 ast_device_state: No provider found, checking channel drivers for SIP - jon [Oct 1 10:47:49] DEBUG[26175]: chan_sip.c:15574 sip_devicestate: Checking device state for peer jon [Oct 1 10:47:49] DEBUG[26175]: devicestate.c:289 do_state_change: Changing state for SIP/jon - state 2 (In use) [Oct 1 10:47:49] DEBUG[26175]: devicestate.c:163 ast_device_state: No provider found, checking channel drivers for SIP - jon [Oct 1 10:47:49] DEBUG[26175]: chan_sip.c:15574 sip_devicestate: Checking device state for peer jon [Oct 1 10:47:49] DEBUG[26175]: devicestate.c:289 do_state_change: Changing state for SIP/jon - state 2 (In use) [Oct 1 10:47:49] DEBUG[4078]: app_queue.c:554 changethread: Device 'SIP/jon' changed to state '2' (In use) [Oct 1 10:47:49] DEBUG[4079]: app_queue.c:554 changethread: Device 'SIP/jon' changed to state '2' (In use) [Oct 1 10:47:50] DEBUG[26204]: chan_sip.c:1902 retrans_pkt: SIP TIMER: Rescheduling retransmission #88924 (1) INVITE - 5 [Oct 1 10:47:50] DEBUG[26204]: chan_sip.c:1916 retrans_pkt: ** SIP timers: Rescheduling retransmission 2 to 1000 ms (t1 500 ms (Retrans id #88924)) Retransmitting #1 (no NAT) to 216.82.224.202:5060: INVITE sip:+15559942999@216.82.224.202 SIP/2.0 Via: SIP/2.0/UDP 66.192.107.225:5060;branch=z9hG4bK08a8c632;rport From: "Elephant Outlook" ;tag=as111394d8 To: Contact: Call-ID: 448732f666f0d30a344f7fa537d298d4@4.68.250.148 CSeq: 102 INVITE User-Agent: Asterisk PBX Max-Forwards: 70 Date: Mon, 01 Oct 2007 14:47:49 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Type: application/sdp Content-Length: 339 v=0 o=root 26169 26169 IN IP4 66.192.107.225 s=session c=IN IP4 66.192.107.225 b=CT:384 t=0 0 m=audio 10836 RTP/AVP 0 3 101 a=rtpmap:0 PCMU/8000 a=rtpmap:3 GSM/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv m=video 14468 RTP/AVP 34 a=rtpmap:34 H263/90000 a=sendrecv --- pbx*CLI> <--- SIP read from 216.82.224.202:5060 ---> SIP/2.0 100 bandwidth.com has received your request Via: SIP/2.0/UDP 66.192.107.225:5060;branch=z9hG4bK08a8c632;rport=5060 From: "Elephant Outlook" ;tag=as111394d8 To: Call-ID: 448732f666f0d30a344f7fa537d298d4@4.68.250.148 CSeq: 102 INVITE Server: Bandwidth.com TRM (bw7.gold.13) Content-Length: 0 <-------------> [Oct 1 10:47:50] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 0: SIP/2.0 100 bandwidth.com has received your request (51) [Oct 1 10:47:50] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 1: Via: SIP/2.0/UDP 66.192.107.225:5060;branch=z9hG4bK08a8c632;rport=5060 (70) [Oct 1 10:47:50] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 2: From: "Elephant Outlook" ;tag=as111394d8 (71) [Oct 1 10:47:50] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 3: To: (37) [Oct 1 10:47:50] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 4: Call-ID: 448732f666f0d30a344f7fa537d298d4@4.68.250.148 (54) [Oct 1 10:47:50] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 5: CSeq: 102 INVITE (16) [Oct 1 10:47:50] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 6: Server: Bandwidth.com TRM (bw7.gold.13) (39) [Oct 1 10:47:50] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 7: Content-Length: 0 (17) [Oct 1 10:47:50] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 8: (0) --- (8 headers 0 lines) --- [Oct 1 10:47:50] DEBUG[26204]: chan_sip.c:4503 find_call: = Found Their Call ID: 448732f666f0d30a344f7fa537d298d4@4.68.250.148 Their Tag Our tag: as111394d8 [Oct 1 10:47:50] DEBUG[26204]: chan_sip.c:2191 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #88924 - INVITE (got response) [Oct 1 10:47:50] DEBUG[26204]: chan_sip.c:2200 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '448732f666f0d30a344f7fa537d298d4@4.68.250.148' Request 102: Found [Oct 1 10:47:50] DEBUG[26204]: chan_sip.c:11814 handle_response_invite: SIP response 100 to standard invite pbx*CLI> <--- SIP read from 71.101.36.190:50002 ---> NOTIFY sip:pbx.elephantoutlook.com SIP/2.0 Via: SIP/2.0/UDP 192.168.1.47:5060;branch=z9hG4bK-468774de From: "Home 2" ;tag=f3edfbba5123de76o0 To: Call-ID: 4b0be73a-76f2e8f6@192.168.1.47 CSeq: 131665 NOTIFY Max-Forwards: 70 Event: keep-alive User-Agent: Sipura/SPA941-4.1.8 Content-Length: 0 <-------------> [Oct 1 10:47:54] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 0: NOTIFY sip:pbx.elephantoutlook.com SIP/2.0 (42) [Oct 1 10:47:54] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.47:5060;branch=z9hG4bK-468774de (58) [Oct 1 10:47:54] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 2: From: "Home 2" ;tag=f3edfbba5123de76o0 (84) [Oct 1 10:47:54] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 3: To: (33) [Oct 1 10:47:54] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 4: Call-ID: 4b0be73a-76f2e8f6@192.168.1.47 (39) [Oct 1 10:47:54] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 5: CSeq: 131665 NOTIFY (19) [Oct 1 10:47:54] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 6: Max-Forwards: 70 (16) [Oct 1 10:47:54] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 7: Event: keep-alive (17) [Oct 1 10:47:54] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 8: User-Agent: Sipura/SPA941-4.1.8 (31) [Oct 1 10:47:54] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 9: Content-Length: 0 (17) [Oct 1 10:47:54] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 10: (0) --- (10 headers 0 lines) --- [Oct 1 10:47:54] DEBUG[26204]: chan_sip.c:4503 find_call: = No match Their Call ID: 448732f666f0d30a344f7fa537d298d4@4.68.250.148 Their Tag Our tag: as111394d8 [Oct 1 10:47:54] DEBUG[26204]: chan_sip.c:4503 find_call: = No match Their Call ID: ededa8e-5e7073a9@192.168.22.22 Their Tag dcfcb54af05ff81do0 Our tag: as32006948 <--- Transmitting (no NAT) to 71.101.36.190:50002 ---> SIP/2.0 489 Bad event Via: SIP/2.0/UDP 192.168.1.47:5060;branch=z9hG4bK-468774de;received=71.101.36.190 From: "Home 2" ;tag=f3edfbba5123de76o0 To: ;tag=as40cb751d Call-ID: 4b0be73a-76f2e8f6@192.168.1.47 CSeq: 131665 NOTIFY User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 <------------> [Oct 1 10:47:54] DEBUG[26204]: chan_sip.c:15128 sipsock_read: Invalid SIP message - rejected , no callid, len 378 [Oct 1 10:47:54] DEBUG[26204]: chan_sip.c:4450 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Oct 1 10:47:54] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 0: OPTIONS sip:phone2@192.168.2.5:5060 SIP/2.0 (50) [Oct 1 10:47:54] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 1: Via: SIP/2.0/UDP 66.192.107.225:5060;branch=z9hG4bK3e86dc06;rport (65) [Oct 1 10:47:54] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 2: From: "asterisk" ;tag=as0dcb19f8 (61) [Oct 1 10:47:54] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 3: To: (40) [Oct 1 10:47:54] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 4: Contact: (38) [Oct 1 10:47:54] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 5: Call-ID: 5d01f10260451d3f5d7806371977a78c@66.192.107.225 (56) [Oct 1 10:47:54] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 6: CSeq: 102 OPTIONS (17) [Oct 1 10:47:54] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 7: User-Agent: Asterisk PBX (24) [Oct 1 10:47:54] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 8: Max-Forwards: 70 (16) [Oct 1 10:47:54] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 9: Date: Mon, 01 Oct 2007 14:47:54 GMT (35) [Oct 1 10:47:54] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Oct 1 10:47:54] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 11: Supported: replaces (19) [Oct 1 10:47:54] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 12: Content-Length: 0 (17) Reliably Transmitting (NAT) to 72.187.95.191:5060: OPTIONS sip:phone2@192.168.2.5:5060 SIP/2.0 Via: SIP/2.0/UDP 66.192.107.225:5060;branch=z9hG4bK3e86dc06;rport From: "asterisk" ;tag=as0dcb19f8 To: Contact: Call-ID: 5d01f10260451d3f5d7806371977a78c@66.192.107.225 CSeq: 102 OPTIONS User-Agent: Asterisk PBX Max-Forwards: 70 Date: Mon, 01 Oct 2007 14:47:54 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 --- [Oct 1 10:47:54] DEBUG[26204]: sched.c:284 ast_sched_del: Attempted to delete nonexistent schedule entry 0! [Oct 1 10:47:54] DEBUG[26204]: chan_sip.c:2037 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #88926 pbx*CLI> <--- SIP read from 72.187.88.46:5061 ---> NOTIFY sip:pbx.elephantoutlook.com SIP/2.0 Via: SIP/2.0/UDP 192.168.0.100:5061;branch=z9hG4bK-7395915a From: "Phone" ;tag=3d2da667eecdead6o0 To: Call-ID: 1a47d947-de4e5576@192.168.0.100 CSeq: 87855 NOTIFY Max-Forwards: 70 Event: keep-alive User-Agent: Sipura/SPA941-4.1.9 Content-Length: 0 <-------------> [Oct 1 10:47:55] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 0: NOTIFY sip:pbx.elephantoutlook.com SIP/2.0 (42) [Oct 1 10:47:55] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.0.100:5061;branch=z9hG4bK-7395915a (59) [Oct 1 10:47:55] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 2: From: "Phone" ;tag=3d2da667eecdead6o0 (86) [Oct 1 10:47:55] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 3: To: (33) [Oct 1 10:47:55] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 4: Call-ID: 1a47d947-de4e5576@192.168.0.100 (40) [Oct 1 10:47:55] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 5: CSeq: 87855 NOTIFY (18) [Oct 1 10:47:55] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 6: Max-Forwards: 70 (16) [Oct 1 10:47:55] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 7: Event: keep-alive (17) [Oct 1 10:47:55] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 8: User-Agent: Sipura/SPA941-4.1.9 (31) [Oct 1 10:47:55] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 9: Content-Length: 0 (17) [Oct 1 10:47:55] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 10: (0) --- (10 headers 0 lines) --- [Oct 1 10:47:55] DEBUG[26204]: chan_sip.c:4503 find_call: = No match Their Call ID: 5d01f10260451d3f5d7806371977a78c@66.192.107.225 Their Tag Our tag: as0dcb19f8 [Oct 1 10:47:55] DEBUG[26204]: chan_sip.c:4503 find_call: = No match Their Call ID: 448732f666f0d30a344f7fa537d298d4@4.68.250.148 Their Tag Our tag: as111394d8 [Oct 1 10:47:55] DEBUG[26204]: chan_sip.c:4503 find_call: = No match Their Call ID: ededa8e-5e7073a9@192.168.22.22 Their Tag dcfcb54af05ff81do0 Our tag: as32006948 <--- Transmitting (no NAT) to 72.187.88.46:5061 ---> SIP/2.0 489 Bad event Via: SIP/2.0/UDP 192.168.0.100:5061;branch=z9hG4bK-7395915a;received=72.187.88.46 From: "Phone" ;tag=3d2da667eecdead6o0 To: ;tag=as0eb5121e Call-ID: 1a47d947-de4e5576@192.168.0.100 CSeq: 87855 NOTIFY User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 <------------> [Oct 1 10:47:55] DEBUG[26204]: chan_sip.c:15128 sipsock_read: Invalid SIP message - rejected , no callid, len 381 pbx*CLI> <--- SIP read from 216.82.224.202:5060 ---> SIP/2.0 200 OK v: SIP/2.0/UDP 66.192.107.225:5060;branch=z9hG4bK08a8c632;rport=5060 Record-Route: P-Charging-Vector:icid-value=default~91633b6cc958d65bb53b89ef39c1ff5a;icid-generated-at=204.13.236.129;orig-ioi=default~;term-ioi=default~;Charge=sip%3A8638774177%404.68.250.148 From: "Elephant Outlook" ;tag=as111394d8 t: ;tag=80b374c5886f0d2f86e27f008e41bdc4 i: 448732f666f0d30a344f7fa537d298d4@4.68.250.148 CSeq: 102 INVITE Server: DC-SIP/1.2 k: timer x: 1800;refresher=uas m: c: application/sdp l: 290 v=0 o=- 259201 25920100 IN IP4 204.13.236.130 s=- t=0 0 m=image 53420 udptl t38 c=IN IP4 204.13.236.130 a=T38FaxVersion:0 a=T38MaxBitRate:14400 a=T38FaxFillBitRemoval:0 a=T38FaxTranscodingMMR:0 a=T38FaxRateManagement:transferredTCF a=T38FaxMaxBuffer:200 a=T38FaxMaxDatagram:72 <-------------> [Oct 1 10:47:55] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 0: SIP/2.0 200 OK (14) [Oct 1 10:47:55] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 1: v: SIP/2.0/UDP 66.192.107.225:5060;branch=z9hG4bK08a8c632;rport=5060 (68) [Oct 1 10:47:55] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 2: Record-Route: (98) [Oct 1 10:47:55] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 3: P-Charging-Vector:icid-value=default~91633b6cc958d65bb53b89ef39c1ff5a;icid-generated-at=204.13.236.129;orig-ioi=default~;term-ioi=default~;Charge=sip%3A8638774177%404.68.250.148 (177) [Oct 1 10:47:55] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 4: From: "Elephant Outlook" ;tag=as111394d8 (71) [Oct 1 10:47:55] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 5: t: ;tag=80b374c5886f0d2f86e27f008e41bdc4 (73) [Oct 1 10:47:55] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 6: i: 448732f666f0d30a344f7fa537d298d4@4.68.250.148 (48) [Oct 1 10:47:55] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 7: CSeq: 102 INVITE (16) [Oct 1 10:47:55] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 8: Server: DC-SIP/1.2 (18) [Oct 1 10:47:55] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 9: k: timer (8) [Oct 1 10:47:55] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 10: x: 1800;refresher=uas (21) [Oct 1 10:47:55] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 11: m: (53) [Oct 1 10:47:55] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 12: c: application/sdp (18) [Oct 1 10:47:55] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 13: l: 290 (6) [Oct 1 10:47:55] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 14: (0) [Oct 1 10:47:55] DEBUG[26204]: chan_sip.c:4747 parse_request: Line: v=0 (3) [Oct 1 10:47:55] DEBUG[26204]: chan_sip.c:4747 parse_request: Line: o=- 259201 25920100 IN IP4 204.13.236.130 (41) [Oct 1 10:47:55] DEBUG[26204]: chan_sip.c:4747 parse_request: Line: s=- (3) [Oct 1 10:47:55] DEBUG[26204]: chan_sip.c:4747 parse_request: Line: t=0 0 (5) [Oct 1 10:47:55] DEBUG[26204]: chan_sip.c:4747 parse_request: Line: m=image 53420 udptl t38 (23) [Oct 1 10:47:55] DEBUG[26204]: chan_sip.c:4747 parse_request: Line: c=IN IP4 204.13.236.130 (23) [Oct 1 10:47:55] DEBUG[26204]: chan_sip.c:4747 parse_request: Line: a=T38FaxVersion:0 (17) [Oct 1 10:47:55] DEBUG[26204]: chan_sip.c:4747 parse_request: Line: a=T38MaxBitRate:14400 (21) [Oct 1 10:47:55] DEBUG[26204]: chan_sip.c:4747 parse_request: Line: a=T38FaxFillBitRemoval:0 (24) [Oct 1 10:47:55] DEBUG[26204]: chan_sip.c:4747 parse_request: Line: a=T38FaxTranscodingMMR:0 (24) [Oct 1 10:47:55] DEBUG[26204]: chan_sip.c:4747 parse_request: Line: a=T38FaxRateManagement:transferredTCF (37) [Oct 1 10:47:55] DEBUG[26204]: chan_sip.c:4747 parse_request: Line: a=T38FaxMaxBuffer:200 (21) [Oct 1 10:47:55] DEBUG[26204]: chan_sip.c:4747 parse_request: Line: a=T38FaxMaxDatagram:72 (22) --- (14 headers 13 lines) --- [Oct 1 10:47:55] DEBUG[26204]: chan_sip.c:4503 find_call: = No match Their Call ID: 5d01f10260451d3f5d7806371977a78c@66.192.107.225 Their Tag Our tag: as0dcb19f8 [Oct 1 10:47:55] DEBUG[26204]: chan_sip.c:4503 find_call: = Found Their Call ID: 448732f666f0d30a344f7fa537d298d4@4.68.250.148 Their Tag Our tag: as111394d8 [Oct 1 10:47:55] DEBUG[26204]: chan_sip.c:2140 __sip_ack: Acked pending invite 102 [Oct 1 10:47:55] DEBUG[26204]: chan_sip.c:2158 __sip_ack: Stopping retransmission on '448732f666f0d30a344f7fa537d298d4@4.68.250.148' of Request 102: Match Not Found [Oct 1 10:47:55] DEBUG[26204]: chan_sip.c:11814 handle_response_invite: SIP response 200 to standard invite [Oct 1 10:47:55] WARNING[26204]: chan_sip.c:5017 process_sdp: Unsupported SDP media type in offer: image 53420 udptl t38 [Oct 1 10:47:55] DEBUG[26204]: chan_sip.c:3133 update_call_counter: Updating call counter for outgoing call [Oct 1 10:47:55] DEBUG[26204]: chan_sip.c:8111 build_route: build_route: Record-Route hop: list_route: hop: set_destination: Parsing for address/port to send to set_destination: set destination to 216.82.224.202, port 5060 Transmitting (no NAT) to 216.82.224.202:5060: ACK sip:5559942999@204.13.236.129:5060;transport=udp SIP/2.0 Via: SIP/2.0/UDP 66.192.107.225:5060;branch=z9hG4bK47b77264;rport Route: From: "Elephant Outlook" ;tag=as111394d8 To: ;tag=80b374c5886f0d2f86e27f008e41bdc4 Contact: Call-ID: 448732f666f0d30a344f7fa537d298d4@4.68.250.148 CSeq: 102 ACK User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- set_destination: Parsing for address/port to send to set_destination: set destination to 216.82.224.202, port 5060 Reliably Transmitting (no NAT) to 216.82.224.202:5060: BYE sip:5559942999@204.13.236.129:5060;transport=udp SIP/2.0 Via: SIP/2.0/UDP 66.192.107.225:5060;branch=z9hG4bK2ca92ce4;rport Route: From: "Elephant Outlook" ;tag=as111394d8 To: ;tag=80b374c5886f0d2f86e27f008e41bdc4 Call-ID: 448732f666f0d30a344f7fa537d298d4@4.68.250.148 CSeq: 103 BYE User-Agent: Asterisk PBX Max-Forwards: 70 X-Asterisk-HangupCause: Normal Clearing X-Asterisk-HangupCauseCode: 16 Content-Length: 0 --- [Oct 1 10:47:55] DEBUG[26204]: sched.c:284 ast_sched_del: Attempted to delete nonexistent schedule entry 0! [Oct 1 10:47:55] DEBUG[26204]: chan_sip.c:2037 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #88928 Scheduling destruction of SIP dialog '448732f666f0d30a344f7fa537d298d4@4.68.250.148' in 32000 ms (Method: INVITE) [Oct 1 10:47:55] DEBUG[4077]: devicestate.c:306 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/bandwidth-08429420 -- SIP/bandwidth-08429420 answered SIP/jon-08331348 [Oct 1 10:47:55] DEBUG[4077]: devicestate.c:306 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/jon-08331348 [Oct 1 10:47:55] DEBUG[4077]: chan_sip.c:3602 sip_answer: SIP answering channel: SIP/jon-08331348 [Oct 1 10:47:55] DEBUG[4077]: chan_sip.c:6574 transmit_response_with_sdp: Setting framing from config on incoming call [Oct 1 10:47:55] DEBUG[4077]: chan_sip.c:6338 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True [Oct 1 10:47:55] DEBUG[4077]: chan_sip.c:6339 add_sdp: ** Our prefcodec: 0x0 (nothing) Audio is at 66.192.107.225 port 17962 Adding codec 0x4 (ulaw) to SDP Adding non-codec 0x1 (telephone-event) to SDP [Oct 1 10:47:55] DEBUG[4077]: chan_sip.c:6470 add_sdp: -- Done with adding codecs to SDP [Oct 1 10:47:55] DEBUG[4077]: channel.c:2562 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=42) [Oct 1 10:47:55] DEBUG[4077]: chan_sip.c:6515 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw) <--- Reliably Transmitting (NAT) to 71.52.101.157:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.22.22:5060;branch=z9hG4bK-cbfbb1b6;received=71.52.101.157 From: "Jon" ;tag=dcfcb54af05ff81do0 To: ;tag=as32006948 Call-ID: ededa8e-5e7073a9@192.168.22.22 CSeq: 102 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 244 v=0 o=root 26169 26169 IN IP4 66.192.107.225 s=session c=IN IP4 66.192.107.225 t=0 0 m=audio 17962 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv <------------> [Oct 1 10:47:55] DEBUG[4077]: sched.c:284 ast_sched_del: Attempted to delete nonexistent schedule entry 0! [Oct 1 10:47:55] DEBUG[4077]: chan_sip.c:2037 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #88930 [Oct 1 10:47:55] DEBUG[26175]: devicestate.c:163 ast_device_state: No provider found, checking channel drivers for SIP - bandwidth [Oct 1 10:47:55] DEBUG[26175]: chan_sip.c:15574 sip_devicestate: Checking device state for peer bandwidth [Oct 1 10:47:55] DEBUG[26175]: devicestate.c:289 do_state_change: Changing state for SIP/bandwidth - state 1 (Not in use) [Oct 1 10:47:55] DEBUG[26175]: devicestate.c:163 ast_device_state: No provider found, checking channel drivers for SIP - jon [Oct 1 10:47:55] DEBUG[26175]: chan_sip.c:15574 sip_devicestate: Checking device state for peer jon [Oct 1 10:47:55] DEBUG[26175]: devicestate.c:289 do_state_change: Changing state for SIP/jon - state 2 (In use) [Oct 1 10:47:55] DEBUG[4080]: app_queue.c:548 changethread: Device 'SIP/bandwidth' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Oct 1 10:47:55] DEBUG[4081]: app_queue.c:554 changethread: Device 'SIP/jon' changed to state '2' (In use) pbx*CLI> <--- SIP read from 71.52.101.157:5060 ---> ACK sip:15559942999@66.192.107.225 SIP/2.0 Via: SIP/2.0/UDP 192.168.22.22:5060;branch=z9hG4bK-1371493b From: "Jon" ;tag=dcfcb54af05ff81do0 To: ;tag=as32006948 Call-ID: ededa8e-5e7073a9@192.168.22.22 CSeq: 102 ACK Max-Forwards: 70 Proxy-Authorization: Digest username="jon",realm="asterisk",nonce="39375bd1",uri="sip:15559942999@66.192.107.225",algorithm=MD5,response="2b298b1b83c9e26d25030fa047158ff8" Contact: "Jon" User-Agent: Sipura/SPA941-4.1.8 Content-Length: 0 <-------------> [Oct 1 10:47:55] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 0: ACK sip:15559942999@66.192.107.225 SIP/2.0 (42) [Oct 1 10:47:55] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.22.22:5060;branch=z9hG4bK-1371493b (59) [Oct 1 10:47:55] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 2: From: "Jon" ;tag=dcfcb54af05ff81do0 (76) [Oct 1 10:47:55] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 3: To: ;tag=as32006948 (60) [Oct 1 10:47:55] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 4: Call-ID: ededa8e-5e7073a9@192.168.22.22 (39) [Oct 1 10:47:55] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 5: CSeq: 102 ACK (13) [Oct 1 10:47:55] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 6: Max-Forwards: 70 (16) [Oct 1 10:47:55] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 7: Proxy-Authorization: Digest username="jon",realm="asterisk",nonce="39375bd1",uri="sip:15559942999@66.192.107.225",algorithm=MD5,response="2b298b1b83c9e26d25030fa047158ff8" (171) [Oct 1 10:47:55] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 8: Contact: "Jon" (51) [Oct 1 10:47:55] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 9: User-Agent: Sipura/SPA941-4.1.8 (31) [Oct 1 10:47:55] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 10: Content-Length: 0 (17) [Oct 1 10:47:55] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 11: (0) --- (11 headers 0 lines) --- [Oct 1 10:47:55] DEBUG[26204]: chan_sip.c:4503 find_call: = No match Their Call ID: 5d01f10260451d3f5d7806371977a78c@66.192.107.225 Their Tag Our tag: as0dcb19f8 [Oct 1 10:47:55] DEBUG[26204]: chan_sip.c:4503 find_call: = No match Their Call ID: 448732f666f0d30a344f7fa537d298d4@4.68.250.148 Their Tag 80b374c5886f0d2f86e27f008e41bdc4 Our tag: as111394d8 [Oct 1 10:47:55] DEBUG[26204]: chan_sip.c:4503 find_call: = Found Their Call ID: ededa8e-5e7073a9@192.168.22.22 Their Tag dcfcb54af05ff81do0 Our tag: as32006948 [Oct 1 10:47:55] DEBUG[26204]: chan_sip.c:14944 handle_request: **** Received ACK (6) - Command in SIP ACK [Oct 1 10:47:55] DEBUG[26204]: chan_sip.c:2148 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #88930 [Oct 1 10:47:55] DEBUG[26204]: chan_sip.c:2158 __sip_ack: Stopping retransmission on 'ededa8e-5e7073a9@192.168.22.22' of Response 102: Match Not Found [Oct 1 10:47:55] DEBUG[4077]: rtp.c:1173 ast_rtp_read: RTP NAT: Got audio from other end. Now sending to address 71.52.101.157:16458 pbx*CLI> <--- SIP read from 216.82.224.202:5060 ---> SIP/2.0 200 OK v: SIP/2.0/UDP 66.192.107.225:5060;branch=z9hG4bK2ca92ce4;rport=5060 P-Charging-Vector:icid-value=default~91633b6cc958d65bb53b89ef39c1ff5a;icid-generated-at=204.13.236.129;orig-ioi=default~;term-ioi=default~;Charge=sip%3A8638774177%404.68.250.148 From: "Elephant Outlook" ;tag=as111394d8 t: ;tag=80b374c5886f0d2f86e27f008e41bdc4 i: 448732f666f0d30a344f7fa537d298d4@4.68.250.148 CSeq: 103 BYE Server: DC-SIP/1.2 k: timer l: 0 <-------------> [Oct 1 10:47:55] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 0: SIP/2.0 200 OK (14) [Oct 1 10:47:55] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 1: v: SIP/2.0/UDP 66.192.107.225:5060;branch=z9hG4bK2ca92ce4;rport=5060 (68) [Oct 1 10:47:55] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 2: P-Charging-Vector:icid-value=default~91633b6cc958d65bb53b89ef39c1ff5a;icid-generated-at=204.13.236.129;orig-ioi=default~;term-ioi=default~;Charge=sip%3A8638774177%404.68.250.148 (177) [Oct 1 10:47:55] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 3: From: "Elephant Outlook" ;tag=as111394d8 (71) [Oct 1 10:47:55] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 4: t: ;tag=80b374c5886f0d2f86e27f008e41bdc4 (73) [Oct 1 10:47:55] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 5: i: 448732f666f0d30a344f7fa537d298d4@4.68.250.148 (48) [Oct 1 10:47:55] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 6: CSeq: 103 BYE (13) [Oct 1 10:47:55] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 7: Server: DC-SIP/1.2 (18) [Oct 1 10:47:55] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 8: k: timer (8) [Oct 1 10:47:55] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 9: l: 0 (4) [Oct 1 10:47:55] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 10: (0) --- (10 headers 0 lines) --- [Oct 1 10:47:55] DEBUG[26204]: chan_sip.c:4503 find_call: = No match Their Call ID: 5d01f10260451d3f5d7806371977a78c@66.192.107.225 Their Tag Our tag: as0dcb19f8 [Oct 1 10:47:55] DEBUG[26204]: chan_sip.c:4503 find_call: = Found Their Call ID: 448732f666f0d30a344f7fa537d298d4@4.68.250.148 Their Tag 80b374c5886f0d2f86e27f008e41bdc4 Our tag: as111394d8 [Oct 1 10:47:55] DEBUG[26204]: chan_sip.c:2148 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #88928 [Oct 1 10:47:55] DEBUG[26204]: chan_sip.c:2158 __sip_ack: Stopping retransmission on '448732f666f0d30a344f7fa537d298d4@4.68.250.148' of Request 103: Match Not Found [Oct 1 10:47:55] DEBUG[26204]: chan_sip.c:1897 retrans_pkt: SIP TIMER: Not rescheduling id #88926:OPTIONS (Method 3) (No timer T1) Retransmitting #1 (NAT) to 72.187.95.191:5060: OPTIONS sip:phone2@192.168.2.5:5060 SIP/2.0 Via: SIP/2.0/UDP 66.192.107.225:5060;branch=z9hG4bK3e86dc06;rport From: "asterisk" ;tag=as0dcb19f8 To: Contact: Call-ID: 5d01f10260451d3f5d7806371977a78c@66.192.107.225 CSeq: 102 OPTIONS User-Agent: Asterisk PBX Max-Forwards: 70 Date: Mon, 01 Oct 2007 14:47:54 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 --- [Oct 1 10:47:56] DEBUG[26204]: chan_sip.c:4450 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Oct 1 10:47:56] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 0: OPTIONS sip:office4@192.168.2.7:5060 SIP/2.0 (44) [Oct 1 10:47:56] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 1: Via: SIP/2.0/UDP 66.192.107.225:5060;branch=z9hG4bK2c037834;rport (65) [Oct 1 10:47:56] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 2: From: "asterisk" ;tag=as4a57aee9 (61) [Oct 1 10:47:56] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 3: To: (34) [Oct 1 10:47:56] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 4: Contact: (38) [Oct 1 10:47:56] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 5: Call-ID: 26046bef17a68baf5517b2106b798aa0@66.192.107.225 (56) [Oct 1 10:47:56] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 6: CSeq: 102 OPTIONS (17) [Oct 1 10:47:56] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 7: User-Agent: Asterisk PBX (24) [Oct 1 10:47:56] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 8: Max-Forwards: 70 (16) [Oct 1 10:47:56] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 9: Date: Mon, 01 Oct 2007 14:47:56 GMT (35) [Oct 1 10:47:56] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Oct 1 10:47:56] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 11: Supported: replaces (19) [Oct 1 10:47:56] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 12: Content-Length: 0 (17) Reliably Transmitting (NAT) to 72.187.95.191:64725: OPTIONS sip:office4@192.168.2.7:5060 SIP/2.0 Via: SIP/2.0/UDP 66.192.107.225:5060;branch=z9hG4bK2c037834;rport From: "asterisk" ;tag=as4a57aee9 To: Contact: Call-ID: 26046bef17a68baf5517b2106b798aa0@66.192.107.225 CSeq: 102 OPTIONS User-Agent: Asterisk PBX Max-Forwards: 70 Date: Mon, 01 Oct 2007 14:47:56 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 --- [Oct 1 10:47:56] DEBUG[26204]: sched.c:284 ast_sched_del: Attempted to delete nonexistent schedule entry 0! [Oct 1 10:47:56] DEBUG[26204]: chan_sip.c:2037 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #88932 [Oct 1 10:47:56] DEBUG[26204]: chan_sip.c:1897 retrans_pkt: SIP TIMER: Not rescheduling id #88926:OPTIONS (Method 3) (No timer T1) Retransmitting #2 (NAT) to 72.187.95.191:5060: OPTIONS sip:phone2@192.168.2.5:5060 SIP/2.0 Via: SIP/2.0/UDP 66.192.107.225:5060;branch=z9hG4bK3e86dc06;rport From: "asterisk" ;tag=as0dcb19f8 To: Contact: Call-ID: 5d01f10260451d3f5d7806371977a78c@66.192.107.225 CSeq: 102 OPTIONS User-Agent: Asterisk PBX Max-Forwards: 70 Date: Mon, 01 Oct 2007 14:47:54 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 --- [Oct 1 10:47:57] DEBUG[26204]: chan_sip.c:1897 retrans_pkt: SIP TIMER: Not rescheduling id #88932:OPTIONS (Method 3) (No timer T1) Retransmitting #1 (NAT) to 72.187.95.191:64725: OPTIONS sip:office4@192.168.2.7:5060 SIP/2.0 Via: SIP/2.0/UDP 66.192.107.225:5060;branch=z9hG4bK2c037834;rport From: "asterisk" ;tag=as4a57aee9 To: Contact: Call-ID: 26046bef17a68baf5517b2106b798aa0@66.192.107.225 CSeq: 102 OPTIONS User-Agent: Asterisk PBX Max-Forwards: 70 Date: Mon, 01 Oct 2007 14:47:56 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 --- [Oct 1 10:47:57] DEBUG[26204]: chan_sip.c:1897 retrans_pkt: SIP TIMER: Not rescheduling id #88926:OPTIONS (Method 3) (No timer T1) Retransmitting #3 (NAT) to 72.187.95.191:5060: OPTIONS sip:phone2@192.168.2.5:5060 SIP/2.0 Via: SIP/2.0/UDP 66.192.107.225:5060;branch=z9hG4bK3e86dc06;rport From: "asterisk" ;tag=as0dcb19f8 To: Contact: Call-ID: 5d01f10260451d3f5d7806371977a78c@66.192.107.225 CSeq: 102 OPTIONS User-Agent: Asterisk PBX Max-Forwards: 70 Date: Mon, 01 Oct 2007 14:47:54 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 --- [Oct 1 10:47:58] DEBUG[26204]: chan_sip.c:1897 retrans_pkt: SIP TIMER: Not rescheduling id #88932:OPTIONS (Method 3) (No timer T1) Retransmitting #2 (NAT) to 72.187.95.191:64725: OPTIONS sip:office4@192.168.2.7:5060 SIP/2.0 Via: SIP/2.0/UDP 66.192.107.225:5060;branch=z9hG4bK2c037834;rport From: "asterisk" ;tag=as4a57aee9 To: Contact: Call-ID: 26046bef17a68baf5517b2106b798aa0@66.192.107.225 CSeq: 102 OPTIONS User-Agent: Asterisk PBX Max-Forwards: 70 Date: Mon, 01 Oct 2007 14:47:56 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 --- pbx*CLI> <--- SIP read from 72.187.88.46:5060 ---> NOTIFY sip:pbx.elephantoutlook.com SIP/2.0 Via: SIP/2.0/UDP 192.168.0.118:5060;branch=z9hG4bK-b6f07df8 From: "Home 3" ;tag=25bcc698ae6160dbo0 To: Call-ID: 12d04ff8-211466fb@192.168.0.118 CSeq: 87826 NOTIFY Max-Forwards: 70 Event: keep-alive User-Agent: Sipura/SPA941-4.1.8 Content-Length: 0 <-------------> [Oct 1 10:47:58] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 0: NOTIFY sip:pbx.elephantoutlook.com SIP/2.0 (42) [Oct 1 10:47:58] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.0.118:5060;branch=z9hG4bK-b6f07df8 (59) [Oct 1 10:47:58] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 2: From: "Home 3" ;tag=25bcc698ae6160dbo0 (81) [Oct 1 10:47:58] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 3: To: (33) [Oct 1 10:47:58] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 4: Call-ID: 12d04ff8-211466fb@192.168.0.118 (40) [Oct 1 10:47:58] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 5: CSeq: 87826 NOTIFY (18) [Oct 1 10:47:58] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 6: Max-Forwards: 70 (16) [Oct 1 10:47:58] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 7: Event: keep-alive (17) [Oct 1 10:47:58] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 8: User-Agent: Sipura/SPA941-4.1.8 (31) [Oct 1 10:47:58] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 9: Content-Length: 0 (17) [Oct 1 10:47:58] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 10: (0) --- (10 headers 0 lines) --- [Oct 1 10:47:58] DEBUG[26204]: chan_sip.c:4503 find_call: = No match Their Call ID: 26046bef17a68baf5517b2106b798aa0@66.192.107.225 Their Tag Our tag: as4a57aee9 [Oct 1 10:47:58] DEBUG[26204]: chan_sip.c:4503 find_call: = No match Their Call ID: 5d01f10260451d3f5d7806371977a78c@66.192.107.225 Their Tag Our tag: as0dcb19f8 [Oct 1 10:47:58] DEBUG[26204]: chan_sip.c:4503 find_call: = No match Their Call ID: 448732f666f0d30a344f7fa537d298d4@4.68.250.148 Their Tag 80b374c5886f0d2f86e27f008e41bdc4 Our tag: as111394d8 [Oct 1 10:47:58] DEBUG[26204]: chan_sip.c:4503 find_call: = No match Their Call ID: ededa8e-5e7073a9@192.168.22.22 Their Tag dcfcb54af05ff81do0 Our tag: as32006948 <--- Transmitting (no NAT) to 72.187.88.46:5060 ---> SIP/2.0 489 Bad event Via: SIP/2.0/UDP 192.168.0.118:5060;branch=z9hG4bK-b6f07df8;received=72.187.88.46 From: "Home 3" ;tag=25bcc698ae6160dbo0 To: ;tag=as15db1849 Call-ID: 12d04ff8-211466fb@192.168.0.118 CSeq: 87826 NOTIFY User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 <------------> [Oct 1 10:47:58] DEBUG[26204]: chan_sip.c:15128 sipsock_read: Invalid SIP message - rejected , no callid, len 376 [Oct 1 10:47:58] DEBUG[26204]: chan_sip.c:1897 retrans_pkt: SIP TIMER: Not rescheduling id #88926:OPTIONS (Method 3) (No timer T1) Retransmitting #4 (NAT) to 72.187.95.191:5060: OPTIONS sip:phone2@192.168.2.5:5060 SIP/2.0 Via: SIP/2.0/UDP 66.192.107.225:5060;branch=z9hG4bK3e86dc06;rport From: "asterisk" ;tag=as0dcb19f8 To: Contact: Call-ID: 5d01f10260451d3f5d7806371977a78c@66.192.107.225 CSeq: 102 OPTIONS User-Agent: Asterisk PBX Max-Forwards: 70 Date: Mon, 01 Oct 2007 14:47:54 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 --- [Oct 1 10:47:58] DEBUG[26204]: chan_sip.c:3242 sip_destroy: Destroying SIP dialog 5d01f10260451d3f5d7806371977a78c@66.192.107.225 Really destroying SIP dialog '5d01f10260451d3f5d7806371977a78c@66.192.107.225' Method: OPTIONS [Oct 1 10:47:58] DEBUG[26204]: devicestate.c:306 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/phone2 [Oct 1 10:47:58] DEBUG[26175]: devicestate.c:163 ast_device_state: No provider found, checking channel drivers for SIP - phone2 [Oct 1 10:47:58] DEBUG[26175]: chan_sip.c:15574 sip_devicestate: Checking device state for peer phone2 [Oct 1 10:47:58] DEBUG[26175]: devicestate.c:289 do_state_change: Changing state for SIP/phone2 - state 1 (Not in use) [Oct 1 10:47:58] DEBUG[4082]: app_queue.c:554 changethread: Device 'SIP/phone2' changed to state '1' (Not in use) [Oct 1 10:47:59] DEBUG[26204]: chan_sip.c:1897 retrans_pkt: SIP TIMER: Not rescheduling id #88932:OPTIONS (Method 3) (No timer T1) Retransmitting #3 (NAT) to 72.187.95.191:64725: OPTIONS sip:office4@192.168.2.7:5060 SIP/2.0 Via: SIP/2.0/UDP 66.192.107.225:5060;branch=z9hG4bK2c037834;rport From: "asterisk" ;tag=as4a57aee9 To: Contact: Call-ID: 26046bef17a68baf5517b2106b798aa0@66.192.107.225 CSeq: 102 OPTIONS User-Agent: Asterisk PBX Max-Forwards: 70 Date: Mon, 01 Oct 2007 14:47:56 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 --- [Oct 1 10:48:00] DEBUG[26204]: chan_sip.c:1897 retrans_pkt: SIP TIMER: Not rescheduling id #88932:OPTIONS (Method 3) (No timer T1) Retransmitting #4 (NAT) to 72.187.95.191:64725: OPTIONS sip:office4@192.168.2.7:5060 SIP/2.0 Via: SIP/2.0/UDP 66.192.107.225:5060;branch=z9hG4bK2c037834;rport From: "asterisk" ;tag=as4a57aee9 To: Contact: Call-ID: 26046bef17a68baf5517b2106b798aa0@66.192.107.225 CSeq: 102 OPTIONS User-Agent: Asterisk PBX Max-Forwards: 70 Date: Mon, 01 Oct 2007 14:47:56 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 --- [Oct 1 10:48:00] DEBUG[26204]: chan_sip.c:3242 sip_destroy: Destroying SIP dialog 26046bef17a68baf5517b2106b798aa0@66.192.107.225 Really destroying SIP dialog '26046bef17a68baf5517b2106b798aa0@66.192.107.225' Method: OPTIONS [Oct 1 10:48:00] DEBUG[26204]: devicestate.c:306 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/office4 [Oct 1 10:48:00] DEBUG[26175]: devicestate.c:163 ast_device_state: No provider found, checking channel drivers for SIP - office4 [Oct 1 10:48:00] DEBUG[26175]: chan_sip.c:15574 sip_devicestate: Checking device state for peer office4 [Oct 1 10:48:00] DEBUG[26175]: devicestate.c:289 do_state_change: Changing state for SIP/office4 - state 1 (Not in use) [Oct 1 10:48:00] DEBUG[4083]: app_queue.c:554 changethread: Device 'SIP/office4' changed to state '1' (Not in use) [Oct 1 10:48:06] DEBUG[26204]: chan_sip.c:4450 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Oct 1 10:48:06] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 0: OPTIONS sip:home2@192.168.1.47:5060 SIP/2.0 (47) [Oct 1 10:48:06] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 1: Via: SIP/2.0/UDP 66.192.107.225:5060;branch=z9hG4bK7ec7fa14;rport (65) [Oct 1 10:48:06] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 2: From: "asterisk" ;tag=as04c9619e (61) [Oct 1 10:48:06] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 3: To: (37) [Oct 1 10:48:06] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 4: Contact: (38) [Oct 1 10:48:06] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 5: Call-ID: 1007aeb74939ae8241ea68101dff5e08@66.192.107.225 (56) [Oct 1 10:48:06] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 6: CSeq: 102 OPTIONS (17) [Oct 1 10:48:06] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 7: User-Agent: Asterisk PBX (24) [Oct 1 10:48:06] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 8: Max-Forwards: 70 (16) [Oct 1 10:48:06] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 9: Date: Mon, 01 Oct 2007 14:48:06 GMT (35) [Oct 1 10:48:06] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Oct 1 10:48:06] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 11: Supported: replaces (19) [Oct 1 10:48:06] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 12: Content-Length: 0 (17) Reliably Transmitting (NAT) to 71.101.36.190:50002: OPTIONS sip:home2@192.168.1.47:5060 SIP/2.0 Via: SIP/2.0/UDP 66.192.107.225:5060;branch=z9hG4bK7ec7fa14;rport From: "asterisk" ;tag=as04c9619e To: Contact: Call-ID: 1007aeb74939ae8241ea68101dff5e08@66.192.107.225 CSeq: 102 OPTIONS User-Agent: Asterisk PBX Max-Forwards: 70 Date: Mon, 01 Oct 2007 14:48:06 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 --- [Oct 1 10:48:06] DEBUG[26204]: sched.c:284 ast_sched_del: Attempted to delete nonexistent schedule entry 0! [Oct 1 10:48:06] DEBUG[26204]: chan_sip.c:2037 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #88936 pbx*CLI> <--- SIP read from 71.101.36.190:50002 ---> SIP/2.0 200 OK To: ;tag=3c08e80a6d855e66i0 From: "asterisk" ;tag=as04c9619e Call-ID: 1007aeb74939ae8241ea68101dff5e08@66.192.107.225 CSeq: 102 OPTIONS Via: SIP/2.0/UDP 66.192.107.225:5060;branch=z9hG4bK7ec7fa14 Server: Sipura/SPA941-4.1.8 Content-Length: 0 Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER <-------------> [Oct 1 10:48:06] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 0: SIP/2.0 200 OK (14) [Oct 1 10:48:06] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 1: To: ;tag=3c08e80a6d855e66i0 (60) [Oct 1 10:48:06] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 2: From: "asterisk" ;tag=as04c9619e (61) [Oct 1 10:48:06] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 3: Call-ID: 1007aeb74939ae8241ea68101dff5e08@66.192.107.225 (56) [Oct 1 10:48:06] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 4: CSeq: 102 OPTIONS (17) [Oct 1 10:48:06] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 5: Via: SIP/2.0/UDP 66.192.107.225:5060;branch=z9hG4bK7ec7fa14 (59) [Oct 1 10:48:06] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 6: Server: Sipura/SPA941-4.1.8 (27) [Oct 1 10:48:06] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 7: Content-Length: 0 (17) [Oct 1 10:48:06] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 8: Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER (61) [Oct 1 10:48:06] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 9: (0) --- (9 headers 0 lines) --- [Oct 1 10:48:06] DEBUG[26204]: chan_sip.c:4503 find_call: = Found Their Call ID: 1007aeb74939ae8241ea68101dff5e08@66.192.107.225 Their Tag Our tag: as04c9619e [Oct 1 10:48:06] DEBUG[26204]: chan_sip.c:2148 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #88936 [Oct 1 10:48:06] DEBUG[26204]: chan_sip.c:2158 __sip_ack: Stopping retransmission on '1007aeb74939ae8241ea68101dff5e08@66.192.107.225' of Request 102: Match Not Found Really destroying SIP dialog '1007aeb74939ae8241ea68101dff5e08@66.192.107.225' Method: OPTIONS pbx*CLI> <--- SIP read from 71.52.101.157:5060 ---> BYE sip:15559942999@66.192.107.225 SIP/2.0 Via: SIP/2.0/UDP 192.168.22.22:5060;branch=z9hG4bK-89469406 From: "Jon" ;tag=dcfcb54af05ff81do0 To: ;tag=as32006948 Call-ID: ededa8e-5e7073a9@192.168.22.22 CSeq: 103 BYE Max-Forwards: 70 Proxy-Authorization: Digest username="jon",realm="asterisk",nonce="39375bd1",uri="sip:15559942999@66.192.107.225",algorithm=MD5,response="ee235813b5b2c7cde8affaff920318fc" User-Agent: Sipura/SPA941-4.1.8 Content-Length: 0 <-------------> [Oct 1 10:48:07] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 0: BYE sip:15559942999@66.192.107.225 SIP/2.0 (42) [Oct 1 10:48:07] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.22.22:5060;branch=z9hG4bK-89469406 (59) [Oct 1 10:48:07] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 2: From: "Jon" ;tag=dcfcb54af05ff81do0 (76) [Oct 1 10:48:07] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 3: To: ;tag=as32006948 (60) [Oct 1 10:48:07] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 4: Call-ID: ededa8e-5e7073a9@192.168.22.22 (39) [Oct 1 10:48:07] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 5: CSeq: 103 BYE (13) [Oct 1 10:48:07] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 6: Max-Forwards: 70 (16) [Oct 1 10:48:07] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 7: Proxy-Authorization: Digest username="jon",realm="asterisk",nonce="39375bd1",uri="sip:15559942999@66.192.107.225",algorithm=MD5,response="ee235813b5b2c7cde8affaff920318fc" (171) [Oct 1 10:48:07] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 8: User-Agent: Sipura/SPA941-4.1.8 (31) [Oct 1 10:48:07] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 9: Content-Length: 0 (17) [Oct 1 10:48:07] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 10: (0) --- (10 headers 0 lines) --- [Oct 1 10:48:07] DEBUG[26204]: chan_sip.c:4503 find_call: = No match Their Call ID: 448732f666f0d30a344f7fa537d298d4@4.68.250.148 Their Tag 80b374c5886f0d2f86e27f008e41bdc4 Our tag: as111394d8 [Oct 1 10:48:07] DEBUG[26204]: chan_sip.c:4503 find_call: = Found Their Call ID: ededa8e-5e7073a9@192.168.22.22 Their Tag dcfcb54af05ff81do0 Our tag: as32006948 [Oct 1 10:48:07] DEBUG[26204]: chan_sip.c:14944 handle_request: **** Received BYE (8) - Command in SIP BYE Sending to 71.52.101.157 : 5060 (NAT) [Oct 1 10:48:07] DEBUG[26204]: chan_sip.c:1646 sip_alreadygone: Setting SIP_ALREADYGONE on dialog ededa8e-5e7073a9@192.168.22.22 [Oct 1 10:48:07] DEBUG[26204]: chan_sip.c:14486 handle_request_bye: Received bye, issuing owner hangup <--- Transmitting (NAT) to 71.52.101.157:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.22.22:5060;branch=z9hG4bK-89469406;received=71.52.101.157 From: "Jon" ;tag=dcfcb54af05ff81do0 To: ;tag=as32006948 Call-ID: ededa8e-5e7073a9@192.168.22.22 CSeq: 103 BYE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Oct 1 10:48:07] DEBUG[4077]: channel.c:4043 ast_generic_bridge: Didn't get a frame from channel: SIP/jon-08331348 [Oct 1 10:48:07] DEBUG[4077]: channel.c:4371 ast_channel_bridge: Bridge stops bridging channels SIP/jon-08331348 and SIP/bandwidth-08429420 [Oct 1 10:48:07] DEBUG[4077]: channel.c:1783 ast_hangup: Hanging up channel 'SIP/bandwidth-08429420' [Oct 1 10:48:07] DEBUG[4077]: chan_sip.c:3445 sip_hangup: Hangup call SIP/bandwidth-08429420, SIP callid 448732f666f0d30a344f7fa537d298d4@4.68.250.148) Scheduling destruction of SIP dialog '448732f666f0d30a344f7fa537d298d4@4.68.250.148' in 32000 ms (Method: INVITE) set_destination: Parsing for address/port to send to set_destination: set destination to 216.82.224.202, port 5060 Reliably Transmitting (no NAT) to 216.82.224.202:5060: BYE sip:5559942999@204.13.236.129:5060;transport=udp SIP/2.0 Via: SIP/2.0/UDP 66.192.107.225:5060;branch=z9hG4bK6035b716;rport Route: From: "Elephant Outlook" ;tag=as111394d8 To: ;tag=80b374c5886f0d2f86e27f008e41bdc4 Call-ID: 448732f666f0d30a344f7fa537d298d4@4.68.250.148 CSeq: 104 BYE User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- [Oct 1 10:48:07] DEBUG[4077]: sched.c:284 ast_sched_del: Attempted to delete nonexistent schedule entry 0! [Oct 1 10:48:07] DEBUG[4077]: chan_sip.c:2037 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #88940 [Oct 1 10:48:07] DEBUG[4077]: devicestate.c:306 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/bandwidth-08429420 [Oct 1 10:48:07] DEBUG[4077]: rtp.c:1499 ast_rtp_early_bridge: Channel '' has no RTP, not doing anything [Oct 1 10:48:07] DEBUG[4077]: app_dial.c:1709 dial_exec_full: Exiting with DIALSTATUS=ANSWER. [Oct 1 10:48:07] DEBUG[4077]: pbx.c:2407 __ast_pbx_run: Spawn extension (local,dial-15559942999,6) exited non-zero on 'SIP/jon-08331348' == Spawn extension (local, dial-15559942999, 6) exited non-zero on 'SIP/jon-08331348' [Oct 1 10:48:07] DEBUG[4077]: channel.c:1566 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/jon-08331348' [Oct 1 10:48:07] DEBUG[4077]: channel.c:1783 ast_hangup: Hanging up channel 'SIP/jon-08331348' [Oct 1 10:48:07] DEBUG[4077]: chan_sip.c:3445 sip_hangup: Hangup call SIP/jon-08331348, SIP callid ededa8e-5e7073a9@192.168.22.22) [Oct 1 10:48:07] DEBUG[4077]: chan_sip.c:3454 sip_hangup: update_call_counter(jon) - decrement call limit counter on hangup [Oct 1 10:48:07] DEBUG[4077]: chan_sip.c:3133 update_call_counter: Updating call counter for incoming call [Oct 1 10:48:07] DEBUG[4077]: chan_sip.c:3184 update_call_counter: Call from peer 'jon' removed from call limit 100 [Oct 1 10:48:07] DEBUG[4077]: devicestate.c:306 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/jon [Oct 1 10:48:07] DEBUG[4077]: devicestate.c:306 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/jon-08331348 [Oct 1 10:48:07] DEBUG[4077]: cdr_radius.c:221 radius_log: Unable to create RADIUS record. CDR not recorded! Really destroying SIP dialog 'ededa8e-5e7073a9@192.168.22.22' Method: BYE [Oct 1 10:48:07] DEBUG[26175]: devicestate.c:163 ast_device_state: No provider found, checking channel drivers for SIP - bandwidth [Oct 1 10:48:07] DEBUG[26175]: chan_sip.c:15574 sip_devicestate: Checking device state for peer bandwidth [Oct 1 10:48:07] DEBUG[26175]: devicestate.c:289 do_state_change: Changing state for SIP/bandwidth - state 1 (Not in use) [Oct 1 10:48:07] DEBUG[26175]: devicestate.c:163 ast_device_state: No provider found, checking channel drivers for SIP - jon [Oct 1 10:48:07] DEBUG[26175]: chan_sip.c:15574 sip_devicestate: Checking device state for peer jon [Oct 1 10:48:07] DEBUG[26175]: devicestate.c:289 do_state_change: Changing state for SIP/jon - state 1 (Not in use) [Oct 1 10:48:07] DEBUG[26175]: devicestate.c:163 ast_device_state: No provider found, checking channel drivers for SIP - jon [Oct 1 10:48:07] DEBUG[26175]: chan_sip.c:15574 sip_devicestate: Checking device state for peer jon [Oct 1 10:48:07] DEBUG[26175]: devicestate.c:289 do_state_change: Changing state for SIP/jon - state 1 (Not in use) [Oct 1 10:48:07] DEBUG[4085]: app_queue.c:548 changethread: Device 'SIP/bandwidth' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Oct 1 10:48:07] DEBUG[4086]: app_queue.c:554 changethread: Device 'SIP/jon' changed to state '1' (Not in use) [Oct 1 10:48:07] DEBUG[4087]: app_queue.c:554 changethread: Device 'SIP/jon' changed to state '1' (Not in use) pbx*CLI> <--- SIP read from 216.82.224.202:5060 ---> SIP/2.0 481 Transaction Does Not Exist v: SIP/2.0/UDP 66.192.107.225:5060;branch=z9hG4bK6035b716;rport=5060 From: "Elephant Outlook" ;tag=as111394d8 t: ;tag=7750116 i: 448732f666f0d30a344f7fa537d298d4@4.68.250.148 CSeq: 104 BYE User-Agent: Asterisk PBX l: 0 <-------------> [Oct 1 10:48:07] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 0: SIP/2.0 481 Transaction Does Not Exist (38) [Oct 1 10:48:07] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 1: v: SIP/2.0/UDP 66.192.107.225:5060;branch=z9hG4bK6035b716;rport=5060 (68) [Oct 1 10:48:07] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 2: From: "Elephant Outlook" ;tag=as111394d8 (71) [Oct 1 10:48:07] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 3: t: ;tag=7750116 (48) [Oct 1 10:48:07] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 4: i: 448732f666f0d30a344f7fa537d298d4@4.68.250.148 (48) [Oct 1 10:48:07] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 5: CSeq: 104 BYE (13) [Oct 1 10:48:07] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 6: User-Agent: Asterisk PBX (24) [Oct 1 10:48:07] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 7: l: 0 (4) [Oct 1 10:48:07] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 8: (0) --- (8 headers 0 lines) --- [Oct 1 10:48:07] DEBUG[26204]: chan_sip.c:4503 find_call: = Found Their Call ID: 448732f666f0d30a344f7fa537d298d4@4.68.250.148 Their Tag 80b374c5886f0d2f86e27f008e41bdc4 Our tag: as111394d8 [Oct 1 10:48:07] DEBUG[26204]: chan_sip.c:2148 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #88940 [Oct 1 10:48:07] DEBUG[26204]: chan_sip.c:2158 __sip_ack: Stopping retransmission on '448732f666f0d30a344f7fa537d298d4@4.68.250.148' of Request 104: Match Not Found [Oct 1 10:48:07] WARNING[26204]: chan_sip.c:12528 handle_response: Remote host can't match request BYE to call '448732f666f0d30a344f7fa537d298d4@4.68.250.148'. Giving up. Really destroying SIP dialog '448732f666f0d30a344f7fa537d298d4@4.68.250.148' Method: INVITE [Oct 1 10:48:08] DEBUG[26204]: chan_sip.c:4450 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Oct 1 10:48:08] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 0: OPTIONS sip:phone2@192.168.2.5:5060 SIP/2.0 (50) [Oct 1 10:48:08] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 1: Via: SIP/2.0/UDP 66.192.107.225:5060;branch=z9hG4bK1a620a3a;rport (65) [Oct 1 10:48:08] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 2: From: "asterisk" ;tag=as1a6af602 (61) [Oct 1 10:48:08] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 3: To: (40) [Oct 1 10:48:08] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 4: Contact: (38) [Oct 1 10:48:08] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 5: Call-ID: 3dec0aeb44f409a07f28dfc615aea302@66.192.107.225 (56) [Oct 1 10:48:08] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 6: CSeq: 102 OPTIONS (17) [Oct 1 10:48:08] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 7: User-Agent: Asterisk PBX (24) [Oct 1 10:48:08] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 8: Max-Forwards: 70 (16) [Oct 1 10:48:08] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 9: Date: Mon, 01 Oct 2007 14:48:08 GMT (35) [Oct 1 10:48:08] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Oct 1 10:48:08] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 11: Supported: replaces (19) [Oct 1 10:48:08] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 12: Content-Length: 0 (17) Reliably Transmitting (NAT) to 72.187.95.191:5060: OPTIONS sip:phone2@192.168.2.5:5060 SIP/2.0 Via: SIP/2.0/UDP 66.192.107.225:5060;branch=z9hG4bK1a620a3a;rport From: "asterisk" ;tag=as1a6af602 To: Contact: Call-ID: 3dec0aeb44f409a07f28dfc615aea302@66.192.107.225 CSeq: 102 OPTIONS User-Agent: Asterisk PBX Max-Forwards: 70 Date: Mon, 01 Oct 2007 14:48:08 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 --- [Oct 1 10:48:08] DEBUG[26204]: sched.c:284 ast_sched_del: Attempted to delete nonexistent schedule entry 0! [Oct 1 10:48:08] DEBUG[26204]: chan_sip.c:2037 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #88941 pbx*CLI> <--- SIP read from 71.101.36.190:50002 ---> NOTIFY sip:pbx.elephantoutlook.com SIP/2.0 Via: SIP/2.0/UDP 192.168.1.47:5060;branch=z9hG4bK-4e189d49 From: "Home 2" ;tag=f3edfbba5123de76o0 To: Call-ID: 4b0be73a-76f2e8f6@192.168.1.47 CSeq: 131666 NOTIFY Max-Forwards: 70 Event: keep-alive User-Agent: Sipura/SPA941-4.1.8 Content-Length: 0 <-------------> [Oct 1 10:48:09] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 0: NOTIFY sip:pbx.elephantoutlook.com SIP/2.0 (42) [Oct 1 10:48:09] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.47:5060;branch=z9hG4bK-4e189d49 (58) [Oct 1 10:48:09] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 2: From: "Home 2" ;tag=f3edfbba5123de76o0 (84) [Oct 1 10:48:09] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 3: To: (33) [Oct 1 10:48:09] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 4: Call-ID: 4b0be73a-76f2e8f6@192.168.1.47 (39) [Oct 1 10:48:09] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 5: CSeq: 131666 NOTIFY (19) [Oct 1 10:48:09] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 6: Max-Forwards: 70 (16) [Oct 1 10:48:09] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 7: Event: keep-alive (17) [Oct 1 10:48:09] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 8: User-Agent: Sipura/SPA941-4.1.8 (31) [Oct 1 10:48:09] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 9: Content-Length: 0 (17) [Oct 1 10:48:09] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 10: (0) --- (10 headers 0 lines) --- [Oct 1 10:48:09] DEBUG[26204]: chan_sip.c:4503 find_call: = No match Their Call ID: 3dec0aeb44f409a07f28dfc615aea302@66.192.107.225 Their Tag Our tag: as1a6af602 <--- Transmitting (no NAT) to 71.101.36.190:50002 ---> SIP/2.0 489 Bad event Via: SIP/2.0/UDP 192.168.1.47:5060;branch=z9hG4bK-4e189d49;received=71.101.36.190 From: "Home 2" ;tag=f3edfbba5123de76o0 To: ;tag=as51fc3e21 Call-ID: 4b0be73a-76f2e8f6@192.168.1.47 CSeq: 131666 NOTIFY User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 <------------> [Oct 1 10:48:09] DEBUG[26204]: chan_sip.c:15128 sipsock_read: Invalid SIP message - rejected , no callid, len 378 [Oct 1 10:48:09] DEBUG[26204]: chan_sip.c:1897 retrans_pkt: SIP TIMER: Not rescheduling id #88941:OPTIONS (Method 3) (No timer T1) Retransmitting #1 (NAT) to 72.187.95.191:5060: OPTIONS sip:phone2@192.168.2.5:5060 SIP/2.0 Via: SIP/2.0/UDP 66.192.107.225:5060;branch=z9hG4bK1a620a3a;rport From: "asterisk" ;tag=as1a6af602 To: Contact: Call-ID: 3dec0aeb44f409a07f28dfc615aea302@66.192.107.225 CSeq: 102 OPTIONS User-Agent: Asterisk PBX Max-Forwards: 70 Date: Mon, 01 Oct 2007 14:48:08 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 --- [Oct 1 10:48:10] DEBUG[26194]: chan_iax2.c:8245 iax2_do_register: Allocate call number [Oct 1 10:48:10] DEBUG[26194]: chan_iax2.c:8251 iax2_do_register: Registration created on call 1 [Oct 1 10:48:10] DEBUG[26204]: chan_sip.c:4450 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Oct 1 10:48:10] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 0: OPTIONS sip:office4@192.168.2.7:5060 SIP/2.0 (44) [Oct 1 10:48:10] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 1: Via: SIP/2.0/UDP 66.192.107.225:5060;branch=z9hG4bK7a482d44;rport (65) [Oct 1 10:48:10] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 2: From: "asterisk" ;tag=as6d3c90d0 (61) [Oct 1 10:48:10] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 3: To: (34) [Oct 1 10:48:10] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 4: Contact: (38) [Oct 1 10:48:10] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 5: Call-ID: 7057453d7e225f361f83d56178b1f643@66.192.107.225 (56) [Oct 1 10:48:10] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 6: CSeq: 102 OPTIONS (17) [Oct 1 10:48:10] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 7: User-Agent: Asterisk PBX (24) [Oct 1 10:48:10] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 8: Max-Forwards: 70 (16) [Oct 1 10:48:10] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 9: Date: Mon, 01 Oct 2007 14:48:10 GMT (35) [Oct 1 10:48:10] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Oct 1 10:48:10] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 11: Supported: replaces (19) [Oct 1 10:48:10] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 12: Content-Length: 0 (17) Reliably Transmitting (NAT) to 72.187.95.191:64725: OPTIONS sip:office4@192.168.2.7:5060 SIP/2.0 Via: SIP/2.0/UDP 66.192.107.225:5060;branch=z9hG4bK7a482d44;rport From: "asterisk" ;tag=as6d3c90d0 To: Contact: Call-ID: 7057453d7e225f361f83d56178b1f643@66.192.107.225 CSeq: 102 OPTIONS User-Agent: Asterisk PBX Max-Forwards: 70 Date: Mon, 01 Oct 2007 14:48:10 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 --- [Oct 1 10:48:10] DEBUG[26204]: sched.c:284 ast_sched_del: Attempted to delete nonexistent schedule entry 0! [Oct 1 10:48:10] DEBUG[26204]: chan_sip.c:2037 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #88943 pbx*CLI> sip debug <--- SIP read from 72.187.88.46:5061 ---> NOTIFY sip:pbx.elephantoutlook.com SIP/2.0 Via: SIP/2.0/UDP 192.168.0.100:5061;branch=z9hG4bK-3039139d From: "Phone" ;tag=3d2da667eecdead6o0 To: Call-ID: 1a47d947-de4e5576@192.168.0.100 CSeq: 87856 NOTIFY Max-Forwards: 70 Event: keep-alive User-Agent: Sipura/SPA941-4.1.9 Content-Length: 0 <-------------> [Oct 1 10:48:10] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 0: NOTIFY sip:pbx.elephantoutlook.com SIP/2.0 (42) [Oct 1 10:48:10] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.0.100:5061;branch=z9hG4bK-3039139d (59) [Oct 1 10:48:10] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 2: From: "Phone" ;tag=3d2da667eecdead6o0 (86) [Oct 1 10:48:10] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 3: To: (33) [Oct 1 10:48:10] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 4: Call-ID: 1a47d947-de4e5576@192.168.0.100 (40) [Oct 1 10:48:10] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 5: CSeq: 87856 NOTIFY (18) [Oct 1 10:48:10] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 6: Max-Forwards: 70 (16) [Oct 1 10:48:10] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 7: Event: keep-alive (17) [Oct 1 10:48:10] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 8: User-Agent: Sipura/SPA941-4.1.9 (31) [Oct 1 10:48:10] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 9: Content-Length: 0 (17) [Oct 1 10:48:10] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 10: (0) --- (10 headers 0 lines) --- [Oct 1 10:48:10] DEBUG[26204]: chan_sip.c:4503 find_call: = No match Their Call ID: 7057453d7e225f361f83d56178b1f643@66.192.107.225 Their Tag Our tag: as6d3c90d0 [Oct 1 10:48:10] DEBUG[26204]: chan_sip.c:4503 find_call: = No match Their Call ID: 3dec0aeb44f409a07f28dfc615aea302@66.192.107.225 Their Tag Our tag: as1a6af602 <--- Transmitting (no NAT) to 72.187.88.46:5061 ---> SIP/2.0 489 Bad event Via: SIP/2.0/UDP 192.168.0.100:5061;branch=z9hG4bK-3039139d;received=72.187.88.46 From: "Phone" ;tag=3d2da667eecdead6o0 To: ;tag=as534b2509 Call-ID: 1a47d947-de4e5576@192.168.0.100 CSeq: 87856 NOTIFY User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 <------------> [Oct 1 10:48:10] DEBUG[26204]: chan_sip.c:15128 sipsock_read: Invalid SIP message - rejected , no callid, len 381 [Oct 1 10:48:10] DEBUG[26204]: chan_sip.c:1897 retrans_pkt: SIP TIMER: Not rescheduling id #88941:OPTIONS (Method 3) (No timer T1) Retransmitting #2 (NAT) to 72.187.95.191:5060: OPTIONS sip:phone2@192.168.2.5:5060 SIP/2.0 Via: SIP/2.0/UDP 66.192.107.225:5060;branch=z9hG4bK1a620a3a;rport From: "asterisk" ;tag=as1a6af602 To: Contact: Call-ID: 3dec0aeb44f409a07f28dfc615aea302@66.192.107.225 CSeq: 102 OPTIONS User-Agent: Asterisk PBX Max-Forwards: 70 Date: Mon, 01 Oct 2007 14:48:08 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 --- [Oct 1 10:48:11] DEBUG[26204]: chan_sip.c:1897 retrans_pkt: SIP TIMER: Not rescheduling id #88943:OPTIONS (Method 3) (No timer T1) Retransmitting #1 (NAT) to 72.187.95.191:64725: OPTIONS sip:office4@192.168.2.7:5060 SIP/2.0 Via: SIP/2.0/UDP 66.192.107.225:5060;branch=z9hG4bK7a482d44;rport From: "asterisk" ;tag=as6d3c90d0 To: Contact: Call-ID: 7057453d7e225f361f83d56178b1f643@66.192.107.225 CSeq: 102 OPTIONS User-Agent: Asterisk PBX Max-Forwards: 70 Date: Mon, 01 Oct 2007 14:48:10 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 --- [Oct 1 10:48:11] DEBUG[26204]: chan_sip.c:1897 retrans_pkt: SIP TIMER: Not rescheduling id #88941:OPTIONS (Method 3) (No timer T1) Retransmitting #3 (NAT) to 72.187.95.191:5060: OPTIONS sip:phone2@192.168.2.5:5060 SIP/2.0 Via: SIP/2.0/UDP 66.192.107.225:5060;branch=z9hG4bK1a620a3a;rport From: "asterisk" ;tag=as1a6af602 To: Contact: Call-ID: 3dec0aeb44f409a07f28dfc615aea302@66.192.107.225 CSeq: 102 OPTIONS User-Agent: Asterisk PBX Max-Forwards: 70 Date: Mon, 01 Oct 2007 14:48:08 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 --- [Oct 1 10:48:12] DEBUG[26204]: chan_sip.c:1897 retrans_pkt: SIP TIMER: Not rescheduling id #88943:OPTIONS (Method 3) (No timer T1) Retransmitting #2 (NAT) to 72.187.95.191:64725: OPTIONS sip:office4@192.168.2.7:5060 SIP/2.0 Via: SIP/2.0/UDP 66.192.107.225:5060;branch=z9hG4bK7a482d44;rport From: "asterisk" ;tag=as6d3c90d0 To: Contact: Call-ID: 7057453d7e225f361f83d56178b1f643@66.192.107.225 CSeq: 102 OPTIONS User-Agent: Asterisk PBX Max-Forwards: 70 Date: Mon, 01 Oct 2007 14:48:10 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 --- [Oct 1 10:48:12] DEBUG[26204]: chan_sip.c:1897 retrans_pkt: SIP TIMER: Not rescheduling id #88941:OPTIONS (Method 3) (No timer T1) Retransmitting #4 (NAT) to 72.187.95.191:5060: OPTIONS sip:phone2@192.168.2.5:5060 SIP/2.0 Via: SIP/2.0/UDP 66.192.107.225:5060;branch=z9hG4bK1a620a3a;rport From: "asterisk" ;tag=as1a6af602 To: Contact: Call-ID: 3dec0aeb44f409a07f28dfc615aea302@66.192.107.225 CSeq: 102 OPTIONS User-Agent: Asterisk PBX Max-Forwards: 70 Date: Mon, 01 Oct 2007 14:48:08 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 --- [Oct 1 10:48:12] DEBUG[26204]: chan_sip.c:3242 sip_destroy: Destroying SIP dialog 3dec0aeb44f409a07f28dfc615aea302@66.192.107.225 Really destroying SIP dialog '3dec0aeb44f409a07f28dfc615aea302@66.192.107.225' Method: OPTIONS [Oct 1 10:48:12] DEBUG[26204]: devicestate.c:306 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/phone2 [Oct 1 10:48:12] DEBUG[26175]: devicestate.c:163 ast_device_state: No provider found, checking channel drivers for SIP - phone2 [Oct 1 10:48:12] DEBUG[26175]: chan_sip.c:15574 sip_devicestate: Checking device state for peer phone2 [Oct 1 10:48:12] DEBUG[26175]: devicestate.c:289 do_state_change: Changing state for SIP/phone2 - state 1 (Not in use) [Oct 1 10:48:12] DEBUG[4088]: app_queue.c:554 changethread: Device 'SIP/phone2' changed to state '1' (Not in use) [Oct 1 10:48:13] DEBUG[26204]: chan_sip.c:1897 retrans_pkt: SIP TIMER: Not rescheduling id #88943:OPTIONS (Method 3) (No timer T1) Retransmitting #3 (NAT) to 72.187.95.191:64725: OPTIONS sip:office4@192.168.2.7:5060 SIP/2.0 Via: SIP/2.0/UDP 66.192.107.225:5060;branch=z9hG4bK7a482d44;rport From: "asterisk" ;tag=as6d3c90d0 To: Contact: Call-ID: 7057453d7e225f361f83d56178b1f643@66.192.107.225 CSeq: 102 OPTIONS User-Agent: Asterisk PBX Max-Forwards: 70 Date: Mon, 01 Oct 2007 14:48:10 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 --- pbx*CLI> core set debug 0 Core debug is now OFF pbx*CLI>