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 22 10:47:48] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 0: INVITE sip:15559942999@pbx.elephantoutlook.com SIP/2.0 (54) [Oct 22 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 22 10:47:48] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 2: From: "Jon" ;tag=dcfcb54af05ff81do0 (76) [Oct 22 10:47:48] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 3: To: (45) [Oct 22 10:47:48] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 4: Call-ID: ededa8e-5e7073a9@192.168.22.22 (39) [Oct 22 10:47:48] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 5: CSeq: 101 INVITE (16) [Oct 22 10:47:48] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 6: Max-Forwards: 70 (16) [Oct 22 10:47:48] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 7: Contact: "Jon" (51) [Oct 22 10:47:48] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 8: Expires: 240 (12) [Oct 22 10:47:48] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 9: User-Agent: Sipura/SPA941-4.1.8 (31) [Oct 22 10:47:48] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 10: Content-Length: 403 (19) [Oct 22 10:47:48] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 11: Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER (61) [Oct 22 10:47:48] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 12: Content-Type: application/sdp (29) [Oct 22 10:47:48] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 13: (0) [Oct 22 10:47:48] DEBUG[26204]: chan_sip.c:4747 parse_request: Line: v=0 (3) [Oct 22 10:47:48] DEBUG[26204]: chan_sip.c:4747 parse_request: Line: o=- 329124448 329124448 IN IP4 192.168.22.22 (44) [Oct 22 10:47:48] DEBUG[26204]: chan_sip.c:4747 parse_request: Line: s=- (3) [Oct 22 10:47:48] DEBUG[26204]: chan_sip.c:4747 parse_request: Line: c=IN IP4 192.168.22.22 (22) [Oct 22 10:47:48] DEBUG[26204]: chan_sip.c:4747 parse_request: Line: t=0 0 (5) [Oct 22 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 22 10:47:48] DEBUG[26204]: chan_sip.c:4747 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Oct 22 10:47:48] DEBUG[26204]: chan_sip.c:4747 parse_request: Line: a=rtpmap:2 G726-32/8000 (23) [Oct 22 10:47:48] DEBUG[26204]: chan_sip.c:4747 parse_request: Line: a=rtpmap:4 G723/8000 (20) [Oct 22 10:47:48] DEBUG[26204]: chan_sip.c:4747 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Oct 22 10:47:48] DEBUG[26204]: chan_sip.c:4747 parse_request: Line: a=rtpmap:18 G729a/8000 (22) [Oct 22 10:47:48] DEBUG[26204]: chan_sip.c:4747 parse_request: Line: a=rtpmap:96 G726-40/8000 (24) [Oct 22 10:47:48] DEBUG[26204]: chan_sip.c:4747 parse_request: Line: a=rtpmap:97 G726-24/8000 (24) [Oct 22 10:47:48] DEBUG[26204]: chan_sip.c:4747 parse_request: Line: a=rtpmap:98 G726-16/8000 (24) [Oct 22 10:47:48] DEBUG[26204]: chan_sip.c:4747 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Oct 22 10:47:48] DEBUG[26204]: chan_sip.c:4747 parse_request: Line: a=fmtp:101 0-15 (15) [Oct 22 10:47:48] DEBUG[26204]: chan_sip.c:4747 parse_request: Line: a=ptime:30 (10) [Oct 22 10:47:48] DEBUG[26204]: chan_sip.c:4747 parse_request: Line: a=sendrecv (10) --- (13 headers 18 lines) --- [Oct 22 10:47:48] DEBUG[26204]: chan_sip.c:2695 do_setnat: Setting NAT on RTP to Off [Oct 22 10:47:48] DEBUG[26204]: chan_sip.c:2700 do_setnat: Setting NAT on VRTP to Off [Oct 22 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 22 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 22 10:47:48] DEBUG[26204]: chan_sip.c:2695 do_setnat: Setting NAT on RTP to On [Oct 22 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 22 10:47:48] DEBUG[26204]: sched.c:284 ast_sched_del: Attempted to delete nonexistent schedule entry 0! [Oct 22 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 22 10:47:48] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 0: ACK sip:15559942999@pbx.elephantoutlook.com SIP/2.0 (51) [Oct 22 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 22 10:47:48] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 2: From: "Jon" ;tag=dcfcb54af05ff81do0 (76) [Oct 22 10:47:48] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 3: To: ;tag=as65a84993 (60) [Oct 22 10:47:48] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 4: Call-ID: ededa8e-5e7073a9@192.168.22.22 (39) [Oct 22 10:47:48] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 5: CSeq: 101 ACK (13) [Oct 22 10:47:48] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 6: Max-Forwards: 70 (16) [Oct 22 10:47:48] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 7: Contact: "Jon" (51) [Oct 22 10:47:48] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 8: User-Agent: Sipura/SPA941-4.1.8 (31) [Oct 22 10:47:48] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 9: Content-Length: 0 (17) [Oct 22 10:47:48] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 10: (0) --- (10 headers 0 lines) --- [Oct 22 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 22 10:47:48] DEBUG[26204]: chan_sip.c:14944 handle_request: **** Received ACK (6) - Command in SIP ACK [Oct 22 10:47:48] DEBUG[26204]: chan_sip.c:2148 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #88922 [Oct 22 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 22 10:47:48] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 0: INVITE sip:15559942999@pbx.elephantoutlook.com SIP/2.0 (54) [Oct 22 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 22 10:47:48] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 2: From: "Jon" ;tag=dcfcb54af05ff81do0 (76) [Oct 22 10:47:48] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 3: To: (45) [Oct 22 10:47:48] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 4: Call-ID: ededa8e-5e7073a9@192.168.22.22 (39) [Oct 22 10:47:48] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 5: CSeq: 102 INVITE (16) [Oct 22 10:47:48] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 6: Max-Forwards: 70 (16) [Oct 22 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 22 10:47:48] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 8: Contact: "Jon" (51) [Oct 22 10:47:48] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 9: Expires: 240 (12) [Oct 22 10:47:48] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 10: User-Agent: Sipura/SPA941-4.1.8 (31) [Oct 22 10:47:48] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 11: Content-Length: 403 (19) [Oct 22 10:47:48] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 12: Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER (61) [Oct 22 10:47:48] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 13: Content-Type: application/sdp (29) [Oct 22 10:47:48] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 14: (0) [Oct 22 10:47:48] DEBUG[26204]: chan_sip.c:4747 parse_request: Line: v=0 (3) [Oct 22 10:47:48] DEBUG[26204]: chan_sip.c:4747 parse_request: Line: o=- 329124448 329124448 IN IP4 192.168.22.22 (44) [Oct 22 10:47:48] DEBUG[26204]: chan_sip.c:4747 parse_request: Line: s=- (3) [Oct 22 10:47:48] DEBUG[26204]: chan_sip.c:4747 parse_request: Line: c=IN IP4 192.168.22.22 (22) [Oct 22 10:47:48] DEBUG[26204]: chan_sip.c:4747 parse_request: Line: t=0 0 (5) [Oct 22 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 22 10:47:48] DEBUG[26204]: chan_sip.c:4747 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Oct 22 10:47:48] DEBUG[26204]: chan_sip.c:4747 parse_request: Line: a=rtpmap:2 G726-32/8000 (23) [Oct 22 10:47:48] DEBUG[26204]: chan_sip.c:4747 parse_request: Line: a=rtpmap:4 G723/8000 (20) [Oct 22 10:47:48] DEBUG[26204]: chan_sip.c:4747 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Oct 22 10:47:48] DEBUG[26204]: chan_sip.c:4747 parse_request: Line: a=rtpmap:18 G729a/8000 (22) [Oct 22 10:47:48] DEBUG[26204]: chan_sip.c:4747 parse_request: Line: a=rtpmap:96 G726-40/8000 (24) [Oct 22 10:47:48] DEBUG[26204]: chan_sip.c:4747 parse_request: Line: a=rtpmap:97 G726-24/8000 (24) [Oct 22 10:47:48] DEBUG[26204]: chan_sip.c:4747 parse_request: Line: a=rtpmap:98 G726-16/8000 (24) [Oct 22 10:47:48] DEBUG[26204]: chan_sip.c:4747 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Oct 22 10:47:48] DEBUG[26204]: chan_sip.c:4747 parse_request: Line: a=fmtp:101 0-15 (15) [Oct 22 10:47:48] DEBUG[26204]: chan_sip.c:4747 parse_request: Line: a=ptime:30 (10) [Oct 22 10:47:48] DEBUG[26204]: chan_sip.c:4747 parse_request: Line: a=sendrecv (10) --- (14 headers 18 lines) --- [Oct 22 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 22 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 22 10:47:48] DEBUG[26204]: chan_sip.c:2695 do_setnat: Setting NAT on RTP to On [Oct 22 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 22 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 22 10:47:48] DEBUG[26204]: chan_sip.c:5381 process_sdp: We're settling with these formats: 0x4 (ulaw) [Oct 22 10:47:48] DEBUG[26204]: chan_sip.c:13626 handle_request_invite: Checking SIP call limits for device jon [Oct 22 10:47:48] DEBUG[26204]: chan_sip.c:3133 update_call_counter: Updating call counter for incoming call [Oct 22 10:47:48] DEBUG[26204]: chan_sip.c:3210 update_call_counter: Call from peer 'jon' is 1 out of 100 [Oct 22 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 22 10:47:48] DEBUG[26204]: chan_sip.c:3944 sip_new: *** Our native formats are 0x4 (ulaw) [Oct 22 10:47:48] DEBUG[26204]: chan_sip.c:3945 sip_new: *** Joint capabilities are 0x4 (ulaw) [Oct 22 10:47:48] DEBUG[26204]: chan_sip.c:3946 sip_new: *** Our capabilities are 0x80006 (gsm|ulaw|h263) [Oct 22 10:47:48] DEBUG[26204]: chan_sip.c:3947 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Oct 22 10:47:48] DEBUG[26204]: chan_sip.c:3970 sip_new: This channel will not be able to handle video. [Oct 22 10:47:48] DEBUG[26204]: chan_sip.c:8140 build_route: build_route: Contact hop: "Jon" list_route: hop: [Oct 22 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 22 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 22 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 22 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 22 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 22 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 22 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 22 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 22 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 22 10:47:48] DEBUG[4077]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is 'jon-08331348' [Oct 22 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 22 10:47:48] DEBUG[4077]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is 'jon' [Oct 22 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 22 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 22 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 22 10:47:48] DEBUG[4077]: chan_sip.c:15640 sip_request_call: Asked to create a SIP channel with formats: 0x4 (ulaw) [Oct 22 10:47:48] DEBUG[4077]: chan_sip.c:4450 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Oct 22 10:47:48] DEBUG[4077]: chan_sip.c:2695 do_setnat: Setting NAT on RTP to Off [Oct 22 10:47:48] DEBUG[4077]: chan_sip.c:2700 do_setnat: Setting NAT on VRTP to Off [Oct 22 10:47:48] DEBUG[4077]: chan_sip.c:3944 sip_new: *** Our native formats are 0x4 (ulaw) [Oct 22 10:47:48] DEBUG[4077]: chan_sip.c:3945 sip_new: *** Joint capabilities are 0x0 (nothing) [Oct 22 10:47:48] DEBUG[4077]: chan_sip.c:3946 sip_new: *** Our capabilities are 0x80006 (gsm|ulaw|h263) [Oct 22 10:47:48] DEBUG[4077]: chan_sip.c:3947 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Oct 22 10:47:48] DEBUG[4077]: chan_sip.c:3949 sip_new: *** Our preferred formats from the incoming channel are 0x4 (ulaw) [Oct 22 10:47:48] DEBUG[4077]: chan_sip.c:3970 sip_new: This channel will not be able to handle video. [Oct 22 10:47:48] DEBUG[4077]: channel.c:3538 ast_channel_inherit_variables: Not copying variable STACK-local-dial-15559942999-6. [Oct 22 10:47:48] DEBUG[4077]: channel.c:3538 ast_channel_inherit_variables: Not copying variable STACK-local-dial-15559942999-5. [Oct 22 10:47:48] DEBUG[4077]: channel.c:3538 ast_channel_inherit_variables: Not copying variable STACK-local-dial-15559942999-4. [Oct 22 10:47:49] DEBUG[4077]: channel.c:3538 ast_channel_inherit_variables: Not copying variable SIP_USER. [Oct 22 10:47:49] DEBUG[4077]: channel.c:3538 ast_channel_inherit_variables: Not copying variable STACK-local-dial-15559942999-3. [Oct 22 10:47:49] DEBUG[4077]: channel.c:3538 ast_channel_inherit_variables: Not copying variable SPYGROUP. [Oct 22 10:47:49] DEBUG[4077]: channel.c:3538 ast_channel_inherit_variables: Not copying variable STACK-local-dial-15559942999-2. [Oct 22 10:47:49] DEBUG[4077]: channel.c:3538 ast_channel_inherit_variables: Not copying variable STACK-local-dial-15559942999-1. [Oct 22 10:47:49] DEBUG[4077]: channel.c:3538 ast_channel_inherit_variables: Not copying variable STACK-local-provider-5-2. [Oct 22 10:47:49] DEBUG[4077]: channel.c:3538 ast_channel_inherit_variables: Not copying variable TRUNK. [Oct 22 10:47:49] DEBUG[4077]: channel.c:3538 ast_channel_inherit_variables: Not copying variable STACK-local-provider-5-1. [Oct 22 10:47:49] DEBUG[4077]: channel.c:3538 ast_channel_inherit_variables: Not copying variable STACK-local-515559942999-2. [Oct 22 10:47:49] DEBUG[4077]: channel.c:3538 ast_channel_inherit_variables: Not copying variable DIALSTRING. [Oct 22 10:47:49] DEBUG[4077]: channel.c:3538 ast_channel_inherit_variables: Not copying variable STACK-local-515559942999-1. [Oct 22 10:47:49] DEBUG[4077]: channel.c:3538 ast_channel_inherit_variables: Not copying variable STACK-local-15559942999-1. [Oct 22 10:47:49] DEBUG[4077]: channel.c:3538 ast_channel_inherit_variables: Not copying variable SIPCALLID. [Oct 22 10:47:49] DEBUG[4077]: channel.c:3538 ast_channel_inherit_variables: Not copying variable SIPUSERAGENT. [Oct 22 10:47:49] DEBUG[4077]: channel.c:3538 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [Oct 22 10:47:49] DEBUG[4077]: channel.c:3538 ast_channel_inherit_variables: Not copying variable SIPURI. [Oct 22 10:47:49] DEBUG[4077]: chan_sip.c:2953 sip_call: Outgoing Call for +15559942999 [Oct 22 10:47:49] DEBUG[4077]: chan_sip.c:3133 update_call_counter: Updating call counter for outgoing call [Oct 22 10:47:49] DEBUG[4077]: chan_sip.c:2968 sip_call: Our T38 capability (0), joint T38 capability (0) [Oct 22 10:47:49] DEBUG[4077]: chan_sip.c:6338 add_sdp: ** Our capability: 0x80006 (gsm|ulaw|h263) Video flag: False [Oct 22 10:47:49] DEBUG[4077]: chan_sip.c:6339 add_sdp: ** Our prefcodec: 0x4 (ulaw) [Oct 22 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 22 10:47:49] DEBUG[4077]: chan_sip.c:6470 add_sdp: -- Done with adding codecs to SDP [Oct 22 10:47:49] DEBUG[4077]: channel.c:2562 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=47) [Oct 22 10:47:49] DEBUG[4077]: chan_sip.c:6515 add_sdp: Done building SDP. Settling with this capability: 0x80006 (gsm|ulaw|h263) [Oct 22 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 22 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 22 10:47:49] DEBUG[4077]: chan_sip.c:4715 parse_request: Header 2: From: "Elephant Outlook" ;tag=as111394d8 (71) [Oct 22 10:47:49] DEBUG[4077]: chan_sip.c:4715 parse_request: Header 3: To: (37) [Oct 22 10:47:49] DEBUG[4077]: chan_sip.c:4715 parse_request: Header 4: Contact: (42) [Oct 22 10:47:49] DEBUG[4077]: chan_sip.c:4715 parse_request: Header 5: Call-ID: 448732f666f0d30a344f7fa537d298d4@4.68.250.148 (54) [Oct 22 10:47:49] DEBUG[4077]: chan_sip.c:4715 parse_request: Header 6: CSeq: 102 INVITE (16) [Oct 22 10:47:49] DEBUG[4077]: chan_sip.c:4715 parse_request: Header 7: User-Agent: Asterisk PBX (24) [Oct 22 10:47:49] DEBUG[4077]: chan_sip.c:4715 parse_request: Header 8: Max-Forwards: 70 (16) [Oct 22 10:47:49] DEBUG[4077]: chan_sip.c:4715 parse_request: Header 9: Date: Mon, 01 Oct 2007 14:47:49 GMT (35) [Oct 22 10:47:49] DEBUG[4077]: chan_sip.c:4715 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Oct 22 10:47:49] DEBUG[4077]: chan_sip.c:4715 parse_request: Header 11: Supported: replaces (19) [Oct 22 10:47:49] DEBUG[4077]: chan_sip.c:4715 parse_request: Header 12: Content-Type: application/sdp (29) [Oct 22 10:47:49] DEBUG[4077]: chan_sip.c:4715 parse_request: Header 13: Content-Length: 339 (19) [Oct 22 10:47:49] DEBUG[4077]: chan_sip.c:4715 parse_request: Header 14: (0) [Oct 22 10:47:49] DEBUG[4077]: chan_sip.c:4747 parse_request: Line: v=0 (3) [Oct 22 10:47:49] DEBUG[4077]: chan_sip.c:4747 parse_request: Line: o=root 26169 26169 IN IP4 66.192.107.225 (40) [Oct 22 10:47:49] DEBUG[4077]: chan_sip.c:4747 parse_request: Line: s=session (9) [Oct 22 10:47:49] DEBUG[4077]: chan_sip.c:4747 parse_request: Line: c=IN IP4 66.192.107.225 (23) [Oct 22 10:47:49] DEBUG[4077]: chan_sip.c:4747 parse_request: Line: b=CT:384 (8) [Oct 22 10:47:49] DEBUG[4077]: chan_sip.c:4747 parse_request: Line: t=0 0 (5) [Oct 22 10:47:49] DEBUG[4077]: chan_sip.c:4747 parse_request: Line: m=audio 10836 RTP/AVP 0 3 101 (29) [Oct 22 10:47:49] DEBUG[4077]: chan_sip.c:4747 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Oct 22 10:47:49] DEBUG[4077]: chan_sip.c:4747 parse_request: Line: a=rtpmap:3 GSM/8000 (19) [Oct 22 10:47:49] DEBUG[4077]: chan_sip.c:4747 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Oct 22 10:47:49] DEBUG[4077]: chan_sip.c:4747 parse_request: Line: a=fmtp:101 0-16 (15) [Oct 22 10:47:49] DEBUG[4077]: chan_sip.c:4747 parse_request: Line: a=silenceSupp:off - - - - (25) [Oct 22 10:47:49] DEBUG[4077]: chan_sip.c:4747 parse_request: Line: a=ptime:20 (10) [Oct 22 10:47:49] DEBUG[4077]: chan_sip.c:4747 parse_request: Line: a=sendrecv (10) [Oct 22 10:47:49] DEBUG[4077]: chan_sip.c:4747 parse_request: Line: m=video 14468 RTP/AVP 34 (24) [Oct 22 10:47:49] DEBUG[4077]: chan_sip.c:4747 parse_request: Line: a=rtpmap:34 H263/90000 (22) [Oct 22 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 22 10:47:49] DEBUG[4077]: sched.c:284 ast_sched_del: Attempted to delete nonexistent schedule entry 0! [Oct 22 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 22 10:47:49] DEBUG[26175]: devicestate.c:163 ast_device_state: No provider found, checking channel drivers for SIP - jon [Oct 22 10:47:49] DEBUG[26175]: chan_sip.c:15574 sip_devicestate: Checking device state for peer jon [Oct 22 10:47:49] DEBUG[26175]: devicestate.c:289 do_state_change: Changing state for SIP/jon - state 2 (In use) [Oct 22 10:47:49] DEBUG[26175]: devicestate.c:163 ast_device_state: No provider found, checking channel drivers for SIP - jon [Oct 22 10:47:49] DEBUG[26175]: chan_sip.c:15574 sip_devicestate: Checking device state for peer jon [Oct 22 10:47:49] DEBUG[26175]: devicestate.c:289 do_state_change: Changing state for SIP/jon - state 2 (In use) [Oct 22 10:47:49] DEBUG[4078]: app_queue.c:554 changethread: Device 'SIP/jon' changed to state '2' (In use) [Oct 22 10:47:49] DEBUG[4079]: app_queue.c:554 changethread: Device 'SIP/jon' changed to state '2' (In use) [Oct 22 10:47:50] DEBUG[26204]: chan_sip.c:1902 retrans_pkt: SIP TIMER: Rescheduling retransmission #88924 (1) INVITE - 5 [Oct 22 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 22 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 22 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 22 10:47:50] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 2: From: "Elephant Outlook" ;tag=as111394d8 (71) [Oct 22 10:47:50] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 3: To: (37) [Oct 22 10:47:50] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 4: Call-ID: 448732f666f0d30a344f7fa537d298d4@4.68.250.148 (54) [Oct 22 10:47:50] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 5: CSeq: 102 INVITE (16) [Oct 22 10:47:50] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 6: Server: Bandwidth.com TRM (bw7.gold.13) (39) [Oct 22 10:47:50] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 7: Content-Length: 0 (17) [Oct 22 10:47:50] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 8: (0) --- (8 headers 0 lines) --- [Oct 22 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 22 10:47:50] DEBUG[26204]: chan_sip.c:2191 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #88924 - INVITE (got response) [Oct 22 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 22 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 22 10:47:54] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 0: NOTIFY sip:pbx.elephantoutlook.com SIP/2.0 (42) [Oct 22 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 22 10:47:54] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 2: From: "Home 2" ;tag=f3edfbba5123de76o0 (84) [Oct 22 10:47:54] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 3: To: (33) [Oct 22 10:47:54] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 4: Call-ID: 4b0be73a-76f2e8f6@192.168.1.47 (39) [Oct 22 10:47:54] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 5: CSeq: 131665 NOTIFY (19) [Oct 22 10:47:54] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 6: Max-Forwards: 70 (16) [Oct 22 10:47:54] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 7: Event: keep-alive (17) [Oct 22 10:47:54] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 8: User-Agent: Sipura/SPA941-4.1.8 (31) [Oct 22 10:47:54] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 9: Content-Length: 0 (17) [Oct 22 10:47:54] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 10: (0) --- (10 headers 0 lines) --- [Oct 22 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 22 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 22 10:47:54] DEBUG[26204]: chan_sip.c:15128 sipsock_read: Invalid SIP message - rejected , no callid, len 378 [Oct 22 10:47:54] DEBUG[26204]: chan_sip.c:4450 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Oct 22 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 22 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 22 10:47:54] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 2: From: "asterisk" ;tag=as0dcb19f8 (61) [Oct 22 10:47:54] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 3: To: (40) [Oct 22 10:47:54] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 4: Contact: (38) [Oct 22 10:47:54] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 5: Call-ID: 5d01f10260451d3f5d7806371977a78c@66.192.107.225 (56) [Oct 22 10:47:54] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 6: CSeq: 102 OPTIONS (17) [Oct 22 10:47:54] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 7: User-Agent: Asterisk PBX (24) [Oct 22 10:47:54] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 8: Max-Forwards: 70 (16) [Oct 22 10:47:54] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 9: Date: Mon, 01 Oct 2007 14:47:54 GMT (35) [Oct 22 10:47:54] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Oct 22 10:47:54] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 11: Supported: replaces (19) [Oct 22 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 22 10:47:54] DEBUG[26204]: sched.c:284 ast_sched_del: Attempted to delete nonexistent schedule entry 0! [Oct 22 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 22 10:47:55] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 0: NOTIFY sip:pbx.elephantoutlook.com SIP/2.0 (42) [Oct 22 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 22 10:47:55] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 2: From: "Phone" ;tag=3d2da667eecdead6o0 (86) [Oct 22 10:47:55] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 3: To: (33) [Oct 22 10:47:55] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 4: Call-ID: 1a47d947-de4e5576@192.168.0.100 (40) [Oct 22 10:47:55] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 5: CSeq: 87855 NOTIFY (18) [Oct 22 10:47:55] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 6: Max-Forwards: 70 (16) [Oct 22 10:47:55] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 7: Event: keep-alive (17) [Oct 22 10:47:55] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 8: User-Agent: Sipura/SPA941-4.1.9 (31) [Oct 22 10:47:55] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 9: Content-Length: 0 (17) [Oct 22 10:47:55] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 10: (0) --- (10 headers 0 lines) --- [Oct 22 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 22 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 22 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 22 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 22 10:47:55] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 0: SIP/2.0 200 OK (14) [Oct 22 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 22 10:47:55] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 2: Record-Route: (98) [Oct 22 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 22 10:47:55] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 4: From: "Elephant Outlook" ;tag=as111394d8 (71) [Oct 22 10:47:55] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 5: t: ;tag=80b374c5886f0d2f86e27f008e41bdc4 (73) [Oct 22 10:47:55] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 6: i: 448732f666f0d30a344f7fa537d298d4@4.68.250.148 (48) [Oct 22 10:47:55] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 7: CSeq: 102 INVITE (16) [Oct 22 10:47:55] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 8: Server: DC-SIP/1.2 (18) [Oct 22 10:47:55] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 9: k: timer (8) [Oct 22 10:47:55] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 10: x: 1800;refresher=uas (21) [Oct 22 10:47:55] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 11: m: (53) [Oct 22 10:47:55] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 12: c: application/sdp (18) [Oct 22 10:47:55] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 13: l: 290 (6) [Oct 22 10:47:55] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 14: (0) [Oct 22 10:47:55] DEBUG[26204]: chan_sip.c:4747 parse_request: Line: v=0 (3) [Oct 22 10:47:55] DEBUG[26204]: chan_sip.c:4747 parse_request: Line: o=- 259201 25920100 IN IP4 204.13.236.130 (41) [Oct 22 10:47:55] DEBUG[26204]: chan_sip.c:4747 parse_request: Line: s=- (3) [Oct 22 10:47:55] DEBUG[26204]: chan_sip.c:4747 parse_request: Line: t=0 0 (5) [Oct 22 10:47:55] DEBUG[26204]: chan_sip.c:4747 parse_request: Line: m=image 53420 udptl t38 (23) [Oct 22 10:47:55] DEBUG[26204]: chan_sip.c:4747 parse_request: Line: c=IN IP4 204.13.236.130 (23) [Oct 22 10:47:55] DEBUG[26204]: chan_sip.c:4747 parse_request: Line: a=T38FaxVersion:0 (17) [Oct 22 10:47:55] DEBUG[26204]: chan_sip.c:4747 parse_request: Line: a=T38MaxBitRate:14400 (21) [Oct 22 10:47:55] DEBUG[26204]: chan_sip.c:4747 parse_request: Line: a=T38FaxFillBitRemoval:0 (24) [Oct 22 10:47:55] DEBUG[26204]: chan_sip.c:4747 parse_request: Line: a=T38FaxTranscodingMMR:0 (24) [Oct 22 10:47:55] DEBUG[26204]: chan_sip.c:4747 parse_request: Line: a=T38FaxRateManagement:transferredTCF (37) [Oct 22 10:47:55] DEBUG[26204]: chan_sip.c:4747 parse_request: Line: a=T38FaxMaxBuffer:200 (21) [Oct 22 10:47:55] DEBUG[26204]: chan_sip.c:4747 parse_request: Line: a=T38FaxMaxDatagram:72 (22) --- (14 headers 13 lines) --- [Oct 22 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 22 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 22 10:47:55] DEBUG[26204]: chan_sip.c:2140 __sip_ack: Acked pending invite 102 [Oct 22 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 22 10:47:55] DEBUG[26204]: chan_sip.c:11814 handle_response_invite: SIP response 200 to standard invite [Oct 22 10:47:55] WARNING[26204]: chan_sip.c:5017 process_sdp: Unsupported SDP media type in offer: image 53420 udptl t38 [Oct 22 10:47:55] DEBUG[26204]: chan_sip.c:3133 update_call_counter: Updating call counter for outgoing call [Oct 22 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 22 10:47:55] DEBUG[26204]: sched.c:284 ast_sched_del: Attempted to delete nonexistent schedule entry 0! [Oct 22 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 22 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 22 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 22 10:47:55] DEBUG[4077]: chan_sip.c:3602 sip_answer: SIP answering channel: SIP/jon-08331348 [Oct 22 10:47:55] DEBUG[4077]: chan_sip.c:6574 transmit_response_with_sdp: Setting framing from config on incoming call [Oct 22 10:47:55] DEBUG[4077]: chan_sip.c:6338 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True [Oct 22 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 22 10:47:55] DEBUG[4077]: chan_sip.c:6470 add_sdp: -- Done with adding codecs to SDP [Oct 22 10:47:55] DEBUG[4077]: channel.c:2562 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=42) [Oct 22 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 22 10:47:55] DEBUG[4077]: sched.c:284 ast_sched_del: Attempted to delete nonexistent schedule entry 0! [Oct 22 10:47:55] DEBUG[4077]: chan_sip.c:2037 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #88930 [Oct 22 10:47:55] DEBUG[26175]: devicestate.c:163 ast_device_state: No provider found, checking channel drivers for SIP - bandwidth [Oct 22 10:47:55] DEBUG[26175]: chan_sip.c:15574 sip_devicestate: Checking device state for peer bandwidth [Oct 22 10:47:55] DEBUG[26175]: devicestate.c:289 do_state_change: Changing state for SIP/bandwidth - state 1 (Not in use) [Oct 22 10:47:55] DEBUG[26175]: devicestate.c:163 ast_device_state: No provider found, checking channel drivers for SIP - jon [Oct 22 10:47:55] DEBUG[26175]: chan_sip.c:15574 sip_devicestate: Checking device state for peer jon [Oct 22 10:47:55] DEBUG[26175]: devicestate.c:289 do_state_change: Changing state for SIP/jon - state 2 (In use) [Oct 22 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 22 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 22 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 22 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 22 10:47:55] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 2: From: "Jon" ;tag=dcfcb54af05ff81do0 (76) [Oct 22 10:47:55] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 3: To: ;tag=as32006948 (60) [Oct 22 10:47:55] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 4: Call-ID: ededa8e-5e7073a9@192.168.22.22 (39) [Oct 22 10:47:55] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 5: CSeq: 102 ACK (13) [Oct 22 10:47:55] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 6: Max-Forwards: 70 (16) [Oct 22 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 22 10:47:55] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 8: Contact: "Jon" (51) [Oct 22 10:47:55] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 9: User-Agent: Sipura/SPA941-4.1.8 (31) [Oct 22 10:47:55] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 10: Content-Length: 0 (17) [Oct 22 10:47:55] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 11: (0) --- (11 headers 0 lines) --- [Oct 22 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 22 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 22 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 22 10:47:55] DEBUG[26204]: chan_sip.c:14944 handle_request: **** Received ACK (6) - Command in SIP ACK [Oct 22 10:47:55] DEBUG[26204]: chan_sip.c:2148 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #88930 [Oct 22 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 22 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 22 10:47:55] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 0: SIP/2.0 200 OK (14) [Oct 22 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 22 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 22 10:47:55] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 3: From: "Elephant Outlook" ;tag=as111394d8 (71) [Oct 22 10:47:55] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 4: t: ;tag=80b374c5886f0d2f86e27f008e41bdc4 (73) [Oct 22 10:47:55] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 5: i: 448732f666f0d30a344f7fa537d298d4@4.68.250.148 (48) [Oct 22 10:47:55] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 6: CSeq: 103 BYE (13) [Oct 22 10:47:55] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 7: Server: DC-SIP/1.2 (18) [Oct 22 10:47:55] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 8: k: timer (8) [Oct 22 10:47:55] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 9: l: 0 (4) [Oct 22 10:47:55] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 10: (0) --- (10 headers 0 lines) --- [Oct 22 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 22 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 22 10:47:55] DEBUG[26204]: chan_sip.c:2148 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #88928 [Oct 22 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 22 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 22 10:47:56] DEBUG[26204]: chan_sip.c:4450 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Oct 22 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 22 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 22 10:47:56] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 2: From: "asterisk" ;tag=as4a57aee9 (61) [Oct 22 10:47:56] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 3: To: (34) [Oct 22 10:47:56] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 4: Contact: (38) [Oct 22 10:47:56] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 5: Call-ID: 26046bef17a68baf5517b2106b798aa0@66.192.107.225 (56) [Oct 22 10:47:56] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 6: CSeq: 102 OPTIONS (17) [Oct 22 10:47:56] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 7: User-Agent: Asterisk PBX (24) [Oct 22 10:47:56] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 8: Max-Forwards: 70 (16) [Oct 22 10:47:56] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 9: Date: Mon, 01 Oct 2007 14:47:56 GMT (35) [Oct 22 10:47:56] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Oct 22 10:47:56] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 11: Supported: replaces (19) [Oct 22 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 22 10:47:56] DEBUG[26204]: sched.c:284 ast_sched_del: Attempted to delete nonexistent schedule entry 0! [Oct 22 10:47:56] DEBUG[26204]: chan_sip.c:2037 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #88932 [Oct 22 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 22 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 22 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 22 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 22 10:47:58] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 0: NOTIFY sip:pbx.elephantoutlook.com SIP/2.0 (42) [Oct 22 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 22 10:47:58] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 2: From: "Home 3" ;tag=25bcc698ae6160dbo0 (81) [Oct 22 10:47:58] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 3: To: (33) [Oct 22 10:47:58] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 4: Call-ID: 12d04ff8-211466fb@192.168.0.118 (40) [Oct 22 10:47:58] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 5: CSeq: 87826 NOTIFY (18) [Oct 22 10:47:58] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 6: Max-Forwards: 70 (16) [Oct 22 10:47:58] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 7: Event: keep-alive (17) [Oct 22 10:47:58] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 8: User-Agent: Sipura/SPA941-4.1.8 (31) [Oct 22 10:47:58] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 9: Content-Length: 0 (17) [Oct 22 10:47:58] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 10: (0) --- (10 headers 0 lines) --- [Oct 22 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 22 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 22 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 22 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 22 10:47:58] DEBUG[26204]: chan_sip.c:15128 sipsock_read: Invalid SIP message - rejected , no callid, len 376 [Oct 22 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 22 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 22 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 22 10:47:58] DEBUG[26175]: devicestate.c:163 ast_device_state: No provider found, checking channel drivers for SIP - phone2 [Oct 22 10:47:58] DEBUG[26175]: chan_sip.c:15574 sip_devicestate: Checking device state for peer phone2 [Oct 22 10:47:58] DEBUG[26175]: devicestate.c:289 do_state_change: Changing state for SIP/phone2 - state 1 (Not in use) [Oct 22 10:47:58] DEBUG[4082]: app_queue.c:554 changethread: Device 'SIP/phone2' changed to state '1' (Not in use) [Oct 22 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 22 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 22 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 22 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 22 10:48:00] DEBUG[26175]: devicestate.c:163 ast_device_state: No provider found, checking channel drivers for SIP - office4 [Oct 22 10:48:00] DEBUG[26175]: chan_sip.c:15574 sip_devicestate: Checking device state for peer office4 [Oct 22 10:48:00] DEBUG[26175]: devicestate.c:289 do_state_change: Changing state for SIP/office4 - state 1 (Not in use) [Oct 22 10:48:00] DEBUG[4083]: app_queue.c:554 changethread: Device 'SIP/office4' changed to state '1' (Not in use) [Oct 22 10:48:06] DEBUG[26204]: chan_sip.c:4450 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Oct 22 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 22 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 22 10:48:06] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 2: From: "asterisk" ;tag=as04c9619e (61) [Oct 22 10:48:06] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 3: To: (37) [Oct 22 10:48:06] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 4: Contact: (38) [Oct 22 10:48:06] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 5: Call-ID: 1007aeb74939ae8241ea68101dff5e08@66.192.107.225 (56) [Oct 22 10:48:06] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 6: CSeq: 102 OPTIONS (17) [Oct 22 10:48:06] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 7: User-Agent: Asterisk PBX (24) [Oct 22 10:48:06] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 8: Max-Forwards: 70 (16) [Oct 22 10:48:06] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 9: Date: Mon, 01 Oct 2007 14:48:06 GMT (35) [Oct 22 10:48:06] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Oct 22 10:48:06] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 11: Supported: replaces (19) [Oct 22 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 22 10:48:06] DEBUG[26204]: sched.c:284 ast_sched_del: Attempted to delete nonexistent schedule entry 0! [Oct 22 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 22 10:48:06] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 0: SIP/2.0 200 OK (14) [Oct 22 10:48:06] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 1: To: ;tag=3c08e80a6d855e66i0 (60) [Oct 22 10:48:06] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 2: From: "asterisk" ;tag=as04c9619e (61) [Oct 22 10:48:06] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 3: Call-ID: 1007aeb74939ae8241ea68101dff5e08@66.192.107.225 (56) [Oct 22 10:48:06] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 4: CSeq: 102 OPTIONS (17) [Oct 22 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 22 10:48:06] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 6: Server: Sipura/SPA941-4.1.8 (27) [Oct 22 10:48:06] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 7: Content-Length: 0 (17) [Oct 22 10:48:06] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 8: Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER (61) [Oct 22 10:48:06] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 9: (0) --- (9 headers 0 lines) --- [Oct 22 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 22 10:48:06] DEBUG[26204]: chan_sip.c:2148 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #88936 [Oct 22 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 22 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 22 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 22 10:48:07] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 2: From: "Jon" ;tag=dcfcb54af05ff81do0 (76) [Oct 22 10:48:07] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 3: To: ;tag=as32006948 (60) [Oct 22 10:48:07] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 4: Call-ID: ededa8e-5e7073a9@192.168.22.22 (39) [Oct 22 10:48:07] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 5: CSeq: 103 BYE (13) [Oct 22 10:48:07] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 6: Max-Forwards: 70 (16) [Oct 22 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 22 10:48:07] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 8: User-Agent: Sipura/SPA941-4.1.8 (31) [Oct 22 10:48:07] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 9: Content-Length: 0 (17) [Oct 22 10:48:07] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 10: (0) --- (10 headers 0 lines) --- [Oct 22 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 22 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 22 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 22 10:48:07] DEBUG[26204]: chan_sip.c:1646 sip_alreadygone: Setting SIP_ALREADYGONE on dialog ededa8e-5e7073a9@192.168.22.22 [Oct 22 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 22 10:48:07] DEBUG[4077]: channel.c:4043 ast_generic_bridge: Didn't get a frame from channel: SIP/jon-08331348 [Oct 22 10:48:07] DEBUG[4077]: channel.c:4371 ast_channel_bridge: Bridge stops bridging channels SIP/jon-08331348 and SIP/bandwidth-08429420 [Oct 22 10:48:07] DEBUG[4077]: channel.c:1783 ast_hangup: Hanging up channel 'SIP/bandwidth-08429420' [Oct 22 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 22 10:48:07] DEBUG[4077]: sched.c:284 ast_sched_del: Attempted to delete nonexistent schedule entry 0! [Oct 22 10:48:07] DEBUG[4077]: chan_sip.c:2037 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #88940 [Oct 22 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 22 10:48:07] DEBUG[4077]: rtp.c:1499 ast_rtp_early_bridge: Channel '' has no RTP, not doing anything [Oct 22 10:48:07] DEBUG[4077]: app_dial.c:1709 dial_exec_full: Exiting with DIALSTATUS=ANSWER. [Oct 22 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 22 10:48:07] DEBUG[4077]: channel.c:1566 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/jon-08331348' [Oct 22 10:48:07] DEBUG[4077]: channel.c:1783 ast_hangup: Hanging up channel 'SIP/jon-08331348' [Oct 22 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 22 10:48:07] DEBUG[4077]: chan_sip.c:3454 sip_hangup: update_call_counter(jon) - decrement call limit counter on hangup [Oct 22 10:48:07] DEBUG[4077]: chan_sip.c:3133 update_call_counter: Updating call counter for incoming call [Oct 22 10:48:07] DEBUG[4077]: chan_sip.c:3184 update_call_counter: Call from peer 'jon' removed from call limit 100 [Oct 22 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 22 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 22 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 22 10:48:07] DEBUG[26175]: devicestate.c:163 ast_device_state: No provider found, checking channel drivers for SIP - bandwidth [Oct 22 10:48:07] DEBUG[26175]: chan_sip.c:15574 sip_devicestate: Checking device state for peer bandwidth [Oct 22 10:48:07] DEBUG[26175]: devicestate.c:289 do_state_change: Changing state for SIP/bandwidth - state 1 (Not in use) [Oct 22 10:48:07] DEBUG[26175]: devicestate.c:163 ast_device_state: No provider found, checking channel drivers for SIP - jon [Oct 22 10:48:07] DEBUG[26175]: chan_sip.c:15574 sip_devicestate: Checking device state for peer jon [Oct 22 10:48:07] DEBUG[26175]: devicestate.c:289 do_state_change: Changing state for SIP/jon - state 1 (Not in use) [Oct 22 10:48:07] DEBUG[26175]: devicestate.c:163 ast_device_state: No provider found, checking channel drivers for SIP - jon [Oct 22 10:48:07] DEBUG[26175]: chan_sip.c:15574 sip_devicestate: Checking device state for peer jon [Oct 22 10:48:07] DEBUG[26175]: devicestate.c:289 do_state_change: Changing state for SIP/jon - state 1 (Not in use) [Oct 22 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 22 10:48:07] DEBUG[4086]: app_queue.c:554 changethread: Device 'SIP/jon' changed to state '1' (Not in use) [Oct 22 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 22 10:48:07] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 0: SIP/2.0 481 Transaction Does Not Exist (38) [Oct 22 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 22 10:48:07] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 2: From: "Elephant Outlook" ;tag=as111394d8 (71) [Oct 22 10:48:07] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 3: t: ;tag=7750116 (48) [Oct 22 10:48:07] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 4: i: 448732f666f0d30a344f7fa537d298d4@4.68.250.148 (48) [Oct 22 10:48:07] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 5: CSeq: 104 BYE (13) [Oct 22 10:48:07] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 6: User-Agent: Asterisk PBX (24) [Oct 22 10:48:07] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 7: l: 0 (4) [Oct 22 10:48:07] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 8: (0) --- (8 headers 0 lines) --- [Oct 22 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 22 10:48:07] DEBUG[26204]: chan_sip.c:2148 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #88940 [Oct 22 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 22 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 22 10:48:08] DEBUG[26204]: chan_sip.c:4450 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Oct 22 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 22 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 22 10:48:08] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 2: From: "asterisk" ;tag=as1a6af602 (61) [Oct 22 10:48:08] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 3: To: (40) [Oct 22 10:48:08] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 4: Contact: (38) [Oct 22 10:48:08] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 5: Call-ID: 3dec0aeb44f409a07f28dfc615aea302@66.192.107.225 (56) [Oct 22 10:48:08] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 6: CSeq: 102 OPTIONS (17) [Oct 22 10:48:08] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 7: User-Agent: Asterisk PBX (24) [Oct 22 10:48:08] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 8: Max-Forwards: 70 (16) [Oct 22 10:48:08] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 9: Date: Mon, 01 Oct 2007 14:48:08 GMT (35) [Oct 22 10:48:08] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Oct 22 10:48:08] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 11: Supported: replaces (19) [Oct 22 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 22 10:48:08] DEBUG[26204]: sched.c:284 ast_sched_del: Attempted to delete nonexistent schedule entry 0! [Oct 22 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 22 10:48:09] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 0: NOTIFY sip:pbx.elephantoutlook.com SIP/2.0 (42) [Oct 22 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 22 10:48:09] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 2: From: "Home 2" ;tag=f3edfbba5123de76o0 (84) [Oct 22 10:48:09] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 3: To: (33) [Oct 22 10:48:09] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 4: Call-ID: 4b0be73a-76f2e8f6@192.168.1.47 (39) [Oct 22 10:48:09] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 5: CSeq: 131666 NOTIFY (19) [Oct 22 10:48:09] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 6: Max-Forwards: 70 (16) [Oct 22 10:48:09] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 7: Event: keep-alive (17) [Oct 22 10:48:09] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 8: User-Agent: Sipura/SPA941-4.1.8 (31) [Oct 22 10:48:09] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 9: Content-Length: 0 (17) [Oct 22 10:48:09] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 10: (0) --- (10 headers 0 lines) --- [Oct 22 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 22 10:48:09] DEBUG[26204]: chan_sip.c:15128 sipsock_read: Invalid SIP message - rejected , no callid, len 378 [Oct 22 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 22 10:48:10] DEBUG[26194]: chan_iax2.c:8245 iax2_do_register: Allocate call number [Oct 22 10:48:10] DEBUG[26194]: chan_iax2.c:8251 iax2_do_register: Registration created on call 1 [Oct 22 10:48:10] DEBUG[26204]: chan_sip.c:4450 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Oct 22 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 22 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 22 10:48:10] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 2: From: "asterisk" ;tag=as6d3c90d0 (61) [Oct 22 10:48:10] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 3: To: (34) [Oct 22 10:48:10] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 4: Contact: (38) [Oct 22 10:48:10] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 5: Call-ID: 7057453d7e225f361f83d56178b1f643@66.192.107.225 (56) [Oct 22 10:48:10] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 6: CSeq: 102 OPTIONS (17) [Oct 22 10:48:10] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 7: User-Agent: Asterisk PBX (24) [Oct 22 10:48:10] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 8: Max-Forwards: 70 (16) [Oct 22 10:48:10] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 9: Date: Mon, 01 Oct 2007 14:48:10 GMT (35) [Oct 22 10:48:10] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Oct 22 10:48:10] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 11: Supported: replaces (19) [Oct 22 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 22 10:48:10] DEBUG[26204]: sched.c:284 ast_sched_del: Attempted to delete nonexistent schedule entry 0! [Oct 22 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 22 10:48:10] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 0: NOTIFY sip:pbx.elephantoutlook.com SIP/2.0 (42) [Oct 22 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 22 10:48:10] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 2: From: "Phone" ;tag=3d2da667eecdead6o0 (86) [Oct 22 10:48:10] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 3: To: (33) [Oct 22 10:48:10] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 4: Call-ID: 1a47d947-de4e5576@192.168.0.100 (40) [Oct 22 10:48:10] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 5: CSeq: 87856 NOTIFY (18) [Oct 22 10:48:10] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 6: Max-Forwards: 70 (16) [Oct 22 10:48:10] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 7: Event: keep-alive (17) [Oct 22 10:48:10] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 8: User-Agent: Sipura/SPA941-4.1.9 (31) [Oct 22 10:48:10] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 9: Content-Length: 0 (17) [Oct 22 10:48:10] DEBUG[26204]: chan_sip.c:4715 parse_request: Header 10: (0) --- (10 headers 0 lines) --- [Oct 22 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 22 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 22 10:48:10] DEBUG[26204]: chan_sip.c:15128 sipsock_read: Invalid SIP message - rejected , no callid, len 381 [Oct 22 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 22 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 22 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 22 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 22 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 22 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 22 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 22 10:48:12] DEBUG[26175]: devicestate.c:163 ast_device_state: No provider found, checking channel drivers for SIP - phone2 [Oct 22 10:48:12] DEBUG[26175]: chan_sip.c:15574 sip_devicestate: Checking device state for peer phone2 [Oct 22 10:48:12] DEBUG[26175]: devicestate.c:289 do_state_change: Changing state for SIP/phone2 - state 1 (Not in use) [Oct 22 10:48:12] DEBUG[4088]: app_queue.c:554 changethread: Device 'SIP/phone2' changed to state '1' (Not in use) [Oct 22 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>