[Jan 8 16:52:16] Asterisk Ready. ]1;Asterisk]2;Asterisk Console on 'steven-sokols-computer.local' (pid 19130)*CLI> [Jan 8 16:52:16] DEBUG[19130]: chan_sip.c:4260 sip_alloc: Allocating new SIP dialog for (No Call-ID) - NOTIFY (No RTP) [Jan 8 16:52:16] DEBUG[19130]: chan_sip.c:3076 sip_destroy: Destroying SIP dialog 261ec5a005d13c7c59f073ed5b48f569@192.168.100.249 [Jan 8 16:52:16] Really destroying SIP dialog '261ec5a005d13c7c59f073ed5b48f569@192.168.100.249' Method: NOTIFY *CLI> [Jan 8 16:52:20] DEBUG[19130]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel IAX2/6000 [Jan 8 16:52:20] DEBUG[19130]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for IAX2 - 6000 [Jan 8 16:52:20] DEBUG[19130]: chan_iax2.c:9604 iax2_devicestate: Checking device state for device 6000 [Jan 8 16:52:20] DEBUG[19130]: chan_iax2.c:9612 iax2_devicestate: iax2_devicestate: Found peer. What's device state of 6000? addr=16777343, defaddr=0 maxms=2000, lastms=4 [Jan 8 16:52:20] DEBUG[19130]: devicestate.c:287 do_state_change: Changing state for IAX2/6000 - state 1 (Not in use) [Jan 8 16:52:20] DEBUG[19130]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 6000 [Jan 8 16:52:20] DEBUG[19130]: chan_sip.c:15051 sip_devicestate: Checking device state for peer 6000 [Jan 8 16:52:20] DEBUG[19130]: app_queue.c:546 changethread: Device 'IAX2/6000' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jan 8 16:52:20] DEBUG[19130]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for IAX2 - 6000 [Jan 8 16:52:20] DEBUG[19130]: chan_iax2.c:9604 iax2_devicestate: Checking device state for device 6000 [Jan 8 16:52:20] DEBUG[19130]: chan_iax2.c:9612 iax2_devicestate: iax2_devicestate: Found peer. What's device state of 6000? addr=16777343, defaddr=0 maxms=2000, lastms=4 set debug 4 Core debug was 5 and is now 4 The 'set debug' command is deprecated and will be removed in a future release. Please use 'core set debug' instead. *CLI> set verbose 4 Verbosity was 5 and is now 4 The 'set verbose' command is deprecated and will be removed in a future release. Please use 'core set verbose' instead. *CLI> sip debug SIP Debugging enabled The 'sip debug' command is deprecated and will be removed in a future release. Please use 'sip set debug' instead. *CLI> [Jan 8 16:52:50] <--- SIP read from 192.168.100.163:5060 ---> INVITE sip:6002@192.168.100.249 SIP/2.0 Via: SIP/2.0/UDP 192.168.100.163:5060;branch=z9hG4bK-da70a04f From: "Paul Barham" ;tag=58b2b7728e83ed57o0 To: "Paul Barham" Call-ID: 8792f9ce-bbfb2eab@192.168.100.163 CSeq: 101 INVITE Max-Forwards: 70 Contact: "Paul Barham" Expires: 240 User-Agent: Linksys/SPA962-5.1.3 Content-Length: 399 Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER Supported: replaces Content-Type: application/sdp v=0 o=- 23458 23458 IN IP4 192.168.100.163 s=- c=IN IP4 192.168.100.163 t=0 0 m=audio 16420 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:20 a=sendrecv <-------------> [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 0: INVITE sip:6002@192.168.100.249 SIP/2.0 (39) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.100.163:5060;branch=z9hG4bK-da70a04f (61) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 2: From: "Paul Barham" ;tag=58b2b7728e83ed57o0 (69) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 3: To: "Paul Barham" (44) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 4: Call-ID: 8792f9ce-bbfb2eab@192.168.100.163 (42) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 5: CSeq: 101 INVITE (16) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 6: Max-Forwards: 70 (16) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 7: Contact: "Paul Barham" (54) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 8: Expires: 240 (12) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 9: User-Agent: Linksys/SPA962-5.1.3 (32) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 10: Content-Length: 399 (19) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 11: Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER (61) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 12: Supported: replaces (19) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 13: Content-Type: application/sdp (29) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 14: (0) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4555 parse_request: Line: v=0 (3) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4555 parse_request: Line: o=- 23458 23458 IN IP4 192.168.100.163 (38) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4555 parse_request: Line: s=- (3) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4555 parse_request: Line: c=IN IP4 192.168.100.163 (24) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4555 parse_request: Line: t=0 0 (5) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4555 parse_request: Line: m=audio 16420 RTP/AVP 0 2 4 8 18 96 97 98 101 (45) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4555 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4555 parse_request: Line: a=rtpmap:2 G726-32/8000 (23) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4555 parse_request: Line: a=rtpmap:4 G723/8000 (20) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4555 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4555 parse_request: Line: a=rtpmap:18 G729a/8000 (22) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4555 parse_request: Line: a=rtpmap:96 G726-40/8000 (24) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4555 parse_request: Line: a=rtpmap:97 G726-24/8000 (24) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4555 parse_request: Line: a=rtpmap:98 G726-16/8000 (24) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4555 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4555 parse_request: Line: a=fmtp:101 0-15 (15) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4555 parse_request: Line: a=ptime:20 (10) [Jan 8 16:52:50] --- (14 headers 18 lines) --- [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:2555 do_setnat: Setting NAT on RTP to On [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4260 sip_alloc: Allocating new SIP dialog for 8792f9ce-bbfb2eab@192.168.100.163 - INVITE (With RTP) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:14456 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:1660 parse_sip_options: Begin: parsing SIP "Supported: replaces" [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:1668 parse_sip_options: Found SIP option: -replaces- [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:1674 parse_sip_options: Matched SIP option: replaces [Jan 8 16:52:50] Sending to 192.168.100.163 : 5060 (NAT) [Jan 8 16:52:50] Using INVITE request as basis request - 8792f9ce-bbfb2eab@192.168.100.163 [Jan 8 16:52:50] Found peer '6001' [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:2555 do_setnat: Setting NAT on RTP to On [Jan 8 16:52:50] <--- Reliably Transmitting (NAT) to 192.168.100.163:5060 ---> SIP/2.0 407 Proxy Authentication Required Via: SIP/2.0/UDP 192.168.100.163:5060;branch=z9hG4bK-da70a04f;received=192.168.100.163 From: "Paul Barham" ;tag=58b2b7728e83ed57o0 To: "Paul Barham" ;tag=as2222e19c Call-ID: 8792f9ce-bbfb2eab@192.168.100.163 CSeq: 101 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Proxy-Authenticate: Digest algorithm=MD5, realm="", nonce="63351778" Content-Length: 0 <------------> [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:1955 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #13 [Jan 8 16:52:50] Scheduling destruction of SIP dialog '8792f9ce-bbfb2eab@192.168.100.163' in 32000 ms (Method: INVITE) [Jan 8 16:52:50] <--- SIP read from 192.168.100.163:5060 ---> ACK sip:6002@192.168.100.249 SIP/2.0 Via: SIP/2.0/UDP 192.168.100.163:5060;branch=z9hG4bK-da70a04f From: "Paul Barham" ;tag=58b2b7728e83ed57o0 To: "Paul Barham" ;tag=as2222e19c Call-ID: 8792f9ce-bbfb2eab@192.168.100.163 CSeq: 101 ACK Max-Forwards: 70 Contact: "Paul Barham" User-Agent: Linksys/SPA962-5.1.3 Content-Length: 0 <-------------> [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 0: ACK sip:6002@192.168.100.249 SIP/2.0 (36) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.100.163:5060;branch=z9hG4bK-da70a04f (61) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 2: From: "Paul Barham" ;tag=58b2b7728e83ed57o0 (69) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 3: To: "Paul Barham" ;tag=as2222e19c (59) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 4: Call-ID: 8792f9ce-bbfb2eab@192.168.100.163 (42) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 5: CSeq: 101 ACK (13) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 6: Max-Forwards: 70 (16) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 7: Contact: "Paul Barham" (54) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 8: User-Agent: Linksys/SPA962-5.1.3 (32) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 9: Content-Length: 0 (17) [Jan 8 16:52:50] --- (10 headers 0 lines) --- [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:14456 handle_request: **** Received ACK (6) - Command in SIP ACK [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:2059 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #13 [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:2069 __sip_ack: Stopping retransmission on '8792f9ce-bbfb2eab@192.168.100.163' of Response 101: Match Not Found [Jan 8 16:52:50] <--- SIP read from 192.168.100.163:5060 ---> INVITE sip:6002@192.168.100.249 SIP/2.0 Via: SIP/2.0/UDP 192.168.100.163:5060;branch=z9hG4bK-61d76283 From: "Paul Barham" ;tag=58b2b7728e83ed57o0 To: "Paul Barham" Call-ID: 8792f9ce-bbfb2eab@192.168.100.163 CSeq: 102 INVITE Max-Forwards: 70 Proxy-Authorization: Digest username="6001",realm="",nonce="63351778",uri="sip:6002@192.168.100.249",algorithm=MD5,response="3adfc72903a4bd7b03e8e223e258cf92" Contact: "Paul Barham" Expires: 240 User-Agent: Linksys/SPA962-5.1.3 Content-Length: 399 Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER Supported: replaces Content-Type: application/sdp v=0 o=- 23458 23458 IN IP4 192.168.100.163 s=- c=IN IP4 192.168.100.163 t=0 0 m=audio 16420 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:20 a=sendrecv <-------------> [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 0: INVITE sip:6002@192.168.100.249 SIP/2.0 (39) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.100.163:5060;branch=z9hG4bK-61d76283 (61) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 2: From: "Paul Barham" ;tag=58b2b7728e83ed57o0 (69) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 3: To: "Paul Barham" (44) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 4: Call-ID: 8792f9ce-bbfb2eab@192.168.100.163 (42) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 5: CSeq: 102 INVITE (16) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 6: Max-Forwards: 70 (16) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 7: Proxy-Authorization: Digest username="6001",realm="",nonce="63351778",uri="sip:6002@192.168.100.249",algorithm=MD5,response="3adfc72903a4bd7b03e8e223e258cf92" (158) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 8: Contact: "Paul Barham" (54) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 9: Expires: 240 (12) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 10: User-Agent: Linksys/SPA962-5.1.3 (32) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 11: Content-Length: 399 (19) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 12: Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER (61) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 13: Supported: replaces (19) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 14: Content-Type: application/sdp (29) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 15: (0) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4555 parse_request: Line: v=0 (3) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4555 parse_request: Line: o=- 23458 23458 IN IP4 192.168.100.163 (38) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4555 parse_request: Line: s=- (3) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4555 parse_request: Line: c=IN IP4 192.168.100.163 (24) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4555 parse_request: Line: t=0 0 (5) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4555 parse_request: Line: m=audio 16420 RTP/AVP 0 2 4 8 18 96 97 98 101 (45) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4555 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4555 parse_request: Line: a=rtpmap:2 G726-32/8000 (23) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4555 parse_request: Line: a=rtpmap:4 G723/8000 (20) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4555 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4555 parse_request: Line: a=rtpmap:18 G729a/8000 (22) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4555 parse_request: Line: a=rtpmap:96 G726-40/8000 (24) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4555 parse_request: Line: a=rtpmap:97 G726-24/8000 (24) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4555 parse_request: Line: a=rtpmap:98 G726-16/8000 (24) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4555 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4555 parse_request: Line: a=fmtp:101 0-15 (15) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4555 parse_request: Line: a=ptime:20 (10) [Jan 8 16:52:50] --- (15 headers 18 lines) --- [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:14456 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Jan 8 16:52:50] Sending to 192.168.100.163 : 5060 (NAT) [Jan 8 16:52:50] Using INVITE request as basis request - 8792f9ce-bbfb2eab@192.168.100.163 [Jan 8 16:52:50] Found peer '6001' [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:2555 do_setnat: Setting NAT on RTP to On [Jan 8 16:52:50] Found RTP audio format 0 [Jan 8 16:52:50] Found RTP audio format 2 [Jan 8 16:52:50] Found RTP audio format 4 [Jan 8 16:52:50] Found RTP audio format 8 [Jan 8 16:52:50] Found RTP audio format 18 [Jan 8 16:52:50] Found RTP audio format 96 [Jan 8 16:52:50] Found RTP audio format 97 [Jan 8 16:52:50] Found RTP audio format 98 [Jan 8 16:52:50] Found RTP audio format 101 [Jan 8 16:52:50] Peer audio RTP is at port 192.168.100.163:16420 [Jan 8 16:52:50] Found description format PCMU for ID 0 [Jan 8 16:52:50] Found description format G726-32 for ID 2 [Jan 8 16:52:50] Found description format G723 for ID 4 [Jan 8 16:52:50] Found description format PCMA for ID 8 [Jan 8 16:52:50] Found description format G729a for ID 18 [Jan 8 16:52:50] Found description format G726-40 for ID 96 [Jan 8 16:52:50] Found description format G726-24 for ID 97 [Jan 8 16:52:50] Found description format G726-16 for ID 98 [Jan 8 16:52:50] Found description format telephone-event for ID 101 [Jan 8 16:52:50] Got unsupported a:fmtp in SDP offer [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:5066 process_sdp: T38 state changed to 0 on channel [Jan 8 16:52:50] Capabilities: us - 0x8000e (gsm|ulaw|alaw|h263), peer - audio=0xd0d (g723|ulaw|alaw|g726|g729|ilbc)/video=0x0 (nothing), combined - 0xc (ulaw|alaw) [Jan 8 16:52:50] Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [Jan 8 16:52:50] Peer audio RTP is at port 192.168.100.163:16420 [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:5143 process_sdp: We're settling with these formats: 0xc (ulaw|alaw) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:13240 handle_request_invite: Checking SIP call limits for device 6001 [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:2974 update_call_counter: Updating call counter for incoming call [Jan 8 16:52:50] Looking for 6002 in user-6001 (domain 192.168.100.249) [Jan 8 16:52:50] DEBUG[19130]: frame.c:1252 ast_codec_choose: Could not find preferred codec - Going for the best codec [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:3762 sip_new: *** Our native formats are 0x4 (ulaw) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:3763 sip_new: *** Joint capabilities are 0xc (ulaw|alaw) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:3764 sip_new: *** Our capabilities are 0x8000e (gsm|ulaw|alaw|h263) [Jan 8 16:52:50] DEBUG[19130]: frame.c:1252 ast_codec_choose: Could not find preferred codec - Going for the best codec [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:3765 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:3788 sip_new: This channel will not be able to handle video. [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:7892 build_route: build_route: Contact hop: "Paul Barham" [Jan 8 16:52:50] list_route: hop: [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:13313 handle_request_invite: SIP/6001-01847800: New call is still down.... Trying... [Jan 8 16:52:50] <--- Transmitting (NAT) to 192.168.100.163:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.100.163:5060;branch=z9hG4bK-61d76283;received=192.168.100.163 From: "Paul Barham" ;tag=58b2b7728e83ed57o0 To: "Paul Barham" Call-ID: 8792f9ce-bbfb2eab@192.168.100.163 CSeq: 102 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Jan 8 16:52:50] DEBUG[19130]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/6001-01847800 [Jan 8 16:52:50] DEBUG[19130]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 6001 [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:15051 sip_devicestate: Checking device state for peer 6001 [Jan 8 16:52:50] DEBUG[19130]: devicestate.c:287 do_state_change: Changing state for SIP/6001 - state 1 (Not in use) [Jan 8 16:52:50] DEBUG[19130]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 6001 [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:15051 sip_devicestate: Checking device state for peer 6001 [Jan 8 16:52:50] DEBUG[19130]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for IAX2 - 6001 [Jan 8 16:52:50] DEBUG[19130]: app_queue.c:546 changethread: Device 'SIP/6001' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jan 8 16:52:50] DEBUG[19130]: chan_iax2.c:9604 iax2_devicestate: Checking device state for device 6001 [Jan 8 16:52:50] DEBUG[19130]: chan_iax2.c:9612 iax2_devicestate: iax2_devicestate: Found peer. What's device state of 6001? addr=0, defaddr=0 maxms=0, lastms=0 [Jan 8 16:52:50] DEBUG[19130]: pbx.c:1767 pbx_extension_helper: Launching 'Macro' [Jan 8 16:52:50] -- Executing [6002@user-6001:1] Macro("SIP/6001-01847800", "stdexten|6002|SIP/6002&IAX2/6002") in new stack [Jan 8 16:52:50] DEBUG[19130]: pbx.c:1767 pbx_extension_helper: Launching 'NoOp' [Jan 8 16:52:50] -- Executing [s@macro-stdexten:1] NoOp("SIP/6001-01847800", "STANDARD EXTENSION MACRO: 6002 | SIP/6002&IAX2/6002") in new stack [Jan 8 16:52:50] DEBUG[19130]: pbx.c:1621 pbx_substitute_variables_helper_full: Function result is '' [Jan 8 16:52:50] DEBUG[19130]: pbx.c:1767 pbx_extension_helper: Launching 'Set' [Jan 8 16:52:50] -- Executing [s@macro-stdexten:2] Set("SIP/6001-01847800", "FMFM=") in new stack [Jan 8 16:52:50] DEBUG[19130]: pbx.c:1688 pbx_substitute_variables_helper_full: Expression result is '0' [Jan 8 16:52:50] DEBUG[19130]: pbx.c:1767 pbx_extension_helper: Launching 'MacroIf' [Jan 8 16:52:50] -- Executing [s@macro-stdexten:3] MacroIf("SIP/6001-01847800", "0?findme") in new stack [Jan 8 16:52:50] DEBUG[19130]: pbx.c:1767 pbx_extension_helper: Launching 'Dial' [Jan 8 16:52:50] -- Executing [s@macro-stdexten:4] Dial("SIP/6001-01847800", "SIP/6002&IAX2/6002|20") in new stack [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:15109 sip_request_call: Asked to create a SIP channel with formats: 0x4 (ulaw) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4260 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:2555 do_setnat: Setting NAT on RTP to On [Jan 8 16:52:50] DEBUG[19130]: frame.c:1252 ast_codec_choose: Could not find preferred codec - Going for the best codec [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:3762 sip_new: *** Our native formats are 0x4 (ulaw) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:3763 sip_new: *** Joint capabilities are 0x0 (nothing) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:3764 sip_new: *** Our capabilities are 0x8000e (gsm|ulaw|alaw|h263) [Jan 8 16:52:50] DEBUG[19130]: frame.c:1252 ast_codec_choose: Could not find preferred codec - Going for the best codec [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:3765 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:3767 sip_new: *** Our preferred formats from the incoming channel are 0x4 (ulaw) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:3788 sip_new: This channel will not be able to handle video. [Jan 8 16:52:50] DEBUG[19130]: rtp.c:1570 ast_rtp_make_compatible: Seeded SDP of 'SIP/6002-01845a00' with that of 'SIP/6001-01847800' [Jan 8 16:52:50] DEBUG[19130]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-macro-stdexten-s-4. [Jan 8 16:52:50] DEBUG[19130]: channel.c:3185 ast_channel_inherit_variables: Not copying variable MACRO_DEPTH. [Jan 8 16:52:50] DEBUG[19130]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-macro-stdexten-s-3. [Jan 8 16:52:50] DEBUG[19130]: channel.c:3185 ast_channel_inherit_variables: Not copying variable FMFM. [Jan 8 16:52:50] DEBUG[19130]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-macro-stdexten-s-2. [Jan 8 16:52:50] DEBUG[19130]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-macro-stdexten-s-1. [Jan 8 16:52:50] DEBUG[19130]: channel.c:3185 ast_channel_inherit_variables: Not copying variable ARG2. [Jan 8 16:52:50] DEBUG[19130]: channel.c:3185 ast_channel_inherit_variables: Not copying variable ARG1. [Jan 8 16:52:50] DEBUG[19130]: channel.c:3185 ast_channel_inherit_variables: Not copying variable MACRO_PRIORITY. [Jan 8 16:52:50] DEBUG[19130]: channel.c:3185 ast_channel_inherit_variables: Not copying variable MACRO_CONTEXT. [Jan 8 16:52:50] DEBUG[19130]: channel.c:3185 ast_channel_inherit_variables: Not copying variable MACRO_EXTEN. [Jan 8 16:52:50] DEBUG[19130]: channel.c:3185 ast_channel_inherit_variables: Not copying variable STACK-user-6001-6002-1. [Jan 8 16:52:50] DEBUG[19130]: channel.c:3185 ast_channel_inherit_variables: Not copying variable USERID. [Jan 8 16:52:50] DEBUG[19130]: channel.c:3185 ast_channel_inherit_variables: Not copying variable SIPCALLID. [Jan 8 16:52:50] DEBUG[19130]: channel.c:3185 ast_channel_inherit_variables: Not copying variable SIPUSERAGENT. [Jan 8 16:52:50] DEBUG[19130]: channel.c:3185 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [Jan 8 16:52:50] DEBUG[19130]: channel.c:3185 ast_channel_inherit_variables: Not copying variable SIPURI. [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:2808 sip_call: Outgoing Call for 6002 [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:2974 update_call_counter: Updating call counter for outgoing call [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:2822 sip_call: Our T38 capability (0), joint T38 capability (0) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:6119 add_sdp: ** Our capability: 0x8000e (gsm|ulaw|alaw|h263) Video flag: False [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:6120 add_sdp: ** Our prefcodec: 0x4 (ulaw) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:6137 add_sdp: This call needs video offers, but there's no video support enabled! [Jan 8 16:52:50] Audio is at 192.168.100.249 port 17850 [Jan 8 16:52:50] Adding codec 0x4 (ulaw) to SDP [Jan 8 16:52:50] Adding codec 0x2 (gsm) to SDP [Jan 8 16:52:50] Adding codec 0x8 (alaw) to SDP [Jan 8 16:52:50] Adding non-codec 0x1 (telephone-event) to SDP [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:6251 add_sdp: -- Done with adding codecs to SDP [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:6296 add_sdp: Done building SDP. Settling with this capability: 0x8000e (gsm|ulaw|alaw|h263) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 0: INVITE sip:6002@192.168.100.247:5061 SIP/2.0 (44) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.100.249:5060;branch=z9hG4bK204f7e14;rport (66) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 2: From: "Steven Sokol" ;tag=as41561da4 (62) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 3: To: (35) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 4: Contact: (35) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 5: Call-ID: 3111d3ea5fb92e26797bbf7a456fe6a4@192.168.100.249 (57) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 6: CSeq: 102 INVITE (16) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 7: User-Agent: Asterisk PBX (24) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 8: Max-Forwards: 70 (16) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 9: Date: Mon, 08 Jan 2007 22:52:50 GMT (35) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 11: Supported: replaces (19) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 12: Content-Type: application/sdp (29) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 13: Content-Length: 293 (19) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 14: (0) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4555 parse_request: Line: v=0 (3) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4555 parse_request: Line: o=root 19130 19130 IN IP4 192.168.100.249 (41) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4555 parse_request: Line: s=session (9) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4555 parse_request: Line: c=IN IP4 192.168.100.249 (24) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4555 parse_request: Line: t=0 0 (5) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4555 parse_request: Line: m=audio 17850 RTP/AVP 0 3 8 101 (31) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4555 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4555 parse_request: Line: a=rtpmap:3 GSM/8000 (19) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4555 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4555 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4555 parse_request: Line: a=fmtp:101 0-16 (15) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4555 parse_request: Line: a=silenceSupp:off - - - - (25) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4555 parse_request: Line: a=ptime:20 (10) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4555 parse_request: Line: a=sendrecv (10) [Jan 8 16:52:50] Reliably Transmitting (NAT) to 192.168.100.247:5061: INVITE sip:6002@192.168.100.247:5061 SIP/2.0 Via: SIP/2.0/UDP 192.168.100.249:5060;branch=z9hG4bK204f7e14;rport From: "Steven Sokol" ;tag=as41561da4 To: Contact: Call-ID: 3111d3ea5fb92e26797bbf7a456fe6a4@192.168.100.249 CSeq: 102 INVITE User-Agent: Asterisk PBX Max-Forwards: 70 Date: Mon, 08 Jan 2007 22:52:50 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Type: application/sdp Content-Length: 293 v=0 o=root 19130 19130 IN IP4 192.168.100.249 s=session c=IN IP4 192.168.100.249 t=0 0 m=audio 17850 RTP/AVP 0 3 8 101 a=rtpmap:0 PCMU/8000 a=rtpmap:3 GSM/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv --- [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:1955 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #15 [Jan 8 16:52:50] -- Called 6002 [Jan 8 16:52:50] WARNING[19130]: app_dial.c:1081 dial_exec_full: Unable to create channel of type 'IAX2' (cause 3 - No route to destination) [Jan 8 16:52:50] <--- SIP read from 192.168.100.247:5061 ---> SIP/2.0 100 Trying To: From: "Steven Sokol" ;tag=as41561da4 Call-ID: 3111d3ea5fb92e26797bbf7a456fe6a4@192.168.100.249 CSeq: 102 INVITE Via: SIP/2.0/UDP 192.168.100.249:5060;branch=z9hG4bK204f7e14 Server: Sipura/SPA942-4.1.10(e) Content-Length: 0 <-------------> [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 0: SIP/2.0 100 Trying (18) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 1: To: (35) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 2: From: "Steven Sokol" ;tag=as41561da4 (62) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 3: Call-ID: 3111d3ea5fb92e26797bbf7a456fe6a4@192.168.100.249 (57) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 4: CSeq: 102 INVITE (16) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 5: Via: SIP/2.0/UDP 192.168.100.249:5060;branch=z9hG4bK204f7e14 (60) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 6: Server: Sipura/SPA942-4.1.10(e) (31) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 7: Content-Length: 0 (17) [Jan 8 16:52:50] --- (8 headers 0 lines) --- [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:2102 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #15 - INVITE (got response) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:2111 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '3111d3ea5fb92e26797bbf7a456fe6a4@192.168.100.249' Request 102: Found [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:11532 handle_response_invite: SIP response 100 to standard invite [Jan 8 16:52:50] <--- SIP read from 192.168.100.247:5061 ---> SIP/2.0 180 Ringing To: ;tag=86110d314737ed86i1 From: "Steven Sokol" ;tag=as41561da4 Call-ID: 3111d3ea5fb92e26797bbf7a456fe6a4@192.168.100.249 CSeq: 102 INVITE Via: SIP/2.0/UDP 192.168.100.249:5060;branch=z9hG4bK204f7e14 Server: Sipura/SPA942-4.1.10(e) Content-Length: 0 <-------------> [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 0: SIP/2.0 180 Ringing (19) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 1: To: ;tag=86110d314737ed86i1 (58) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 2: From: "Steven Sokol" ;tag=as41561da4 (62) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 3: Call-ID: 3111d3ea5fb92e26797bbf7a456fe6a4@192.168.100.249 (57) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 4: CSeq: 102 INVITE (16) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 5: Via: SIP/2.0/UDP 192.168.100.249:5060;branch=z9hG4bK204f7e14 (60) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 6: Server: Sipura/SPA942-4.1.10(e) (31) [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 7: Content-Length: 0 (17) [Jan 8 16:52:50] --- (8 headers 0 lines) --- [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:2111 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '3111d3ea5fb92e26797bbf7a456fe6a4@192.168.100.249' Request 102: Found [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:11532 handle_response_invite: SIP response 180 to standard invite [Jan 8 16:52:50] DEBUG[19130]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/6002-01845a00 [Jan 8 16:52:50] DEBUG[19130]: devicestate.c:161 ast_device_state: [Jan 8 16:52:50] -- SIP/6002-01845a00 is ringing No provider found, checking channel drivers for SIP - 6002 [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:15051 sip_devicestate: Checking device state for peer 6002 [Jan 8 16:52:50] DEBUG[19130]: devicestate.c:287 do_state_change: Changing state for SIP/6002 - state 1 (Not in use) [Jan 8 16:52:50] DEBUG[19130]: rtp.c:1505 ast_rtp_early_bridge: Setting early bridge SDP of 'SIP/6001-01847800' with that of 'SIP/6002-01845a00' [Jan 8 16:52:50] DEBUG[19130]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 6002 [Jan 8 16:52:50] DEBUG[19130]: chan_sip.c:15051 sip_devicestate: Checking device state for peer 6002 [Jan 8 16:52:50] DEBUG[19130]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for IAX2 - 6002 [Jan 8 16:52:50] DEBUG[19130]: chan_iax2.c:9604 iax2_devicestate: Checking device state for device 6002 [Jan 8 16:52:50] <--- Transmitting (NAT) to 192.168.100.163:5060 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 192.168.100.163:5060;branch=z9hG4bK-61d76283;received=192.168.100.163 From: "Paul Barham" ;tag=58b2b7728e83ed57o0 To: "Paul Barham" ;tag=as294415d8 Call-ID: 8792f9ce-bbfb2eab@192.168.100.163 CSeq: 102 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Jan 8 16:52:50] DEBUG[19130]: app_queue.c:546 changethread: Device 'SIP/6002' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jan 8 16:52:50] DEBUG[19130]: chan_iax2.c:9612 iax2_devicestate: iax2_devicestate: Found peer. What's device state of 6002? addr=0, defaddr=0 maxms=0, lastms=0 [Jan 8 16:52:53] <--- SIP read from 192.168.100.247:5061 ---> SIP/2.0 200 OK To: ;tag=86110d314737ed86i1 From: "Steven Sokol" ;tag=as41561da4 Call-ID: 3111d3ea5fb92e26797bbf7a456fe6a4@192.168.100.249 CSeq: 102 INVITE Via: SIP/2.0/UDP 192.168.100.249:5060;branch=z9hG4bK204f7e14 Contact: Server: Sipura/SPA942-4.1.10(e) Content-Length: 210 Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER Content-Type: application/sdp v=0 o=- 20100 20100 IN IP4 192.168.100.247 s=- c=IN IP4 192.168.100.247 t=0 0 m=audio 16414 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:20 a=sendrecv <-------------> [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 0: SIP/2.0 200 OK (14) [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 1: To: ;tag=86110d314737ed86i1 (58) [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 2: From: "Steven Sokol" ;tag=as41561da4 (62) [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 3: Call-ID: 3111d3ea5fb92e26797bbf7a456fe6a4@192.168.100.249 (57) [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 4: CSeq: 102 INVITE (16) [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 5: Via: SIP/2.0/UDP 192.168.100.249:5060;branch=z9hG4bK204f7e14 (60) [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 6: Contact: (40) [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 7: Server: Sipura/SPA942-4.1.10(e) (31) [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 8: Content-Length: 210 (19) [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 9: Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER (61) [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 10: Content-Type: application/sdp (29) [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 11: (0) [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:4555 parse_request: Line: v=0 (3) [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:4555 parse_request: Line: o=- 20100 20100 IN IP4 192.168.100.247 (38) [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:4555 parse_request: Line: s=- (3) [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:4555 parse_request: Line: c=IN IP4 192.168.100.247 (24) [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:4555 parse_request: Line: t=0 0 (5) [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:4555 parse_request: Line: m=audio 16414 RTP/AVP 0 101 (27) [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:4555 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:4555 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:4555 parse_request: Line: a=fmtp:101 0-15 (15) [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:4555 parse_request: Line: a=ptime:20 (10) [Jan 8 16:52:53] --- (11 headers 11 lines) --- [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:2051 __sip_ack: Acked pending invite 102 [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:2069 __sip_ack: Stopping retransmission on '3111d3ea5fb92e26797bbf7a456fe6a4@192.168.100.249' of Request 102: Match Not Found [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:11532 handle_response_invite: SIP response 200 to standard invite [Jan 8 16:52:53] Found RTP audio format 0 [Jan 8 16:52:53] Found RTP audio format 101 [Jan 8 16:52:53] Peer audio RTP is at port 192.168.100.247:16414 [Jan 8 16:52:53] Found description format PCMU for ID 0 [Jan 8 16:52:53] Found description format telephone-event for ID 101 [Jan 8 16:52:53] Got unsupported a:fmtp in SDP offer [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:5066 process_sdp: T38 state changed to 0 on channel SIP/6002-01845a00 [Jan 8 16:52:53] Capabilities: us - 0x8000e (gsm|ulaw|alaw|h263), peer - audio=0x4 (ulaw)/video=0x0 (nothing), combined - 0x4 (ulaw) [Jan 8 16:52:53] Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [Jan 8 16:52:53] Peer audio RTP is at port 192.168.100.247:16414 [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:5143 process_sdp: We're settling with these formats: 0x4 (ulaw) [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:5150 process_sdp: We have an owner, now see if we need to change this call [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:2974 update_call_counter: Updating call counter for outgoing call [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:7892 build_route: build_route: Contact hop: [Jan 8 16:52:53] list_route: hop: [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:5574 reqprep: Strict routing enforced for session 3111d3ea5fb92e26797bbf7a456fe6a4@192.168.100.249 [Jan 8 16:52:53] set_destination: Parsing for address/port to send to [Jan 8 16:52:53] set_destination: set destination to 192.168.100.247, port 5061 [Jan 8 16:52:53] Transmitting (NAT) to 192.168.100.247:5061: ACK sip:6002@192.168.100.247:5061 SIP/2.0 Via: SIP/2.0/UDP 192.168.100.249:5060;branch=z9hG4bK65aa75ce;rport From: "Steven Sokol" ;tag=as41561da4 To: ;tag=86110d314737ed86i1 Contact: Call-ID: 3111d3ea5fb92e26797bbf7a456fe6a4@192.168.100.249 CSeq: 102 ACK User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- [Jan 8 16:52:53] DEBUG[19130]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/6002-01845a00 [Jan 8 16:52:53] -- SIP/6002-01845a00 answered SIP/6001-01847800 [Jan 8 16:52:53] DEBUG[19130]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 6002 [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:16686 sip_set_rtp_peer: Early remote bridge setting SIP '8792f9ce-bbfb2eab@192.168.100.163' - Sending media to 192.168.100.247 [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:15051 sip_devicestate: Checking device state for peer 6002 [Jan 8 16:52:53] DEBUG[19130]: rtp.c:1505 ast_rtp_early_bridge: Setting early bridge SDP of 'SIP/6001-01847800' with that of 'SIP/6002-01845a00' [Jan 8 16:52:53] DEBUG[19130]: devicestate.c:287 do_state_change: Changing state for SIP/6002 - state 1 (Not in use) [Jan 8 16:52:53] DEBUG[19130]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/6001-01847800 [Jan 8 16:52:53] DEBUG[19130]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 6002 [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:3424 sip_answer: SIP answering channel: SIP/6001-01847800 [Jan 8 16:52:53] DEBUG[19130]: app_queue.c:546 changethread: Device 'SIP/6002' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:15051 sip_devicestate: Checking device state for peer 6002 [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:6351 transmit_response_with_sdp: Setting framing from config on incoming call [Jan 8 16:52:53] DEBUG[19130]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for IAX2 - 6002 [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:6119 add_sdp: ** Our capability: 0xc (ulaw|alaw) Video flag: True [Jan 8 16:52:53] DEBUG[19130]: chan_iax2.c:9604 iax2_devicestate: Checking device state for device 6002 [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:6120 add_sdp: ** Our prefcodec: 0x0 (nothing) [Jan 8 16:52:53] Audio is at 192.168.100.249 port 16988 [Jan 8 16:52:53] Adding codec 0x4 (ulaw) to SDP [Jan 8 16:52:53] Adding codec 0x8 (alaw) to SDP [Jan 8 16:52:53] Adding non-codec 0x1 (telephone-event) to SDP [Jan 8 16:52:53] DEBUG[19130]: chan_iax2.c:9612 iax2_devicestate: iax2_devicestate: Found peer. What's device state of 6002? addr=0, defaddr=0 maxms=0, lastms=0 [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:6251 add_sdp: -- Done with adding codecs to SDP [Jan 8 16:52:53] DEBUG[19130]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 6001 [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:6296 add_sdp: Done building SDP. Settling with this capability: 0xc (ulaw|alaw) [Jan 8 16:52:53] <--- Reliably Transmitting (NAT) to 192.168.100.163:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.100.163:5060;branch=z9hG4bK-61d76283;received=192.168.100.163 From: "Paul Barham" ;tag=58b2b7728e83ed57o0 To: "Paul Barham" ;tag=as294415d8 Call-ID: 8792f9ce-bbfb2eab@192.168.100.163 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: 270 v=0 o=root 19130 19130 IN IP4 192.168.100.247 s=session c=IN IP4 192.168.100.247 t=0 0 m=audio 16414 RTP/AVP 0 8 101 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv <------------> [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:15051 sip_devicestate: Checking device state for peer 6001 [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:1955 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #17 [Jan 8 16:52:53] DEBUG[19130]: devicestate.c:287 do_state_change: Changing state for SIP/6001 - state 1 (Not in use) [Jan 8 16:52:53] -- Native bridging SIP/6001-01847800 and SIP/6002-01845a00 [Jan 8 16:52:53] DEBUG[19130]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 6001 [Jan 8 16:52:53] DEBUG[19130]: app_queue.c:546 changethread: Device 'SIP/6001' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:16689 sip_set_rtp_peer: Sending reinvite on SIP '3111d3ea5fb92e26797bbf7a456fe6a4@192.168.100.249' - It's audio soon redirected to IP 192.168.100.163 [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:15051 sip_devicestate: Checking device state for peer 6001 [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:5574 reqprep: Strict routing enforced for session 3111d3ea5fb92e26797bbf7a456fe6a4@192.168.100.249 [Jan 8 16:52:53] set_destination: Parsing for address/port to send to [Jan 8 16:52:53] DEBUG[19130]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for IAX2 - 6001 [Jan 8 16:52:53] DEBUG[19130]: chan_iax2.c:9604 iax2_devicestate: [Jan 8 16:52:53] set_destination: set destination to 192.168.100.247, port 5061 Checking device state for device 6001 [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:6119 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True [Jan 8 16:52:53] DEBUG[19130]: chan_iax2.c:9612 iax2_devicestate: iax2_devicestate: Found peer. What's device state of 6001? addr=0, defaddr=0 maxms=0, lastms=0 [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:6120 add_sdp: ** Our prefcodec: 0x4 (ulaw) [Jan 8 16:52:53] Audio is at 192.168.100.249 port 17850 [Jan 8 16:52:53] Adding codec 0x4 (ulaw) to SDP [Jan 8 16:52:53] Adding non-codec 0x1 (telephone-event) to SDP [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:6251 add_sdp: -- Done with adding codecs to SDP [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:6296 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw) [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:1601 initialize_initreq: Initializing already initialized SIP dialog 3111d3ea5fb92e26797bbf7a456fe6a4@192.168.100.249 (presumably reinvite) [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 0: INVITE sip:6002@192.168.100.247:5061 SIP/2.0 (44) [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.100.249:5060;branch=z9hG4bK19aec727;rport (66) [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 2: From: "Steven Sokol" ;tag=as41561da4 (62) [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 3: To: ;tag=86110d314737ed86i1 (58) [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 4: Contact: (35) [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 5: Call-ID: 3111d3ea5fb92e26797bbf7a456fe6a4@192.168.100.249 (57) [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 6: CSeq: 103 INVITE (16) [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 7: User-Agent: Asterisk PBX (24) [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 8: Max-Forwards: 70 (16) [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 9: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 10: Supported: replaces (19) [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 11: X-asterisk-Info: SIP re-invite (External RTP bridge) (52) [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 12: Content-Type: application/sdp (29) [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 13: Content-Length: 246 (19) [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 14: (0) [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:4555 parse_request: Line: v=0 (3) [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:4555 parse_request: Line: o=root 19130 19131 IN IP4 192.168.100.163 (41) [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:4555 parse_request: Line: s=session (9) [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:4555 parse_request: Line: c=IN IP4 192.168.100.163 (24) [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:4555 parse_request: Line: t=0 0 (5) [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:4555 parse_request: Line: m=audio 16420 RTP/AVP 0 101 (27) [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:4555 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:4555 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:4555 parse_request: Line: a=fmtp:101 0-16 (15) [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:4555 parse_request: Line: a=silenceSupp:off - - - - (25) [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:4555 parse_request: Line: a=ptime:20 (10) [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:4555 parse_request: Line: a=sendrecv (10) [Jan 8 16:52:53] Reliably Transmitting (NAT) to 192.168.100.247:5061: INVITE sip:6002@192.168.100.247:5061 SIP/2.0 Via: SIP/2.0/UDP 192.168.100.249:5060;branch=z9hG4bK19aec727;rport From: "Steven Sokol" ;tag=as41561da4 To: ;tag=86110d314737ed86i1 Contact: Call-ID: 3111d3ea5fb92e26797bbf7a456fe6a4@192.168.100.249 CSeq: 103 INVITE User-Agent: Asterisk PBX Max-Forwards: 70 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces X-asterisk-Info: SIP re-invite (External RTP bridge) Content-Type: application/sdp Content-Length: 246 v=0 o=root 19130 19131 IN IP4 192.168.100.163 s=session c=IN IP4 192.168.100.163 t=0 0 m=audio 16420 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 --- [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:1955 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #18 [Jan 8 16:52:53] <--- SIP read from 192.168.100.163:5060 ---> ACK sip:6002@192.168.100.249 SIP/2.0 Via: SIP/2.0/UDP 192.168.100.163:5060;branch=z9hG4bK-d49456cb From: "Paul Barham" ;tag=58b2b7728e83ed57o0 To: "Paul Barham" ;tag=as294415d8 Call-ID: 8792f9ce-bbfb2eab@192.168.100.163 CSeq: 102 ACK Max-Forwards: 70 Proxy-Authorization: Digest username="6001",realm="",nonce="63351778",uri="sip:6002@192.168.100.249",algorithm=MD5,response="f3ea7a35fabcfd25e76589575df57450" Contact: "Paul Barham" User-Agent: Linksys/SPA962-5.1.3 Content-Length: 0 <-------------> [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 0: ACK sip:6002@192.168.100.249 SIP/2.0 (36) [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.100.163:5060;branch=z9hG4bK-d49456cb (61) [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 2: From: "Paul Barham" ;tag=58b2b7728e83ed57o0 (69) [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 3: To: "Paul Barham" ;tag=as294415d8 (59) [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 4: Call-ID: 8792f9ce-bbfb2eab@192.168.100.163 (42) [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 5: CSeq: 102 ACK (13) [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 6: Max-Forwards: 70 (16) [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 7: Proxy-Authorization: Digest username="6001",realm="",nonce="63351778",uri="sip:6002@192.168.100.249",algorithm=MD5,response="f3ea7a35fabcfd25e76589575df57450" (158) [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 8: Contact: "Paul Barham" (54) [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 9: User-Agent: Linksys/SPA962-5.1.3 (32) [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 10: Content-Length: 0 (17) [Jan 8 16:52:53] --- (11 headers 0 lines) --- [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:14456 handle_request: **** Received ACK (6) - Command in SIP ACK [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:2059 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #17 [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:2069 __sip_ack: Stopping retransmission on '8792f9ce-bbfb2eab@192.168.100.163' of Response 102: Match Not Found [Jan 8 16:52:53] <--- SIP read from 192.168.100.247:5061 ---> SIP/2.0 200 OK To: ;tag=86110d314737ed86i1 From: "Steven Sokol" ;tag=as41561da4 Call-ID: 3111d3ea5fb92e26797bbf7a456fe6a4@192.168.100.249 CSeq: 103 INVITE Via: SIP/2.0/UDP 192.168.100.249:5060;branch=z9hG4bK19aec727 Contact: Server: Sipura/SPA942-4.1.10(e) Content-Length: 210 Content-Type: application/sdp v=0 o=- 20433 20433 IN IP4 192.168.100.247 s=- c=IN IP4 192.168.100.247 t=0 0 m=audio 16414 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:20 a=sendrecv <-------------> [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 0: SIP/2.0 200 OK (14) [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 1: To: ;tag=86110d314737ed86i1 (58) [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 2: From: "Steven Sokol" ;tag=as41561da4 (62) [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 3: Call-ID: 3111d3ea5fb92e26797bbf7a456fe6a4@192.168.100.249 (57) [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 4: CSeq: 103 INVITE (16) [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 5: Via: SIP/2.0/UDP 192.168.100.249:5060;branch=z9hG4bK19aec727 (60) [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 6: Contact: (40) [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 7: Server: Sipura/SPA942-4.1.10(e) (31) [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 8: Content-Length: 210 (19) [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 9: Content-Type: application/sdp (29) [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 10: (0) [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:4555 parse_request: Line: v=0 (3) [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:4555 parse_request: Line: o=- 20433 20433 IN IP4 192.168.100.247 (38) [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:4555 parse_request: Line: s=- (3) [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:4555 parse_request: Line: c=IN IP4 192.168.100.247 (24) [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:4555 parse_request: Line: t=0 0 (5) [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:4555 parse_request: Line: m=audio 16414 RTP/AVP 0 101 (27) [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:4555 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:4555 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:4555 parse_request: Line: a=fmtp:101 0-15 (15) [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:4555 parse_request: Line: a=ptime:20 (10) [Jan 8 16:52:53] --- (10 headers 11 lines) --- [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:2051 __sip_ack: Acked pending invite 103 [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:2059 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #18 [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:2069 __sip_ack: Stopping retransmission on '3111d3ea5fb92e26797bbf7a456fe6a4@192.168.100.249' of Request 103: Match Not Found [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:11530 handle_response_invite: SIP response 200 to RE-invite on outgoing call 3111d3ea5fb92e26797bbf7a456fe6a4@192.168.100.249 [Jan 8 16:52:53] Found RTP audio format 0 [Jan 8 16:52:53] Found RTP audio format 101 [Jan 8 16:52:53] Peer audio RTP is at port 192.168.100.247:16414 [Jan 8 16:52:53] Found description format PCMU for ID 0 [Jan 8 16:52:53] Found description format telephone-event for ID 101 [Jan 8 16:52:53] Got unsupported a:fmtp in SDP offer [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:5066 process_sdp: T38 state changed to 0 on channel SIP/6002-01845a00 [Jan 8 16:52:53] Capabilities: us - 0x8000e (gsm|ulaw|alaw|h263), peer - audio=0x4 (ulaw)/video=0x0 (nothing), combined - 0x4 (ulaw) [Jan 8 16:52:53] Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [Jan 8 16:52:53] Peer audio RTP is at port 192.168.100.247:16414 [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:5143 process_sdp: We're settling with these formats: 0x4 (ulaw) [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:5150 process_sdp: We have an owner, now see if we need to change this call [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:2974 update_call_counter: Updating call counter for outgoing call [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:7831 build_route: build_route: Retaining previous route: [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:11663 handle_response_invite: Strange... The other side of the bridge does not have a udptl struct [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:11668 handle_response_invite: T38 state changed to 0 on channel SIP [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:11671 handle_response_invite: T38 state changed to 0 on channel SIP/6002-01845a00 [Jan 8 16:52:53] DEBUG[19130]: chan_sip.c:5574 reqprep: Strict routing enforced for session 3111d3ea5fb92e26797bbf7a456fe6a4@192.168.100.249 [Jan 8 16:52:53] set_destination: Parsing for address/port to send to [Jan 8 16:52:53] set_destination: set destination to 192.168.100.247, port 5061 [Jan 8 16:52:53] Transmitting (NAT) to 192.168.100.247:5061: ACK sip:6002@192.168.100.247:5061 SIP/2.0 Via: SIP/2.0/UDP 192.168.100.249:5060;branch=z9hG4bK787615d7;rport From: "Steven Sokol" ;tag=as41561da4 To: ;tag=86110d314737ed86i1 Contact: Call-ID: 3111d3ea5fb92e26797bbf7a456fe6a4@192.168.100.249 CSeq: 103 ACK User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- [Jan 8 16:53:06] DEBUG[19130]: chan_iax2.c:7697 iax2_do_register: Allocate call number [Jan 8 16:53:06] DEBUG[19130]: chan_iax2.c:7703 iax2_do_register: Registration created on call 5 [Jan 8 16:53:16] DEBUG[19130]: chan_iax2.c:7091 socket_process: Peer trunk_1: got pong, lastms 1, historicms 1, maxms 2000 [Jan 8 16:53:16] DEBUG[19130]: chan_iax2.c:7091 socket_process: Peer 6000: got pong, lastms 7, historicms 7, maxms 2000 [Jan 8 16:53:20] DEBUG[19130]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel IAX2/6000 [Jan 8 16:53:20] DEBUG[19130]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for IAX2 - 6000 [Jan 8 16:53:20] DEBUG[19130]: chan_iax2.c:9604 iax2_devicestate: Checking device state for device 6000 [Jan 8 16:53:20] DEBUG[19130]: chan_iax2.c:9612 iax2_devicestate: iax2_devicestate: Found peer. What's device state of 6000? addr=16777343, defaddr=0 maxms=2000, lastms=7 [Jan 8 16:53:20] DEBUG[19130]: devicestate.c:287 do_state_change: Changing state for IAX2/6000 - state 1 (Not in use) [Jan 8 16:53:20] DEBUG[19130]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 6000 [Jan 8 16:53:20] DEBUG[19130]: app_queue.c:546 changethread: Device 'IAX2/6000' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jan 8 16:53:20] DEBUG[19130]: chan_sip.c:15051 sip_devicestate: Checking device state for peer 6000 [Jan 8 16:53:20] DEBUG[19130]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for IAX2 - 6000 [Jan 8 16:53:20] DEBUG[19130]: chan_iax2.c:9604 iax2_devicestate: Checking device state for device 6000 [Jan 8 16:53:20] DEBUG[19130]: chan_iax2.c:9612 iax2_devicestate: iax2_devicestate: Found peer. What's device state of 6000? addr=16777343, defaddr=0 maxms=2000, lastms=7 [Jan 8 16:53:28] -- Accepting AUTHENTICATED call from 127.0.0.1: > requested format = gsm, > requested prefs = (), > actual format = ulaw, > host prefs = (ulaw|alaw|gsm), > priority = mine [Jan 8 16:53:28] DEBUG[19130]: pbx.c:1767 pbx_extension_helper: Launching 'NoOp' [Jan 8 16:53:28] -- Executing [*846002@user-6000:1] NoOp("IAX2/6000-2", "Call Monitoring Enabled: 6002") in new stack [Jan 8 16:53:28] DEBUG[19130]: pbx.c:1767 pbx_extension_helper: Launching 'Answer' [Jan 8 16:53:28] -- Executing [*846002@user-6000:2] Answer("IAX2/6000-2", "") in new stack [Jan 8 16:53:28] DEBUG[19130]: chan_iax2.c:3183 iax2_answer: Answering IAX2 call [Jan 8 16:53:28] DEBUG[19130]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel IAX2/6000-2 [Jan 8 16:53:28] DEBUG[19130]: pbx.c:1767 pbx_extension_helper: Launching 'Playback' [Jan 8 16:53:28] -- Executing [*846002@user-6000:3] Playback("IAX2/6000-2", "beep") in new stack [Jan 8 16:53:28] DEBUG[19130]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for IAX2 - 6000 [Jan 8 16:53:28] DEBUG[19130]: chan_iax2.c:9604 iax2_devicestate: Checking device state for device 6000 [Jan 8 16:53:28] DEBUG[19130]: chan_iax2.c:9612 iax2_devicestate: iax2_devicestate: Found peer. What's device state of 6000? addr=16777343, defaddr=0 maxms=2000, lastms=7 [Jan 8 16:53:28] DEBUG[19130]: devicestate.c:287 do_state_change: Changing state for IAX2/6000 - state 2 (In use) [Jan 8 16:53:28] DEBUG[19130]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 6000 [Jan 8 16:53:28] DEBUG[19130]: chan_sip.c:15051 sip_devicestate: Checking device state for peer 6000 [Jan 8 16:53:28] DEBUG[19130]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for IAX2 - 6000 [Jan 8 16:53:28] DEBUG[19130]: chan_iax2.c:9604 iax2_devicestate: Checking device state for device 6000 [Jan 8 16:53:28] DEBUG[19130]: chan_iax2.c:9612 iax2_devicestate: iax2_devicestate: Found peer. What's device state of 6000? addr=16777343, defaddr=0 maxms=2000, lastms=7 [Jan 8 16:53:28] DEBUG[19130]: app_queue.c:546 changethread: Device 'IAX2/6000' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Jan 8 16:53:28] DEBUG[19130]: channel.c:2731 set_format: Set channel IAX2/6000-2 to write format ulaw [Jan 8 16:53:28] -- Playing 'beep' (language 'en') [Jan 8 16:53:28] DEBUG[19130]: chan_iax2.c:6630 socket_process: Ooh, voice format changed to 4 [Jan 8 16:53:28] DEBUG[19130]: channel.c:2731 set_format: Set channel IAX2/6000-2 to read format ulaw [Jan 8 16:53:28] DEBUG[19130]: pbx.c:1767 pbx_extension_helper: Launching 'ChanSpy' [Jan 8 16:53:28] -- Executing [*846002@user-6000:4] ChanSpy("IAX2/6000-2", "SIP/6002|bq") in new stack [Jan 8 16:53:28] DEBUG[19130]: channel.c:2731 set_format: Set channel IAX2/6000-2 to write format slin [Jan 8 16:53:28] == Spying on channel SIP/6002-01845a00 [Jan 8 16:53:28] NOTICE[19130]: app_chanspy.c:202 start_spying: Attaching IAX2/6000-2 to SIP/6002-01845a00 [Jan 8 16:53:28] DEBUG[19130]: channel.c:1263 ast_channel_spy_add: Spy ChanSpy added to channel SIP/6002-01845a00 [Jan 8 16:53:28] DEBUG[19130]: channel.c:1394 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/6001-01847800' [Jan 8 16:53:28] DEBUG[19130]: rtp.c:2830 bridge_native_loop: Ooh, empty read... [Jan 8 16:53:28] -- Native bridging SIP/6001-01847800 and SIP/6002-01845a00 ended [Jan 8 16:53:28] DEBUG[19130]: channel.c:3682 ast_generic_bridge: Didn't get a frame from channel: SIP/6001-01847800 [Jan 8 16:53:28] DEBUG[19130]: channel.c:3990 ast_channel_bridge: Bridge stops bridging channels SIP/6001-01847800 and SIP/6002-01845a00 [Jan 8 16:53:28] DEBUG[19130]: channel.c:1299 spy_detach: Spy ChanSpy removed from channel SIP/6002-01845a00 [Jan 8 16:53:28] DEBUG[19130]: channel.c:1606 ast_hangup: Hanging up channel 'SIP/6002-01845a00' [Jan 8 16:53:28] DEBUG[19130]: chan_sip.c:3274 sip_hangup: Hangup call SIP/6002-01845a00, SIP callid 3111d3ea5fb92e26797bbf7a456fe6a4@192.168.100.249) [Jan 8 16:53:28] DEBUG[19130]: chan_sip.c:3282 sip_hangup: update_call_counter(6002) - decrement call limit counter on hangup [Jan 8 16:53:28] DEBUG[19130]: chan_sip.c:2974 update_call_counter: Updating call counter for outgoing call [Jan 8 16:53:28] Scheduling destruction of SIP dialog '3111d3ea5fb92e26797bbf7a456fe6a4@192.168.100.249' in 32000 ms (Method: INVITE) [Jan 8 16:53:28] DEBUG[19130]: chan_sip.c:5574 reqprep: Strict routing enforced for session 3111d3ea5fb92e26797bbf7a456fe6a4@192.168.100.249 [Jan 8 16:53:28] set_destination: Parsing for address/port to send to [Jan 8 16:53:28] set_destination: set destination to 192.168.100.247, port 5061 [Jan 8 16:53:28] Reliably Transmitting (NAT) to 192.168.100.247:5061: BYE sip:6002@192.168.100.247:5061 SIP/2.0 Via: SIP/2.0/UDP 192.168.100.249:5060;branch=z9hG4bK2ba6b996;rport From: "Steven Sokol" ;tag=as41561da4 To: ;tag=86110d314737ed86i1 Call-ID: 3111d3ea5fb92e26797bbf7a456fe6a4@192.168.100.249 CSeq: 104 BYE User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- [Jan 8 16:53:28] DEBUG[19130]: chan_sip.c:1955 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #20 [Jan 8 16:53:28] DEBUG[19130]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/6002-01845a00 [Jan 8 16:53:28] DEBUG[19130]: rtp.c:1465 ast_rtp_early_bridge: Channel '' has no RTP, not doing anything [Jan 8 16:53:28] DEBUG[19130]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 6002 [Jan 8 16:53:28] DEBUG[19130]: app_dial.c:1643 dial_exec_full: Exiting with DIALSTATUS=ANSWER. [Jan 8 16:53:28] DEBUG[19130]: chan_sip.c:15051 sip_devicestate: Checking device state for peer 6002 [Jan 8 16:53:28] DEBUG[19130]: app_macro.c:253 _macro_exec: Spawn extension (macro-stdexten,s,4) exited non-zero on 'SIP/6001-01847800' in macro 'stdexten' [Jan 8 16:53:28] DEBUG[19130]: devicestate.c:287 do_state_change: Changing state for SIP/6002 - state 1 (Not in use) [Jan 8 16:53:28] DEBUG[19130]: pbx.c:2363 __ast_pbx_run: Spawn extension (macro-stdexten,s,4) exited non-zero on 'SIP/6001-01847800' [Jan 8 16:53:28] == Spawn extension (macro-stdexten, s, 4) exited non-zero on 'SIP/6001-01847800' [Jan 8 16:53:28] DEBUG[19130]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 6002 [Jan 8 16:53:28] DEBUG[19130]: channel.c:1606 ast_hangup: Hanging up channel 'SIP/6001-01847800' [Jan 8 16:53:28] DEBUG[19130]: chan_sip.c:15051 sip_devicestate: [Jan 8 16:53:28] == Done Spying on channel SIP/6002-01845a00 Checking device state for peer 6002 [Jan 8 16:53:28] DEBUG[19130]: app_queue.c:546 changethread: Device 'SIP/6002' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jan 8 16:53:28] DEBUG[19130]: chan_sip.c:3274 sip_hangup: Hangup call SIP/6001-01847800, SIP callid 8792f9ce-bbfb2eab@192.168.100.163) [Jan 8 16:53:28] DEBUG[19130]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for IAX2 - 6002 [Jan 8 16:53:28] DEBUG[19130]: chan_sip.c:3282 sip_hangup: update_call_counter(6001) - decrement call limit counter on hangup [Jan 8 16:53:28] DEBUG[19130]: chan_iax2.c:9604 iax2_devicestate: Checking device state for device 6002 [Jan 8 16:53:28] DEBUG[19130]: chan_sip.c:2974 update_call_counter: Updating call counter for incoming call [Jan 8 16:53:28] Scheduling destruction of SIP dialog '8792f9ce-bbfb2eab@192.168.100.163' in 32000 ms (Method: ACK) [Jan 8 16:53:28] DEBUG[19130]: chan_iax2.c:9612 iax2_devicestate: iax2_devicestate: Found peer. What's device state of 6002? addr=0, defaddr=0 maxms=0, lastms=0 [Jan 8 16:53:28] DEBUG[19130]: chan_sip.c:5574 reqprep: Strict routing enforced for session 8792f9ce-bbfb2eab@192.168.100.163 [Jan 8 16:53:28] set_destination: Parsing for address/port to send to [Jan 8 16:53:28] set_destination: set destination to 192.168.100.163, port 5060 [Jan 8 16:53:28] Reliably Transmitting (NAT) to 192.168.100.163:5060: BYE sip:6001@192.168.100.163:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.100.249:5060;branch=z9hG4bK0433746d;rport From: "Paul Barham" ;tag=as294415d8 To: "Paul Barham" ;tag=58b2b7728e83ed57o0 Call-ID: 8792f9ce-bbfb2eab@192.168.100.163 CSeq: 102 BYE User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- [Jan 8 16:53:28] DEBUG[19130]: chan_sip.c:1955 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #22 [Jan 8 16:53:28] DEBUG[19130]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/6001-01847800 [Jan 8 16:53:28] DEBUG[19130]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 6001 [Jan 8 16:53:28] DEBUG[19130]: chan_sip.c:15051 sip_devicestate: Checking device state for peer 6001 [Jan 8 16:53:28] DEBUG[19130]: devicestate.c:287 do_state_change: Changing state for SIP/6001 - state 1 (Not in use) [Jan 8 16:53:28] DEBUG[19130]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 6001 [Jan 8 16:53:28] DEBUG[19130]: app_queue.c:546 changethread: Device 'SIP/6001' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jan 8 16:53:28] DEBUG[19130]: chan_sip.c:15051 sip_devicestate: Checking device state for peer 6001 [Jan 8 16:53:28] DEBUG[19130]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for IAX2 - 6001 [Jan 8 16:53:28] DEBUG[19130]: chan_iax2.c:9604 iax2_devicestate: Checking device state for device 6001 [Jan 8 16:53:28] DEBUG[19130]: chan_iax2.c:9612 iax2_devicestate: iax2_devicestate: Found peer. What's device state of 6001? addr=0, defaddr=0 maxms=0, lastms=0 [Jan 8 16:53:28] <--- SIP read from 192.168.100.163:5060 ---> SIP/2.0 200 OK To: "Paul Barham" ;tag=58b2b7728e83ed57o0 From: "Paul Barham" ;tag=as294415d8 Call-ID: 8792f9ce-bbfb2eab@192.168.100.163 CSeq: 102 BYE Via: SIP/2.0/UDP 192.168.100.249:5060;branch=z9hG4bK0433746d Server: Linksys/SPA962-5.1.3 Content-Length: 0 <-------------> [Jan 8 16:53:28] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 0: SIP/2.0 200 OK (14) [Jan 8 16:53:28] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 1: To: "Paul Barham" ;tag=58b2b7728e83ed57o0 (67) [Jan 8 16:53:28] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 2: From: "Paul Barham" ;tag=as294415d8 (61) [Jan 8 16:53:28] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 3: Call-ID: 8792f9ce-bbfb2eab@192.168.100.163 (42) [Jan 8 16:53:28] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 4: CSeq: 102 BYE (13) [Jan 8 16:53:28] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 5: Via: SIP/2.0/UDP 192.168.100.249:5060;branch=z9hG4bK0433746d (60) [Jan 8 16:53:28] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 6: Server: Linksys/SPA962-5.1.3 (28) [Jan 8 16:53:28] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 7: Content-Length: 0 (17) [Jan 8 16:53:28] --- (8 headers 0 lines) --- [Jan 8 16:53:28] DEBUG[19130]: chan_sip.c:2059 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #22 [Jan 8 16:53:28] DEBUG[19130]: chan_sip.c:2069 __sip_ack: Stopping retransmission on '8792f9ce-bbfb2eab@192.168.100.163' of Request 102: Match Not Found [Jan 8 16:53:28] SIP Response message for INCOMING dialog BYE arrived [Jan 8 16:53:28] Really destroying SIP dialog '8792f9ce-bbfb2eab@192.168.100.163' Method: ACK [Jan 8 16:53:28] <--- SIP read from 192.168.100.247:5061 ---> SIP/2.0 200 OK To: ;tag=86110d314737ed86i1 From: "Steven Sokol" ;tag=as41561da4 Call-ID: 3111d3ea5fb92e26797bbf7a456fe6a4@192.168.100.249 CSeq: 104 BYE Via: SIP/2.0/UDP 192.168.100.249:5060;branch=z9hG4bK2ba6b996 Server: Sipura/SPA942-4.1.10(e) Content-Length: 0 <-------------> [Jan 8 16:53:28] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 0: SIP/2.0 200 OK (14) [Jan 8 16:53:28] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 1: To: ;tag=86110d314737ed86i1 (58) [Jan 8 16:53:28] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 2: From: "Steven Sokol" ;tag=as41561da4 (62) [Jan 8 16:53:28] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 3: Call-ID: 3111d3ea5fb92e26797bbf7a456fe6a4@192.168.100.249 (57) [Jan 8 16:53:28] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 4: CSeq: 104 BYE (13) [Jan 8 16:53:28] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 5: Via: SIP/2.0/UDP 192.168.100.249:5060;branch=z9hG4bK2ba6b996 (60) [Jan 8 16:53:28] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 6: Server: Sipura/SPA942-4.1.10(e) (31) [Jan 8 16:53:28] DEBUG[19130]: chan_sip.c:4523 parse_request: Header 7: Content-Length: 0 (17) [Jan 8 16:53:28] --- (8 headers 0 lines) --- [Jan 8 16:53:28] DEBUG[19130]: chan_sip.c:2059 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #20 [Jan 8 16:53:28] DEBUG[19130]: chan_sip.c:2069 __sip_ack: Stopping retransmission on '3111d3ea5fb92e26797bbf7a456fe6a4@192.168.100.249' of Request 104: Match Not Found [Jan 8 16:53:28] Really destroying SIP dialog '3111d3ea5fb92e26797bbf7a456fe6a4@192.168.100.249' Method: INVITE [Jan 8 16:53:40] DEBUG[19130]: chan_iax2.c:6925 socket_process: Immediately destroying 2, having received hangup [Jan 8 16:53:40] DEBUG[19130]: channel.c:2731 set_format: Set channel IAX2/6000-2 to write format ulaw [Jan 8 16:53:40] DEBUG[19130]: pbx.c:2363 __ast_pbx_run: Spawn extension (user-6000,*846002,4) exited non-zero on 'IAX2/6000-2' [Jan 8 16:53:40] == Spawn extension (user-6000, *846002, 4) exited non-zero on 'IAX2/6000-2' [Jan 8 16:53:40] DEBUG[19130]: channel.c:1606 ast_hangup: Hanging up channel 'IAX2/6000-2' [Jan 8 16:53:40] DEBUG[19130]: chan_iax2.c:2940 iax2_hangup: We're hanging up IAX2/6000-2 now... [Jan 8 16:53:40] DEBUG[19130]: chan_iax2.c:2950 iax2_hangup: Really destroying IAX2/6000-2 now... [Jan 8 16:53:40] -- Hungup 'IAX2/6000-2' [Jan 8 16:53:40] DEBUG[19130]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel IAX2/6000-2 [Jan 8 16:53:40] DEBUG[19130]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for IAX2 - 6000 [Jan 8 16:53:40] DEBUG[19130]: chan_iax2.c:9604 iax2_devicestate: Checking device state for device 6000 [Jan 8 16:53:40] DEBUG[19130]: chan_iax2.c:9612 iax2_devicestate: iax2_devicestate: Found peer. What's device state of 6000? addr=16777343, defaddr=0 maxms=2000, lastms=7 [Jan 8 16:53:40] DEBUG[19130]: devicestate.c:287 do_state_change: Changing state for IAX2/6000 - state 1 (Not in use) [Jan 8 16:53:40] DEBUG[19130]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 6000 [Jan 8 16:53:40] DEBUG[19130]: chan_sip.c:15051 sip_devicestate: Checking device state for peer 6000 [Jan 8 16:53:40] DEBUG[19130]: app_queue.c:546 changethread: Device 'IAX2/6000' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jan 8 16:53:40] DEBUG[19130]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for IAX2 - 6000 [Jan 8 16:53:40] DEBUG[19130]: chan_iax2.c:9604 iax2_devicestate: Checking device state for device 6000 [Jan 8 16:53:40] DEBUG[19130]: chan_iax2.c:9612 iax2_devicestate: iax2_devicestate: Found peer. What's device state of 6000? addr=16777343, defaddr=0 maxms=2000, lastms=7 *CLI> stop now [Jan 8 16:53:43] Beginning asterisk shutdown.... [Jan 8 16:53:43] Executing last minute cleanups [Jan 8 16:53:43] == Destroying musiconhold processes [Jan 8 16:53:43] Asterisk cleanly ending (0). [Jan 8 16:53:43] DEBUG[19130]: asterisk.c:1191 quit_handler: Asterisk ending (0).