<--- SIP read from 192.168.4.11:5060 ---> INVITE sip:103@192.168.4.155:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.4.11;rport;branch=z9hG4bKc0a8040b0000001f461ba835000041350000002e Content-Length: 337 Contact: Call-ID: 95DAB8BF-A247-424B-ABBC-818327C31118@192.168.4.11 Content-Type: application/sdp CSeq: 1 INVITE From: "unknown";tag=3390393732197 Max-Forwards: 70 To: User-Agent: SJphone/1.60.289a (SJ Labs) v=0 o=- 3385206453 3385206453 IN IP4 192.168.4.11 s=SJphone c=IN IP4 192.168.4.11 t=0 0 a=direction:active m=audio 49152 RTP/AVP 3 97 98 8 0 101 a=rtpmap:3 GSM/8000 a=rtpmap:97 iLBC/8000 a=rtpmap:98 iLBC/8000 a=fmtp:98 mode=20 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-11,16 <-------------> [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 0 [ 41]: INVITE sip:103@192.168.4.155:5060 SIP/2.0 [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 1 [ 90]: Via: SIP/2.0/UDP 192.168.4.11;rport;branch=z9hG4bKc0a8040b0000001f461ba835000041350000002e [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 2 [ 19]: Content-Length: 337 [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 3 [ 36]: Contact: [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 4 [ 58]: Call-ID: 95DAB8BF-A247-424B-ABBC-818327C31118@192.168.4.11 [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 5 [ 29]: Content-Type: application/sdp [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 6 [ 14]: CSeq: 1 INVITE [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 7 [ 61]: From: "unknown";tag=3390393732197 [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 8 [ 16]: Max-Forwards: 70 [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 9 [ 32]: To: [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 10 [ 39]: User-Agent: SJphone/1.60.289a (SJ Labs) [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 11 [ 0]: [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Body 0 [ 3]: v=0 [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Body 1 [ 45]: o=- 3385206453 3385206453 IN IP4 192.168.4.11 [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Body 2 [ 9]: s=SJphone [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Body 3 [ 21]: c=IN IP4 192.168.4.11 [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Body 4 [ 5]: t=0 0 [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Body 5 [ 18]: a=direction:active [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Body 6 [ 37]: m=audio 49152 RTP/AVP 3 97 98 8 0 101 [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Body 7 [ 19]: a=rtpmap:3 GSM/8000 [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Body 8 [ 21]: a=rtpmap:97 iLBC/8000 [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Body 9 [ 21]: a=rtpmap:98 iLBC/8000 [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Body 10 [ 17]: a=fmtp:98 mode=20 [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Body 11 [ 20]: a=rtpmap:8 PCMA/8000 [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Body 12 [ 20]: a=rtpmap:0 PCMU/8000 [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Body 13 [ 33]: a=rtpmap:101 telephone-event/8000 --- (11 headers 14 lines) --- [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:2845 do_setnat: Setting NAT on RTP to Off [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:2850 do_setnat: Setting NAT on VRTP to Off [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:2855 do_setnat: Setting NAT on UDPTL to Off [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4666 sip_alloc: Allocating new SIP dialog for 95DAB8BF-A247-424B-ABBC-818327C31118@192.168.4.11 - INVITE (With RTP) [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:15375 handle_request: **** Received INVITE (5) - Command in SIP INVITE Sending to 192.168.4.11 : 5060 (NAT) [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:14001 handle_request_invite: Initializing initreq for method INVITE - callid 95DAB8BF-A247-424B-ABBC-818327C31118@192.168.4.11 Using INVITE request as basis request - 95DAB8BF-A247-424B-ABBC-818327C31118@192.168.4.11 No user '101' in SIP users list Found peer '101' for '101' from 192.168.4.11:5060 [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:2845 do_setnat: Setting NAT on RTP to On [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:2850 do_setnat: Setting NAT on VRTP to On [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:2855 do_setnat: Setting NAT on UDPTL to On <--- Reliably Transmitting (NAT) to 192.168.4.11:5060 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 192.168.4.11;branch=z9hG4bKc0a8040b0000001f461ba835000041350000002e;received=192.168.4.11;rport=5060 From: "unknown";tag=3390393732197 To: ;tag=as5ea7540a Call-ID: 95DAB8BF-A247-424B-ABBC-818327C31118@192.168.4.11 CSeq: 1 INVITE User-Agent: Asterisk PBX SVN-trunk-r61184 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="391bc730" Content-Length: 0 <------------> [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:2118 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #27 Scheduling destruction of SIP dialog '95DAB8BF-A247-424B-ABBC-818327C31118@192.168.4.11' in 128 ms (Method: INVITE) <--- SIP read from 192.168.4.11:5060 ---> ACK sip:103@192.168.4.155:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.4.11;rport;branch=z9hG4bKc0a8040b0000001f461ba835000041350000002e Content-Length: 0 Call-ID: 95DAB8BF-A247-424B-ABBC-818327C31118@192.168.4.11 CSeq: 1 ACK From: "unknown";tag=3390393732197 Max-Forwards: 70 To: ;tag=as5ea7540a User-Agent: SJphone/1.60.289a (SJ Labs) <-------------> [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 0 [ 38]: ACK sip:103@192.168.4.155:5060 SIP/2.0 [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 1 [ 90]: Via: SIP/2.0/UDP 192.168.4.11;rport;branch=z9hG4bKc0a8040b0000001f461ba835000041350000002e [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 2 [ 17]: Content-Length: 0 [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 3 [ 58]: Call-ID: 95DAB8BF-A247-424B-ABBC-818327C31118@192.168.4.11 [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 4 [ 11]: CSeq: 1 ACK [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 5 [ 61]: From: "unknown";tag=3390393732197 [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 6 [ 16]: Max-Forwards: 70 [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 7 [ 47]: To: ;tag=as5ea7540a [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 8 [ 39]: User-Agent: SJphone/1.60.289a (SJ Labs) --- (9 headers 0 lines) --- [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:15375 handle_request: **** Received ACK (6) - Command in SIP ACK [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:2226 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #27 [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:2237 __sip_ack: Stopping retransmission on '95DAB8BF-A247-424B-ABBC-818327C31118@192.168.4.11' of Response 1: Match Found <--- SIP read from 192.168.4.11:5060 ---> INVITE sip:103@192.168.4.155:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.4.11;rport;branch=z9hG4bKc0a8040b0000001f461ba83500003b6d0000002f Content-Length: 337 Contact: Call-ID: 95DAB8BF-A247-424B-ABBC-818327C31118@192.168.4.11 Content-Type: application/sdp CSeq: 2 INVITE From: "unknown";tag=3390393732197 Max-Forwards: 70 To: User-Agent: SJphone/1.60.289a (SJ Labs) Authorization: Digest username="101",realm="asterisk",nonce="391bc730",uri="sip:103@192.168.4.155:5060",response="cca73197b221b277ce19050724f0e89c",algorithm="MD5" v=0 o=- 3385206453 3385206453 IN IP4 192.168.4.11 s=SJphone c=IN IP4 192.168.4.11 t=0 0 a=direction:active m=audio 49152 RTP/AVP 3 97 98 8 0 101 a=rtpmap:3 GSM/8000 a=rtpmap:97 iLBC/8000 a=rtpmap:98 iLBC/8000 a=fmtp:98 mode=20 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-11,16 <-------------> [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 0 [ 41]: INVITE sip:103@192.168.4.155:5060 SIP/2.0 [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 1 [ 90]: Via: SIP/2.0/UDP 192.168.4.11;rport;branch=z9hG4bKc0a8040b0000001f461ba83500003b6d0000002f [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 2 [ 19]: Content-Length: 337 [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 3 [ 36]: Contact: [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 4 [ 58]: Call-ID: 95DAB8BF-A247-424B-ABBC-818327C31118@192.168.4.11 [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 5 [ 29]: Content-Type: application/sdp [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 6 [ 14]: CSeq: 2 INVITE [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 7 [ 61]: From: "unknown";tag=3390393732197 [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 8 [ 16]: Max-Forwards: 70 [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 9 [ 32]: To: [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 10 [ 39]: User-Agent: SJphone/1.60.289a (SJ Labs) [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 11 [163]: Authorization: Digest username="101",realm="asterisk",nonce="391bc730",uri="sip:103@192.168.4.155:5060",response="cca73197b221b277ce19050724f0e89c",algorithm="MD5" [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 12 [ 0]: [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Body 0 [ 3]: v=0 [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Body 1 [ 45]: o=- 3385206453 3385206453 IN IP4 192.168.4.11 [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Body 2 [ 9]: s=SJphone [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Body 3 [ 21]: c=IN IP4 192.168.4.11 [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Body 4 [ 5]: t=0 0 [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Body 5 [ 18]: a=direction:active [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Body 6 [ 37]: m=audio 49152 RTP/AVP 3 97 98 8 0 101 [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Body 7 [ 19]: a=rtpmap:3 GSM/8000 [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Body 8 [ 21]: a=rtpmap:97 iLBC/8000 [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Body 9 [ 21]: a=rtpmap:98 iLBC/8000 [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Body 10 [ 17]: a=fmtp:98 mode=20 [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Body 11 [ 20]: a=rtpmap:8 PCMA/8000 [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Body 12 [ 20]: a=rtpmap:0 PCMU/8000 [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Body 13 [ 33]: a=rtpmap:101 telephone-event/8000 --- (12 headers 14 lines) --- [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:15375 handle_request: **** Received INVITE (5) - Command in SIP INVITE Sending to 192.168.4.11 : 5060 (NAT) [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:14001 handle_request_invite: Initializing initreq for method INVITE - callid 95DAB8BF-A247-424B-ABBC-818327C31118@192.168.4.11 Using INVITE request as basis request - 95DAB8BF-A247-424B-ABBC-818327C31118@192.168.4.11 No user '101' in SIP users list Found peer '101' for '101' from 192.168.4.11:5060 [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:2845 do_setnat: Setting NAT on RTP to On [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:2850 do_setnat: Setting NAT on VRTP to On [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:2855 do_setnat: Setting NAT on UDPTL to On Found RTP audio format 3 Found RTP audio format 97 Found RTP audio format 98 Found RTP audio format 8 Found RTP audio format 0 Found RTP audio format 101 [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:5291 process_sdp: Peer doesn't provide T.38 UDPTL Peer audio RTP is at port 192.168.4.11:49152 Found description format GSM for ID 3 Found description format iLBC for ID 97 Found description format iLBC for ID 98 Got unsupported a:fmtp in SDP offer Found description format PCMA for ID 8 Found description format PCMU for ID 0 Found description format telephone-event for ID 101 [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:5536 process_sdp: T38 state changed to 0 on channel Capabilities: us - 0x4 (ulaw), peer - audio=0x40e (gsm|ulaw|alaw|ilbc)/video=0x0 (nothing)/text=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.4.11:49152 [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:5627 process_sdp: We're settling with these formats: 0x4 (ulaw) [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:14082 handle_request_invite: Checking SIP call limits for device 101 [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:3308 update_call_counter: Updating call counter for incoming call [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:3378 update_call_counter: Call from peer '101' is 1 out of 2 [Apr 10 16:10:32] DEBUG[27900]: devicestate.c:444 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/101 Looking for 103 in from-sip (domain 192.168.4.155) [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4128 sip_new: *** Our native formats are 0x4 (ulaw) [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4129 sip_new: *** Joint capabilities are 0x4 (ulaw) [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4130 sip_new: *** Our capabilities are 0x4 (ulaw) [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4131 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4161 sip_new: This channel will not be able to handle video. [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:8494 build_route: build_route: Contact hop: list_route: hop: [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:14156 handle_request_invite: SIP/101-081edb90: New call is still down.... Trying... <--- Transmitting (NAT) to 192.168.4.11:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.4.11;branch=z9hG4bKc0a8040b0000001f461ba83500003b6d0000002f;received=192.168.4.11;rport=5060 From: "unknown";tag=3390393732197 To: Call-ID: 95DAB8BF-A247-424B-ABBC-818327C31118@192.168.4.11 CSeq: 2 INVITE User-Agent: Asterisk PBX SVN-trunk-r61184 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Apr 10 16:10:32] DEBUG[27900]: devicestate.c:444 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/101-081edb90 [Apr 10 16:10:32] DEBUG[27900]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 101 [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:16008 sip_devicestate: Checking device state for peer 101 [Apr 10 16:10:32] DEBUG[27900]: devicestate.c:428 do_state_change: Changing state for SIP/101 - state 2 (In use) [Apr 10 16:10:32] DEBUG[27900]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 101 [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:16008 sip_devicestate: Checking device state for peer 101 [Apr 10 16:10:32] DEBUG[27900]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 101 [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:16008 sip_devicestate: Checking device state for peer 101 [Apr 10 16:10:32] DEBUG[27900]: devicestate.c:428 do_state_change: Changing state for SIP/101 - state 2 (In use) [Apr 10 16:10:32] DEBUG[27900]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 101 [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:16008 sip_devicestate: Checking device state for peer 101 [Apr 10 16:10:32] DEBUG[27900]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 103 [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:16008 sip_devicestate: Checking device state for peer 103 [Apr 10 16:10:32] DEBUG[27900]: pbx.c:1566 pbx_substitute_variables_helper_full: Function result is 'NOT_INUSE' [Apr 10 16:10:32] DEBUG[27900]: pbx.c:1716 pbx_extension_helper: Launching 'NoOp' -- Executing [103@from-sip:1] NoOp("SIP/101-081edb90", "SIP/103 has state NOT_INUSE") in new stack [Apr 10 16:10:32] DEBUG[27900]: pbx.c:1566 pbx_substitute_variables_helper_full: Function result is '0' [Apr 10 16:10:32] DEBUG[27900]: app_queue.c:568 changethread: Device 'SIP/101' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Apr 10 16:10:32] DEBUG[27900]: app_queue.c:568 changethread: Device 'SIP/101' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Apr 10 16:10:32] DEBUG[27900]: pbx.c:1716 pbx_extension_helper: Launching 'NoOp' -- Executing [103@from-sip:2] NoOp("SIP/101-081edb90", "SIPPEER(103:curcalls) is 0") in new stack [Apr 10 16:10:32] DEBUG[27900]: pbx.c:1716 pbx_extension_helper: Launching 'Dial' -- Executing [103@from-sip:3] Dial("SIP/101-081edb90", "SIP/103") in new stack [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:16077 sip_request_call: Asked to create a SIP channel with formats: 0x4 (ulaw) [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4666 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:2900 create_addr_from_peer: Our T38 capability (3856) [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:2845 do_setnat: Setting NAT on RTP to On [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:2855 do_setnat: Setting NAT on UDPTL to On [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:1786 obproxy_get: OBPROXY: Not applying OBproxy to this call [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4128 sip_new: *** Our native formats are 0x4 (ulaw) [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4129 sip_new: *** Joint capabilities are 0x4 (ulaw) [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4130 sip_new: *** Our capabilities are 0x4 (ulaw) [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4131 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4133 sip_new: *** Our preferred formats from the incoming channel are 0x4 (ulaw) [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4161 sip_new: This channel will not be able to handle video. [Apr 10 16:10:32] DEBUG[27900]: channel.c:3284 ast_channel_inherit_variables: Not copying variable STACK-from-sip-103-3. [Apr 10 16:10:32] DEBUG[27900]: channel.c:3284 ast_channel_inherit_variables: Not copying variable STACK-from-sip-103-2. [Apr 10 16:10:32] DEBUG[27900]: channel.c:3284 ast_channel_inherit_variables: Not copying variable STACK-from-sip-103-1. [Apr 10 16:10:32] DEBUG[27900]: channel.c:3284 ast_channel_inherit_variables: Not copying variable SIPCALLID. [Apr 10 16:10:32] DEBUG[27900]: channel.c:3284 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [Apr 10 16:10:32] DEBUG[27900]: channel.c:3284 ast_channel_inherit_variables: Not copying variable SIPURI. [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:3125 sip_call: Outgoing Call for 103 [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:3308 update_call_counter: Updating call counter for outgoing call [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:3378 update_call_counter: Call to peer '103' is 1 out of 2 [Apr 10 16:10:32] DEBUG[27900]: devicestate.c:444 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/103 [Apr 10 16:10:32] DEBUG[27900]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 103 [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:16008 sip_devicestate: Checking device state for peer 103 [Apr 10 16:10:32] DEBUG[27900]: devicestate.c:428 do_state_change: Changing state for SIP/103 - state 6 (Ringing) [Apr 10 16:10:32] DEBUG[27900]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 103 [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:16008 sip_devicestate: Checking device state for peer 103 [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:3143 sip_call: Our T38 capability (3856), joint T38 capability (3856) [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:6680 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: False Text flag: False [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:6682 add_sdp: ** Our prefcodec: 0x4 (ulaw) Audio is at 192.168.4.155 port 10374 Adding codec 0x4 (ulaw) to SDP Adding non-codec 0x1 (telephone-event) to SDP [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:6843 add_sdp: -- Done with adding codecs to SDP [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:6903 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw) [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:1721 initialize_initreq: Initializing initreq for method INVITE - callid 16221df46b0c1cc779b6602135db084b@192.168.4.155 [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 0 [ 55]: INVITE sip:103@192.168.4.109:2051;line=0cl0sm4g SIP/2.0 [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 1 [ 64]: Via: SIP/2.0/UDP 192.168.4.155:5060;branch=z9hG4bK1388cc2c;rport [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 2 [ 16]: Max-Forwards: 70 [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 3 [ 54]: From: "unknown" ;tag=as633c1492 [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 4 [ 46]: To: [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 5 [ 32]: Contact: [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 6 [ 55]: Call-ID: 16221df46b0c1cc779b6602135db084b@192.168.4.155 [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 7 [ 16]: CSeq: 102 INVITE [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 8 [ 41]: User-Agent: Asterisk PBX SVN-trunk-r61184 [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 9 [ 35]: Date: Tue, 10 Apr 2007 14:10:32 GMT [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 10 [ 66]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 11 [ 19]: Supported: replaces [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 12 [ 29]: Content-Type: application/sdp [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 13 [ 19]: Content-Length: 252 [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 14 [ 0]: [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Body 0 [ 3]: v=0 [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Body 1 [ 49]: o=root 1035984372 1035984372 IN IP4 192.168.4.155 [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Body 2 [ 9]: s=session [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Body 3 [ 22]: c=IN IP4 192.168.4.155 [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Body 4 [ 5]: t=0 0 [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Body 5 [ 27]: m=audio 10374 RTP/AVP 0 101 [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Body 6 [ 20]: a=rtpmap:0 PCMU/8000 [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Body 7 [ 33]: a=rtpmap:101 telephone-event/8000 [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Body 8 [ 15]: a=fmtp:101 0-16 [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Body 9 [ 25]: a=silenceSupp:off - - - - [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Body 10 [ 10]: a=ptime:20 [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Body 11 [ 10]: a=sendrecv Reliably Transmitting (NAT) to 192.168.4.109:2051: INVITE sip:103@192.168.4.109:2051;line=0cl0sm4g SIP/2.0 Via: SIP/2.0/UDP 192.168.4.155:5060;branch=z9hG4bK1388cc2c;rport Max-Forwards: 70 From: "unknown" ;tag=as633c1492 To: Contact: Call-ID: 16221df46b0c1cc779b6602135db084b@192.168.4.155 CSeq: 102 INVITE User-Agent: Asterisk PBX SVN-trunk-r61184 Date: Tue, 10 Apr 2007 14:10:32 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Type: application/sdp Content-Length: 252 v=0 o=root 1035984372 1035984372 IN IP4 192.168.4.155 s=session c=IN IP4 192.168.4.155 t=0 0 m=audio 10374 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 --- [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:2118 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #29 -- Called 103 [Apr 10 16:10:32] DEBUG[27900]: app_queue.c:568 changethread: Device 'SIP/103' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. <--- SIP read from 192.168.4.109:2051 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 192.168.4.155:5060;branch=z9hG4bK1388cc2c;rport=5060 From: "unknown" ;tag=as633c1492 To: ;tag=v3o4bfn60t Call-ID: 16221df46b0c1cc779b6602135db084b@192.168.4.155 CSeq: 102 INVITE Contact: ;flow-id=1 Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO Allow-Events: talk, hold, refer Content-Length: 0 <-------------> [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 0 [ 19]: SIP/2.0 180 Ringing [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 1 [ 69]: Via: SIP/2.0/UDP 192.168.4.155:5060;branch=z9hG4bK1388cc2c;rport=5060 [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 2 [ 54]: From: "unknown" ;tag=as633c1492 [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 3 [ 61]: To: ;tag=v3o4bfn60t [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 4 [ 55]: Call-ID: 16221df46b0c1cc779b6602135db084b@192.168.4.155 [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 5 [ 16]: CSeq: 102 INVITE [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 6 [ 61]: Contact: ;flow-id=1 [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 7 [ 88]: Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 8 [ 31]: Allow-Events: talk, hold, refer [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 9 [ 17]: Content-Length: 0 --- (10 headers 0 lines) --- [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:2271 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #29 - INVITE (got response) [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:2280 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '16221df46b0c1cc779b6602135db084b@192.168.4.155' Request 102: Found [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:12310 handle_response_invite: SIP response 180 to standard invite [Apr 10 16:10:32] DEBUG[27900]: devicestate.c:444 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/103-08202018 -- SIP/103-08202018 is ringing <--- Transmitting (NAT) to 192.168.4.11:5060 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 192.168.4.11;branch=z9hG4bKc0a8040b0000001f461ba83500003b6d0000002f;received=192.168.4.11;rport=5060 From: "unknown";tag=3390393732197 To: ;tag=as6a034200 Call-ID: 95DAB8BF-A247-424B-ABBC-818327C31118@192.168.4.11 CSeq: 2 INVITE User-Agent: Asterisk PBX SVN-trunk-r61184 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Apr 10 16:10:32] DEBUG[27900]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 103 [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:16008 sip_devicestate: Checking device state for peer 103 [Apr 10 16:10:32] DEBUG[27900]: devicestate.c:428 do_state_change: Changing state for SIP/103 - state 6 (Ringing) [Apr 10 16:10:32] DEBUG[27900]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 103 [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:16008 sip_devicestate: Checking device state for peer 103 [Apr 10 16:10:32] DEBUG[27900]: app_queue.c:568 changethread: Device 'SIP/103' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. <--- SIP read from 192.168.4.109:2051 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 192.168.4.155:5060;branch=z9hG4bK1388cc2c;rport=5060 From: "unknown" ;tag=as633c1492 To: ;tag=v3o4bfn60t Call-ID: 16221df46b0c1cc779b6602135db084b@192.168.4.155 CSeq: 102 INVITE Contact: ;flow-id=1 Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO Allow-Events: talk, hold, refer Content-Length: 0 <-------------> [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 0 [ 19]: SIP/2.0 180 Ringing [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 1 [ 69]: Via: SIP/2.0/UDP 192.168.4.155:5060;branch=z9hG4bK1388cc2c;rport=5060 [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 2 [ 54]: From: "unknown" ;tag=as633c1492 [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 3 [ 61]: To: ;tag=v3o4bfn60t [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 4 [ 55]: Call-ID: 16221df46b0c1cc779b6602135db084b@192.168.4.155 [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 5 [ 16]: CSeq: 102 INVITE [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 6 [ 61]: Contact: ;flow-id=1 [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 7 [ 88]: Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 8 [ 31]: Allow-Events: talk, hold, refer [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 9 [ 17]: Content-Length: 0 --- (10 headers 0 lines) --- [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:2280 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '16221df46b0c1cc779b6602135db084b@192.168.4.155' Request 102: Found [Apr 10 16:10:32] DEBUG[27900]: chan_sip.c:12310 handle_response_invite: SIP response 180 to standard invite -- SIP/103-08202018 is ringing <--- SIP read from 192.168.4.109:2051 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 192.168.4.155:5060;branch=z9hG4bK1388cc2c;rport=5060 From: "unknown" ;tag=as633c1492 To: ;tag=v3o4bfn60t Call-ID: 16221df46b0c1cc779b6602135db084b@192.168.4.155 CSeq: 102 INVITE Contact: ;flow-id=1 Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO Allow-Events: talk, hold, refer Content-Length: 0 <-------------> [Apr 10 16:10:33] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 0 [ 19]: SIP/2.0 180 Ringing [Apr 10 16:10:33] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 1 [ 69]: Via: SIP/2.0/UDP 192.168.4.155:5060;branch=z9hG4bK1388cc2c;rport=5060 [Apr 10 16:10:33] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 2 [ 54]: From: "unknown" ;tag=as633c1492 [Apr 10 16:10:33] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 3 [ 61]: To: ;tag=v3o4bfn60t [Apr 10 16:10:33] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 4 [ 55]: Call-ID: 16221df46b0c1cc779b6602135db084b@192.168.4.155 [Apr 10 16:10:33] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 5 [ 16]: CSeq: 102 INVITE [Apr 10 16:10:33] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 6 [ 61]: Contact: ;flow-id=1 [Apr 10 16:10:33] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 7 [ 88]: Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO [Apr 10 16:10:33] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 8 [ 31]: Allow-Events: talk, hold, refer [Apr 10 16:10:33] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 9 [ 17]: Content-Length: 0 --- (10 headers 0 lines) --- [Apr 10 16:10:33] DEBUG[27900]: chan_sip.c:2280 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '16221df46b0c1cc779b6602135db084b@192.168.4.155' Request 102: Found [Apr 10 16:10:33] DEBUG[27900]: chan_sip.c:12310 handle_response_invite: SIP response 180 to standard invite -- SIP/103-08202018 is ringing [Apr 10 16:10:35] DEBUG[27900]: rtp.c:940 ast_rtcp_read: RTCP NAT: Got RTCP from other end. Now sending to address 192.168.4.109:14035 [Apr 10 16:10:35] DEBUG[27900]: rtp.c:945 ast_rtcp_read: Got RTCP report of 52 bytes <--- SIP read from 192.168.4.109:2051 ---> SIP/2.0 200 Ok Via: SIP/2.0/UDP 192.168.4.155:5060;branch=z9hG4bK1388cc2c;rport=5060 From: "unknown" ;tag=as633c1492 To: ;tag=v3o4bfn60t Call-ID: 16221df46b0c1cc779b6602135db084b@192.168.4.155 CSeq: 102 INVITE Contact: ;flow-id=1 User-Agent: snom360/6.5.8 Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO Allow-Events: talk, hold, refer Supported: timer, 100rel, replaces, callerid Content-Type: application/sdp Content-Length: 329 v=0 o=root 1057625675 1057625676 IN IP4 192.168.4.109 s=call c=IN IP4 192.168.4.109 t=0 0 m=audio 14034 RTP/AVP 0 101 a=crypto:1 AES_CM_128_HMAC_SHA1_32 inline:rj0cWBN9iiuN2z/KFrLGXbczPqOB+DiiWN7hhmp5 a=rtpmap:0 pcmu/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=encryption:optional a=sendrecv <-------------> [Apr 10 16:10:35] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 0 [ 14]: SIP/2.0 200 Ok [Apr 10 16:10:35] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 1 [ 69]: Via: SIP/2.0/UDP 192.168.4.155:5060;branch=z9hG4bK1388cc2c;rport=5060 [Apr 10 16:10:35] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 2 [ 54]: From: "unknown" ;tag=as633c1492 [Apr 10 16:10:35] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 3 [ 61]: To: ;tag=v3o4bfn60t [Apr 10 16:10:35] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 4 [ 55]: Call-ID: 16221df46b0c1cc779b6602135db084b@192.168.4.155 [Apr 10 16:10:35] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 5 [ 16]: CSeq: 102 INVITE [Apr 10 16:10:35] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 6 [ 61]: Contact: ;flow-id=1 [Apr 10 16:10:35] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 7 [ 25]: User-Agent: snom360/6.5.8 [Apr 10 16:10:35] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 8 [ 88]: Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO [Apr 10 16:10:35] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 9 [ 31]: Allow-Events: talk, hold, refer [Apr 10 16:10:35] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 10 [ 44]: Supported: timer, 100rel, replaces, callerid [Apr 10 16:10:35] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 11 [ 29]: Content-Type: application/sdp [Apr 10 16:10:35] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 12 [ 19]: Content-Length: 329 [Apr 10 16:10:35] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 13 [ 0]: [Apr 10 16:10:35] DEBUG[27900]: chan_sip.c:4944 parse_request: Body 0 [ 3]: v=0 [Apr 10 16:10:35] DEBUG[27900]: chan_sip.c:4944 parse_request: Body 1 [ 49]: o=root 1057625675 1057625676 IN IP4 192.168.4.109 [Apr 10 16:10:35] DEBUG[27900]: chan_sip.c:4944 parse_request: Body 2 [ 6]: s=call [Apr 10 16:10:35] DEBUG[27900]: chan_sip.c:4944 parse_request: Body 3 [ 22]: c=IN IP4 192.168.4.109 [Apr 10 16:10:35] DEBUG[27900]: chan_sip.c:4944 parse_request: Body 4 [ 5]: t=0 0 [Apr 10 16:10:35] DEBUG[27900]: chan_sip.c:4944 parse_request: Body 5 [ 27]: m=audio 14034 RTP/AVP 0 101 [Apr 10 16:10:35] DEBUG[27900]: chan_sip.c:4944 parse_request: Body 6 [ 82]: a=crypto:1 AES_CM_128_HMAC_SHA1_32 inline:rj0cWBN9iiuN2z/KFrLGXbczPqOB+DiiWN7hhmp5 [Apr 10 16:10:35] DEBUG[27900]: chan_sip.c:4944 parse_request: Body 7 [ 20]: a=rtpmap:0 pcmu/8000 [Apr 10 16:10:35] DEBUG[27900]: chan_sip.c:4944 parse_request: Body 8 [ 33]: a=rtpmap:101 telephone-event/8000 [Apr 10 16:10:35] DEBUG[27900]: chan_sip.c:4944 parse_request: Body 9 [ 15]: a=fmtp:101 0-16 [Apr 10 16:10:35] DEBUG[27900]: chan_sip.c:4944 parse_request: Body 10 [ 10]: a=ptime:20 [Apr 10 16:10:35] DEBUG[27900]: chan_sip.c:4944 parse_request: Body 11 [ 21]: a=encryption:optional --- (13 headers 12 lines) --- [Apr 10 16:10:35] DEBUG[27900]: chan_sip.c:2221 __sip_ack: Acked pending invite 102 [Apr 10 16:10:35] DEBUG[27900]: chan_sip.c:2237 __sip_ack: Stopping retransmission on '16221df46b0c1cc779b6602135db084b@192.168.4.155' of Request 102: Match Found [Apr 10 16:10:35] DEBUG[27900]: chan_sip.c:12310 handle_response_invite: SIP response 200 to standard invite Found RTP audio format 0 Found RTP audio format 101 [Apr 10 16:10:35] DEBUG[27900]: chan_sip.c:5291 process_sdp: Peer doesn't provide T.38 UDPTL Peer audio RTP is at port 192.168.4.109:14034 Got unsupported a:crypto in SDP offer Found description format pcmu for ID 0 Found description format telephone-event for ID 101 Got unsupported a:fmtp in SDP offer [Apr 10 16:10:35] DEBUG[27900]: chan_sip.c:5536 process_sdp: T38 state changed to 0 on channel SIP/103-08202018 Capabilities: us - 0x4 (ulaw), peer - audio=0x4 (ulaw)/video=0x0 (nothing)/text=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.4.109:14034 [Apr 10 16:10:35] DEBUG[27900]: chan_sip.c:5627 process_sdp: We're settling with these formats: 0x4 (ulaw) [Apr 10 16:10:35] DEBUG[27900]: chan_sip.c:5634 process_sdp: We have an owner, now see if we need to change this call [Apr 10 16:10:35] DEBUG[27900]: chan_sip.c:3308 update_call_counter: Updating call counter for outgoing call [Apr 10 16:10:35] DEBUG[27900]: devicestate.c:444 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/103 [Apr 10 16:10:35] DEBUG[27900]: chan_sip.c:8494 build_route: build_route: Contact hop: ;flow-id=1 list_route: hop: [Apr 10 16:10:35] DEBUG[27900]: chan_sip.c:6055 reqprep: Strict routing enforced for session 16221df46b0c1cc779b6602135db084b@192.168.4.155 set_destination: Parsing for address/port to send to set_destination: set destination to 192.168.4.109, port 2051 Transmitting (NAT) to 192.168.4.109:2051: ACK sip:103@192.168.4.109:2051;line=0cl0sm4g SIP/2.0 Via: SIP/2.0/UDP 192.168.4.155:5060;branch=z9hG4bK6bf5d458;rport Max-Forwards: 70 From: "unknown" ;tag=as633c1492 To: ;tag=v3o4bfn60t Contact: Call-ID: 16221df46b0c1cc779b6602135db084b@192.168.4.155 CSeq: 102 ACK User-Agent: Asterisk PBX SVN-trunk-r61184 Content-Length: 0 --- [Apr 10 16:10:35] DEBUG[27900]: devicestate.c:444 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/103-08202018 -- SIP/103-08202018 answered SIP/101-081edb90 [Apr 10 16:10:35] DEBUG[27900]: devicestate.c:444 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/101-081edb90 [Apr 10 16:10:35] DEBUG[27900]: chan_sip.c:3764 sip_answer: SIP answering channel: SIP/101-081edb90 [Apr 10 16:10:35] DEBUG[27900]: chan_sip.c:6958 transmit_response_with_sdp: Setting framing from config on incoming call [Apr 10 16:10:35] DEBUG[27900]: chan_sip.c:6680 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True Text flag: True [Apr 10 16:10:35] DEBUG[27900]: chan_sip.c:6682 add_sdp: ** Our prefcodec: 0x0 (nothing) Audio is at 192.168.4.155 port 12206 Adding codec 0x4 (ulaw) to SDP Adding non-codec 0x1 (telephone-event) to SDP [Apr 10 16:10:35] DEBUG[27900]: chan_sip.c:6843 add_sdp: -- Done with adding codecs to SDP [Apr 10 16:10:35] DEBUG[27900]: chan_sip.c:6903 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw) <--- Reliably Transmitting (NAT) to 192.168.4.11:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.4.11;branch=z9hG4bKc0a8040b0000001f461ba83500003b6d0000002f;received=192.168.4.11;rport=5060 From: "unknown";tag=3390393732197 To: ;tag=as6a034200 Call-ID: 95DAB8BF-A247-424B-ABBC-818327C31118@192.168.4.11 CSeq: 2 INVITE User-Agent: Asterisk PBX SVN-trunk-r61184 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 252 v=0 o=root 1820935938 1820935938 IN IP4 192.168.4.155 s=session c=IN IP4 192.168.4.155 t=0 0 m=audio 12206 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 <------------> [Apr 10 16:10:35] DEBUG[27900]: chan_sip.c:2118 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #31 [Apr 10 16:10:35] DEBUG[27900]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 103 [Apr 10 16:10:35] DEBUG[27900]: chan_sip.c:16008 sip_devicestate: Checking device state for peer 103 [Apr 10 16:10:35] DEBUG[27900]: devicestate.c:428 do_state_change: Changing state for SIP/103 - state 2 (In use) [Apr 10 16:10:35] DEBUG[27900]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 103 [Apr 10 16:10:35] DEBUG[27900]: chan_sip.c:16008 sip_devicestate: Checking device state for peer 103 [Apr 10 16:10:35] DEBUG[27900]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 103 [Apr 10 16:10:35] DEBUG[27900]: chan_sip.c:16008 sip_devicestate: Checking device state for peer 103 [Apr 10 16:10:35] DEBUG[27900]: devicestate.c:428 do_state_change: Changing state for SIP/103 - state 2 (In use) [Apr 10 16:10:35] DEBUG[27900]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 103 [Apr 10 16:10:35] DEBUG[27900]: chan_sip.c:16008 sip_devicestate: Checking device state for peer 103 [Apr 10 16:10:35] DEBUG[27900]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 101 [Apr 10 16:10:35] DEBUG[27900]: chan_sip.c:16008 sip_devicestate: Checking device state for peer 101 [Apr 10 16:10:35] DEBUG[27900]: devicestate.c:428 do_state_change: Changing state for SIP/101 - state 2 (In use) [Apr 10 16:10:35] DEBUG[27900]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 101 [Apr 10 16:10:35] DEBUG[27900]: chan_sip.c:16008 sip_devicestate: Checking device state for peer 101 [Apr 10 16:10:35] DEBUG[27900]: app_queue.c:568 changethread: Device 'SIP/103' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Apr 10 16:10:35] DEBUG[27900]: app_queue.c:568 changethread: Device 'SIP/103' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Apr 10 16:10:35] DEBUG[27900]: chan_sip.c:2014 retrans_pkt: SIP TIMER: Rescheduling retransmission #31 (1) SIP/2.0 - 1 [Apr 10 16:10:35] DEBUG[27900]: chan_sip.c:2028 retrans_pkt: ** SIP timers: Rescheduling retransmission 2 to 4 ms (t1 2 ms (Retrans id #31)) Retransmitting #1 (NAT) to 192.168.4.11:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.4.11;branch=z9hG4bKc0a8040b0000001f461ba83500003b6d0000002f;received=192.168.4.11;rport=5060 From: "unknown";tag=3390393732197 To: ;tag=as6a034200 Call-ID: 95DAB8BF-A247-424B-ABBC-818327C31118@192.168.4.11 CSeq: 2 INVITE User-Agent: Asterisk PBX SVN-trunk-r61184 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 252 v=0 o=root 1820935938 1820935938 IN IP4 192.168.4.155 s=session c=IN IP4 192.168.4.155 t=0 0 m=audio 12206 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 --- [Apr 10 16:10:35] DEBUG[27900]: sched.c:205 sched_settime: Request to schedule in the past?!?! [Apr 10 16:10:35] DEBUG[27900]: chan_sip.c:2014 retrans_pkt: SIP TIMER: Rescheduling retransmission #31 (2) SIP/2.0 - 1 [Apr 10 16:10:35] DEBUG[27900]: chan_sip.c:2028 retrans_pkt: ** SIP timers: Rescheduling retransmission 3 to 8 ms (t1 2 ms (Retrans id #31)) Retransmitting #2 (NAT) to 192.168.4.11:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.4.11;branch=z9hG4bKc0a8040b0000001f461ba83500003b6d0000002f;received=192.168.4.11;rport=5060 From: "unknown";tag=3390393732197 To: ;tag=as6a034200 Call-ID: 95DAB8BF-A247-424B-ABBC-818327C31118@192.168.4.11 CSeq: 2 INVITE User-Agent: Asterisk PBX SVN-trunk-r61184 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 252 v=0 o=root 1820935938 1820935938 IN IP4 192.168.4.155 s=session c=IN IP4 192.168.4.155 t=0 0 m=audio 12206 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 --- [Apr 10 16:10:35] DEBUG[27900]: app_queue.c:568 changethread: Device 'SIP/101' changed to state '2' (In use) but we don't care because they're not a member of any queue. <--- SIP read from 192.168.4.11:5060 ---> ACK sip:103@192.168.4.155 SIP/2.0 Via: SIP/2.0/UDP 192.168.4.11;rport;branch=z9hG4bKc0a8040b0000001f461ba83800006b1700000033 Content-Length: 0 Call-ID: 95DAB8BF-A247-424B-ABBC-818327C31118@192.168.4.11 CSeq: 2 ACK From: "unknown";tag=3390393732197 Max-Forwards: 70 To: ;tag=as6a034200 User-Agent: SJphone/1.60.289a (SJ Labs) <-------------> [Apr 10 16:10:35] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 0 [ 33]: ACK sip:103@192.168.4.155 SIP/2.0 [Apr 10 16:10:35] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 1 [ 90]: Via: SIP/2.0/UDP 192.168.4.11;rport;branch=z9hG4bKc0a8040b0000001f461ba83800006b1700000033 [Apr 10 16:10:35] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 2 [ 17]: Content-Length: 0 [Apr 10 16:10:35] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 3 [ 58]: Call-ID: 95DAB8BF-A247-424B-ABBC-818327C31118@192.168.4.11 [Apr 10 16:10:35] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 4 [ 11]: CSeq: 2 ACK [Apr 10 16:10:35] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 5 [ 61]: From: "unknown";tag=3390393732197 [Apr 10 16:10:35] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 6 [ 16]: Max-Forwards: 70 [Apr 10 16:10:35] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 7 [ 47]: To: ;tag=as6a034200 [Apr 10 16:10:35] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 8 [ 39]: User-Agent: SJphone/1.60.289a (SJ Labs) --- (9 headers 0 lines) --- [Apr 10 16:10:35] DEBUG[27900]: chan_sip.c:15375 handle_request: **** Received ACK (6) - Command in SIP ACK [Apr 10 16:10:35] DEBUG[27900]: chan_sip.c:2226 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #31 [Apr 10 16:10:35] DEBUG[27900]: chan_sip.c:2237 __sip_ack: Stopping retransmission on '95DAB8BF-A247-424B-ABBC-818327C31118@192.168.4.11' of Response 2: Match Found <--- SIP read from 192.168.4.11:5060 ---> ACK sip:103@192.168.4.155 SIP/2.0 Via: SIP/2.0/UDP 192.168.4.11;rport;branch=z9hG4bKc0a8040b0000001f461ba83800007d5600000036 Content-Length: 0 Call-ID: 95DAB8BF-A247-424B-ABBC-818327C31118@192.168.4.11 CSeq: 2 ACK From: "unknown";tag=3390393732197 Max-Forwards: 70 To: ;tag=as6a034200 User-Agent: SJphone/1.60.289a (SJ Labs) <-------------> [Apr 10 16:10:35] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 0 [ 33]: ACK sip:103@192.168.4.155 SIP/2.0 [Apr 10 16:10:35] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 1 [ 90]: Via: SIP/2.0/UDP 192.168.4.11;rport;branch=z9hG4bKc0a8040b0000001f461ba83800007d5600000036 [Apr 10 16:10:35] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 2 [ 17]: Content-Length: 0 [Apr 10 16:10:35] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 3 [ 58]: Call-ID: 95DAB8BF-A247-424B-ABBC-818327C31118@192.168.4.11 [Apr 10 16:10:35] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 4 [ 11]: CSeq: 2 ACK [Apr 10 16:10:35] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 5 [ 61]: From: "unknown";tag=3390393732197 [Apr 10 16:10:35] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 6 [ 16]: Max-Forwards: 70 [Apr 10 16:10:35] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 7 [ 47]: To: ;tag=as6a034200 [Apr 10 16:10:35] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 8 [ 39]: User-Agent: SJphone/1.60.289a (SJ Labs) --- (9 headers 0 lines) --- [Apr 10 16:10:35] DEBUG[27900]: chan_sip.c:15375 handle_request: **** Received ACK (6) - Command in SIP ACK <--- SIP read from 192.168.4.11:5060 ---> ACK sip:103@192.168.4.155 SIP/2.0 Via: SIP/2.0/UDP 192.168.4.11;rport;branch=z9hG4bKc0a8040b0000001f461ba83800002e5300000037 Content-Length: 0 Call-ID: 95DAB8BF-A247-424B-ABBC-818327C31118@192.168.4.11 CSeq: 2 ACK From: "unknown";tag=3390393732197 Max-Forwards: 70 To: ;tag=as6a034200 User-Agent: SJphone/1.60.289a (SJ Labs) <-------------> [Apr 10 16:10:35] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 0 [ 33]: ACK sip:103@192.168.4.155 SIP/2.0 [Apr 10 16:10:35] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 1 [ 90]: Via: SIP/2.0/UDP 192.168.4.11;rport;branch=z9hG4bKc0a8040b0000001f461ba83800002e5300000037 [Apr 10 16:10:35] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 2 [ 17]: Content-Length: 0 [Apr 10 16:10:35] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 3 [ 58]: Call-ID: 95DAB8BF-A247-424B-ABBC-818327C31118@192.168.4.11 [Apr 10 16:10:35] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 4 [ 11]: CSeq: 2 ACK [Apr 10 16:10:35] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 5 [ 61]: From: "unknown";tag=3390393732197 [Apr 10 16:10:35] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 6 [ 16]: Max-Forwards: 70 [Apr 10 16:10:35] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 7 [ 47]: To: ;tag=as6a034200 [Apr 10 16:10:35] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 8 [ 39]: User-Agent: SJphone/1.60.289a (SJ Labs) --- (9 headers 0 lines) --- [Apr 10 16:10:35] DEBUG[27900]: chan_sip.c:15375 handle_request: **** Received ACK (6) - Command in SIP ACK [Apr 10 16:10:35] DEBUG[27900]: chan_sip.c:2164 __sip_autodestruct: Auto destroying SIP dialog '67A5E3DF-487C-4AD8-80E0-76048020090D@192.168.4.11' [Apr 10 16:10:35] DEBUG[27900]: chan_sip.c:3404 sip_destroy: Destroying SIP dialog 67A5E3DF-487C-4AD8-80E0-76048020090D@192.168.4.11 Really destroying SIP dialog '67A5E3DF-487C-4AD8-80E0-76048020090D@192.168.4.11' Method: OPTIONS -- Packet2Packet bridging SIP/101-081edb90 and SIP/103-08202018 [Apr 10 16:10:36] DEBUG[27900]: chan_sip.c:2164 __sip_autodestruct: Auto destroying SIP dialog 'BEEF3415-1201-4FBC-9CCD-F5998F25B5B4@192.168.4.11' [Apr 10 16:10:36] DEBUG[27900]: chan_sip.c:3404 sip_destroy: Destroying SIP dialog BEEF3415-1201-4FBC-9CCD-F5998F25B5B4@192.168.4.11 Really destroying SIP dialog 'BEEF3415-1201-4FBC-9CCD-F5998F25B5B4@192.168.4.11' Method: REGISTER <--- SIP read from 192.168.4.11:5060 ---> INVITE sip:103@192.168.4.155 SIP/2.0 Via: SIP/2.0/UDP 192.168.4.11;rport;branch=z9hG4bKc0a8040b0000001f461ba83b000041d900000038 Content-Length: 214 Contact: Call-ID: 95DAB8BF-A247-424B-ABBC-818327C31118@192.168.4.11 Content-Type: application/sdp CSeq: 3 INVITE From: "unknown";tag=3390393732197 Max-Forwards: 70 To: ;tag=as6a034200 User-Agent: SJphone/1.60.289a (SJ Labs) v=0 o=- 3385206453 3385206454 IN IP4 192.168.4.11 s=SJphone c=IN IP4 0.0.0.0 t=0 0 a=direction:active m=audio 49152 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-11,16 <-------------> [Apr 10 16:10:38] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 0 [ 36]: INVITE sip:103@192.168.4.155 SIP/2.0 [Apr 10 16:10:38] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 1 [ 90]: Via: SIP/2.0/UDP 192.168.4.11;rport;branch=z9hG4bKc0a8040b0000001f461ba83b000041d900000038 [Apr 10 16:10:38] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 2 [ 19]: Content-Length: 214 [Apr 10 16:10:38] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 3 [ 36]: Contact: [Apr 10 16:10:38] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 4 [ 58]: Call-ID: 95DAB8BF-A247-424B-ABBC-818327C31118@192.168.4.11 [Apr 10 16:10:38] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 5 [ 29]: Content-Type: application/sdp [Apr 10 16:10:38] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 6 [ 14]: CSeq: 3 INVITE [Apr 10 16:10:38] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 7 [ 61]: From: "unknown";tag=3390393732197 [Apr 10 16:10:38] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 8 [ 16]: Max-Forwards: 70 [Apr 10 16:10:38] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 9 [ 47]: To: ;tag=as6a034200 [Apr 10 16:10:38] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 10 [ 39]: User-Agent: SJphone/1.60.289a (SJ Labs) [Apr 10 16:10:38] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 11 [ 0]: [Apr 10 16:10:38] DEBUG[27900]: chan_sip.c:4944 parse_request: Body 0 [ 3]: v=0 [Apr 10 16:10:38] DEBUG[27900]: chan_sip.c:4944 parse_request: Body 1 [ 45]: o=- 3385206453 3385206454 IN IP4 192.168.4.11 [Apr 10 16:10:38] DEBUG[27900]: chan_sip.c:4944 parse_request: Body 2 [ 9]: s=SJphone [Apr 10 16:10:38] DEBUG[27900]: chan_sip.c:4944 parse_request: Body 3 [ 16]: c=IN IP4 0.0.0.0 [Apr 10 16:10:38] DEBUG[27900]: chan_sip.c:4944 parse_request: Body 4 [ 5]: t=0 0 [Apr 10 16:10:38] DEBUG[27900]: chan_sip.c:4944 parse_request: Body 5 [ 18]: a=direction:active [Apr 10 16:10:38] DEBUG[27900]: chan_sip.c:4944 parse_request: Body 6 [ 27]: m=audio 49152 RTP/AVP 0 101 [Apr 10 16:10:38] DEBUG[27900]: chan_sip.c:4944 parse_request: Body 7 [ 20]: a=rtpmap:0 PCMU/8000 [Apr 10 16:10:38] DEBUG[27900]: chan_sip.c:4944 parse_request: Body 8 [ 33]: a=rtpmap:101 telephone-event/8000 --- (11 headers 9 lines) --- [Apr 10 16:10:38] DEBUG[27900]: chan_sip.c:15375 handle_request: **** Received INVITE (5) - Command in SIP INVITE Sending to 192.168.4.11 : 5060 (NAT) [Apr 10 16:10:38] DEBUG[27900]: chan_sip.c:14001 handle_request_invite: Initializing initreq for method INVITE - callid 95DAB8BF-A247-424B-ABBC-818327C31118@192.168.4.11 Found RTP audio format 0 Found RTP audio format 101 [Apr 10 16:10:38] DEBUG[27900]: chan_sip.c:5291 process_sdp: Peer doesn't provide T.38 UDPTL Peer audio RTP is at port 0.0.0.0:49152 Found description format PCMU for ID 0 Found description format telephone-event for ID 101 [Apr 10 16:10:38] DEBUG[27900]: chan_sip.c:5536 process_sdp: T38 state changed to 0 on channel SIP/101-081edb90 Capabilities: us - 0x4 (ulaw), peer - audio=0x4 (ulaw)/video=0x0 (nothing)/text=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 0.0.0.0:49152 [Apr 10 16:10:38] DEBUG[27900]: chan_sip.c:5627 process_sdp: We're settling with these formats: 0x4 (ulaw) [Apr 10 16:10:38] DEBUG[27900]: chan_sip.c:5634 process_sdp: We have an owner, now see if we need to change this call [Apr 10 16:10:38] DEBUG[27900]: devicestate.c:444 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/101 [Apr 10 16:10:38] DEBUG[27900]: chan_sip.c:14134 handle_request_invite: Got a SIP re-invite for call 95DAB8BF-A247-424B-ABBC-818327C31118@192.168.4.11 [Apr 10 16:10:38] DEBUG[27900]: chan_sip.c:14229 handle_request_invite: SIP/101-081edb90: This call is UP.... [Apr 10 16:10:38] DEBUG[27900]: chan_sip.c:6958 transmit_response_with_sdp: Setting framing from config on incoming call [Apr 10 16:10:38] DEBUG[27900]: chan_sip.c:6680 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True Text flag: True [Apr 10 16:10:38] DEBUG[27900]: chan_sip.c:6682 add_sdp: ** Our prefcodec: 0x0 (nothing) Audio is at 192.168.4.155 port 12206 Adding codec 0x4 (ulaw) to SDP Adding non-codec 0x1 (telephone-event) to SDP [Apr 10 16:10:38] DEBUG[27900]: chan_sip.c:6843 add_sdp: -- Done with adding codecs to SDP [Apr 10 16:10:38] DEBUG[27900]: chan_sip.c:6903 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw) <--- Reliably Transmitting (NAT) to 192.168.4.11:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.4.11;branch=z9hG4bKc0a8040b0000001f461ba83b000041d900000038;received=192.168.4.11;rport=5060 From: "unknown";tag=3390393732197 To: ;tag=as6a034200 Call-ID: 95DAB8BF-A247-424B-ABBC-818327C31118@192.168.4.11 CSeq: 3 INVITE User-Agent: Asterisk PBX SVN-trunk-r61184 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 252 v=0 o=root 1820935938 1820935939 IN IP4 192.168.4.155 s=session c=IN IP4 192.168.4.155 t=0 0 m=audio 12206 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 <------------> [Apr 10 16:10:38] DEBUG[27900]: chan_sip.c:2118 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #32 -- Started music on hold, class 'default', on SIP/103-08202018 [Apr 10 16:10:38] DEBUG[27900]: channel.c:1964 ast_settimeout: Scheduling timer at 160 sample intervals [Apr 10 16:10:38] DEBUG[27900]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 101 [Apr 10 16:10:38] DEBUG[27900]: chan_sip.c:16008 sip_devicestate: Checking device state for peer 101 [Apr 10 16:10:38] DEBUG[27900]: devicestate.c:428 do_state_change: Changing state for SIP/101 - state 8 (On Hold) [Apr 10 16:10:38] DEBUG[27900]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 101 [Apr 10 16:10:38] DEBUG[27900]: chan_sip.c:2014 retrans_pkt: SIP TIMER: Rescheduling retransmission #32 (1) SIP/2.0 - 1 [Apr 10 16:10:38] DEBUG[27900]: chan_sip.c:2028 retrans_pkt: ** SIP timers: Rescheduling retransmission 2 to 4 ms (t1 2 ms (Retrans id #32)) Retransmitting #1 (NAT) to 192.168.4.11:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.4.11;branch=z9hG4bKc0a8040b0000001f461ba83b000041d900000038;received=192.168.4.11;rport=5060 From: "unknown";tag=3390393732197 To: ;tag=as6a034200 Call-ID: 95DAB8BF-A247-424B-ABBC-818327C31118@192.168.4.11 CSeq: 3 INVITE User-Agent: Asterisk PBX SVN-trunk-r61184 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 252 v=0 o=root 1820935938 1820935939 IN IP4 192.168.4.155 s=session c=IN IP4 192.168.4.155 t=0 0 m=audio 12206 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 --- [Apr 10 16:10:38] DEBUG[27900]: chan_sip.c:16008 sip_devicestate: Checking device state for peer 101 <--- SIP read from 192.168.4.11:5060 ---> ACK sip:103@192.168.4.155 SIP/2.0 Via: SIP/2.0/UDP 192.168.4.11;rport;branch=z9hG4bKc0a8040b0000001f461ba83b00003ac10000003a Content-Length: 0 Call-ID: 95DAB8BF-A247-424B-ABBC-818327C31118@192.168.4.11 CSeq: 3 ACK From: "unknown";tag=3390393732197 Max-Forwards: 70 To: ;tag=as6a034200 User-Agent: SJphone/1.60.289a (SJ Labs) <-------------> [Apr 10 16:10:38] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 0 [ 33]: ACK sip:103@192.168.4.155 SIP/2.0 [Apr 10 16:10:38] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 1 [ 90]: Via: SIP/2.0/UDP 192.168.4.11;rport;branch=z9hG4bKc0a8040b0000001f461ba83b00003ac10000003a [Apr 10 16:10:38] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 2 [ 17]: Content-Length: 0 [Apr 10 16:10:38] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 3 [ 58]: Call-ID: 95DAB8BF-A247-424B-ABBC-818327C31118@192.168.4.11 [Apr 10 16:10:38] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 4 [ 11]: CSeq: 3 ACK [Apr 10 16:10:38] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 5 [ 61]: From: "unknown";tag=3390393732197 [Apr 10 16:10:38] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 6 [ 16]: Max-Forwards: 70 [Apr 10 16:10:38] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 7 [ 47]: To: ;tag=as6a034200 [Apr 10 16:10:38] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 8 [ 39]: User-Agent: SJphone/1.60.289a (SJ Labs) --- (9 headers 0 lines) --- [Apr 10 16:10:38] DEBUG[27900]: chan_sip.c:15375 handle_request: **** Received ACK (6) - Command in SIP ACK [Apr 10 16:10:38] DEBUG[27900]: chan_sip.c:2226 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #32 [Apr 10 16:10:38] DEBUG[27900]: chan_sip.c:2237 __sip_ack: Stopping retransmission on '95DAB8BF-A247-424B-ABBC-818327C31118@192.168.4.11' of Response 3: Match Found [Apr 10 16:10:38] DEBUG[27900]: app_queue.c:568 changethread: Device 'SIP/101' changed to state '8' (On Hold) but we don't care because they're not a member of any queue. <--- SIP read from 192.168.4.11:5060 ---> ACK sip:103@192.168.4.155 SIP/2.0 Via: SIP/2.0/UDP 192.168.4.11;rport;branch=z9hG4bKc0a8040b0000001f461ba83b000000cd0000003c Content-Length: 0 Call-ID: 95DAB8BF-A247-424B-ABBC-818327C31118@192.168.4.11 CSeq: 3 ACK From: "unknown";tag=3390393732197 Max-Forwards: 70 To: ;tag=as6a034200 User-Agent: SJphone/1.60.289a (SJ Labs) <-------------> [Apr 10 16:10:38] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 0 [ 33]: ACK sip:103@192.168.4.155 SIP/2.0 [Apr 10 16:10:38] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 1 [ 90]: Via: SIP/2.0/UDP 192.168.4.11;rport;branch=z9hG4bKc0a8040b0000001f461ba83b000000cd0000003c [Apr 10 16:10:38] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 2 [ 17]: Content-Length: 0 [Apr 10 16:10:38] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 3 [ 58]: Call-ID: 95DAB8BF-A247-424B-ABBC-818327C31118@192.168.4.11 [Apr 10 16:10:38] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 4 [ 11]: CSeq: 3 ACK [Apr 10 16:10:38] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 5 [ 61]: From: "unknown";tag=3390393732197 [Apr 10 16:10:38] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 6 [ 16]: Max-Forwards: 70 [Apr 10 16:10:38] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 7 [ 47]: To: ;tag=as6a034200 [Apr 10 16:10:38] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 8 [ 39]: User-Agent: SJphone/1.60.289a (SJ Labs) --- (9 headers 0 lines) --- [Apr 10 16:10:38] DEBUG[27900]: channel.c:2307 __ast_read: Generator got voice, switching to phase locked mode [Apr 10 16:10:38] DEBUG[27900]: channel.c:1964 ast_settimeout: Scheduling timer at 0 sample intervals [Apr 10 16:10:38] DEBUG[27900]: channel.c:2822 set_format: Set channel SIP/103-08202018 to write format slin [Apr 10 16:10:38] DEBUG[27900]: res_musiconhold.c:252 ast_moh_files_next: SIP/103-08202018 Opened file 1 '/var/lib/asterisk/moh/fpm-sunshine' [Apr 10 16:10:38] DEBUG[27900]: rtp.c:2827 ast_rtp_write: Ooh, format changed from unknown to ulaw [Apr 10 16:10:38] DEBUG[27900]: rtp.c:2844 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160 [Apr 10 16:10:38] DEBUG[27900]: chan_sip.c:15375 handle_request: **** Received ACK (6) - Command in SIP ACK [Apr 10 16:10:40] DEBUG[27900]: rtp.c:945 ast_rtcp_read: Got RTCP report of 52 bytes <--- SIP read from 192.168.4.11:5060 ---> OPTIONS sip:192.168.4.155:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.4.11;rport;branch=z9hG4bKc0a8040b00000008461ba84000004d1d0000003d Content-Length: 0 Call-ID: 67A5E3DF-487C-4AD8-80E0-76048020090D@192.168.4.11 CSeq: 13 OPTIONS From: ;tag=3391559331435 Max-Forwards: 70 To: <-------------> [Apr 10 16:10:43] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 0 [ 38]: OPTIONS sip:192.168.4.155:5060 SIP/2.0 [Apr 10 16:10:43] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 1 [ 90]: Via: SIP/2.0/UDP 192.168.4.11;rport;branch=z9hG4bKc0a8040b00000008461ba84000004d1d0000003d [Apr 10 16:10:43] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 2 [ 17]: Content-Length: 0 [Apr 10 16:10:43] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 3 [ 58]: Call-ID: 67A5E3DF-487C-4AD8-80E0-76048020090D@192.168.4.11 [Apr 10 16:10:43] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 4 [ 16]: CSeq: 13 OPTIONS [Apr 10 16:10:43] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 5 [ 52]: From: ;tag=3391559331435 [Apr 10 16:10:43] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 6 [ 16]: Max-Forwards: 70 [Apr 10 16:10:43] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 7 [ 28]: To: --- (8 headers 0 lines) --- [Apr 10 16:10:43] DEBUG[27900]: chan_sip.c:4666 sip_alloc: Allocating new SIP dialog for 67A5E3DF-487C-4AD8-80E0-76048020090D@192.168.4.11 - OPTIONS (No RTP) [Apr 10 16:10:43] DEBUG[27900]: chan_sip.c:15375 handle_request: **** Received OPTIONS (3) - Command in SIP OPTIONS Looking for s in default (domain 192.168.4.155) <--- Transmitting (no NAT) to 192.168.4.11:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.4.11;branch=z9hG4bKc0a8040b00000008461ba84000004d1d0000003d;received=192.168.4.11;rport=5060 From: ;tag=3391559331435 To: ;tag=as3b45eac3 Call-ID: 67A5E3DF-487C-4AD8-80E0-76048020090D@192.168.4.11 CSeq: 13 OPTIONS User-Agent: Asterisk PBX SVN-trunk-r61184 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Accept: application/sdp Content-Length: 0 <------------> Scheduling destruction of SIP dialog '67A5E3DF-487C-4AD8-80E0-76048020090D@192.168.4.11' in 32000 ms (Method: OPTIONS) [Apr 10 16:10:45] DEBUG[27900]: rtp.c:945 ast_rtcp_read: Got RTCP report of 52 bytes <--- SIP read from 192.168.4.11:5060 ---> INVITE sip:103@192.168.4.155 SIP/2.0 Via: SIP/2.0/UDP 192.168.4.11;rport;branch=z9hG4bKc0a8040b0000001f461ba843000067330000003f Content-Length: 219 Contact: Call-ID: 95DAB8BF-A247-424B-ABBC-818327C31118@192.168.4.11 Content-Type: application/sdp CSeq: 4 INVITE From: "unknown";tag=3390393732197 Max-Forwards: 70 To: ;tag=as6a034200 User-Agent: SJphone/1.60.289a (SJ Labs) v=0 o=- 3385206453 3385206455 IN IP4 192.168.4.11 s=SJphone c=IN IP4 192.168.4.11 t=0 0 a=direction:active m=audio 49152 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-11,16 <-------------> [Apr 10 16:10:47] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 0 [ 36]: INVITE sip:103@192.168.4.155 SIP/2.0 [Apr 10 16:10:47] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 1 [ 90]: Via: SIP/2.0/UDP 192.168.4.11;rport;branch=z9hG4bKc0a8040b0000001f461ba843000067330000003f [Apr 10 16:10:47] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 2 [ 19]: Content-Length: 219 [Apr 10 16:10:47] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 3 [ 36]: Contact: [Apr 10 16:10:47] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 4 [ 58]: Call-ID: 95DAB8BF-A247-424B-ABBC-818327C31118@192.168.4.11 [Apr 10 16:10:47] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 5 [ 29]: Content-Type: application/sdp [Apr 10 16:10:47] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 6 [ 14]: CSeq: 4 INVITE [Apr 10 16:10:47] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 7 [ 61]: From: "unknown";tag=3390393732197 [Apr 10 16:10:47] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 8 [ 16]: Max-Forwards: 70 [Apr 10 16:10:47] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 9 [ 47]: To: ;tag=as6a034200 [Apr 10 16:10:47] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 10 [ 39]: User-Agent: SJphone/1.60.289a (SJ Labs) [Apr 10 16:10:47] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 11 [ 0]: [Apr 10 16:10:47] DEBUG[27900]: chan_sip.c:4944 parse_request: Body 0 [ 3]: v=0 [Apr 10 16:10:47] DEBUG[27900]: chan_sip.c:4944 parse_request: Body 1 [ 45]: o=- 3385206453 3385206455 IN IP4 192.168.4.11 [Apr 10 16:10:47] DEBUG[27900]: chan_sip.c:4944 parse_request: Body 2 [ 9]: s=SJphone [Apr 10 16:10:47] DEBUG[27900]: chan_sip.c:4944 parse_request: Body 3 [ 21]: c=IN IP4 192.168.4.11 [Apr 10 16:10:47] DEBUG[27900]: chan_sip.c:4944 parse_request: Body 4 [ 5]: t=0 0 [Apr 10 16:10:47] DEBUG[27900]: chan_sip.c:4944 parse_request: Body 5 [ 18]: a=direction:active [Apr 10 16:10:47] DEBUG[27900]: chan_sip.c:4944 parse_request: Body 6 [ 27]: m=audio 49152 RTP/AVP 0 101 [Apr 10 16:10:47] DEBUG[27900]: chan_sip.c:4944 parse_request: Body 7 [ 20]: a=rtpmap:0 PCMU/8000 [Apr 10 16:10:47] DEBUG[27900]: chan_sip.c:4944 parse_request: Body 8 [ 33]: a=rtpmap:101 telephone-event/8000 --- (11 headers 9 lines) --- [Apr 10 16:10:47] DEBUG[27900]: chan_sip.c:15375 handle_request: **** Received INVITE (5) - Command in SIP INVITE Sending to 192.168.4.11 : 5060 (NAT) [Apr 10 16:10:47] DEBUG[27900]: chan_sip.c:14001 handle_request_invite: Initializing initreq for method INVITE - callid 95DAB8BF-A247-424B-ABBC-818327C31118@192.168.4.11 Found RTP audio format 0 Found RTP audio format 101 [Apr 10 16:10:47] DEBUG[27900]: chan_sip.c:5291 process_sdp: Peer doesn't provide T.38 UDPTL Peer audio RTP is at port 192.168.4.11:49152 Found description format PCMU for ID 0 Found description format telephone-event for ID 101 [Apr 10 16:10:47] DEBUG[27900]: chan_sip.c:5536 process_sdp: T38 state changed to 0 on channel SIP/101-081edb90 Capabilities: us - 0x4 (ulaw), peer - audio=0x4 (ulaw)/video=0x0 (nothing)/text=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.4.11:49152 [Apr 10 16:10:47] DEBUG[27900]: chan_sip.c:5627 process_sdp: We're settling with these formats: 0x4 (ulaw) [Apr 10 16:10:47] DEBUG[27900]: chan_sip.c:5634 process_sdp: We have an owner, now see if we need to change this call [Apr 10 16:10:47] DEBUG[27900]: chan_sip.c:14134 handle_request_invite: Got a SIP re-invite for call 95DAB8BF-A247-424B-ABBC-818327C31118@192.168.4.11 [Apr 10 16:10:47] DEBUG[27900]: chan_sip.c:14229 handle_request_invite: SIP/101-081edb90: This call is UP.... [Apr 10 16:10:47] DEBUG[27900]: chan_sip.c:6958 transmit_response_with_sdp: Setting framing from config on incoming call [Apr 10 16:10:47] DEBUG[27900]: chan_sip.c:6680 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True Text flag: True [Apr 10 16:10:47] DEBUG[27900]: chan_sip.c:6682 add_sdp: ** Our prefcodec: 0x0 (nothing) Audio is at 192.168.4.155 port 12206 Adding codec 0x4 (ulaw) to SDP Adding non-codec 0x1 (telephone-event) to SDP [Apr 10 16:10:47] DEBUG[27900]: chan_sip.c:6843 add_sdp: -- Done with adding codecs to SDP [Apr 10 16:10:47] DEBUG[27900]: chan_sip.c:6903 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw) <--- Reliably Transmitting (NAT) to 192.168.4.11:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.4.11;branch=z9hG4bKc0a8040b0000001f461ba843000067330000003f;received=192.168.4.11;rport=5060 From: "unknown";tag=3390393732197 To: ;tag=as6a034200 Call-ID: 95DAB8BF-A247-424B-ABBC-818327C31118@192.168.4.11 CSeq: 4 INVITE User-Agent: Asterisk PBX SVN-trunk-r61184 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 252 v=0 o=root 1820935938 1820935940 IN IP4 192.168.4.155 s=session c=IN IP4 192.168.4.155 t=0 0 m=audio 12206 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 <------------> [Apr 10 16:10:47] DEBUG[27900]: chan_sip.c:2118 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #35 [Apr 10 16:10:47] DEBUG[27900]: rtp.c:2827 ast_rtp_write: Ooh, format changed from unknown to ulaw [Apr 10 16:10:47] DEBUG[27900]: rtp.c:2844 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160 [Apr 10 16:10:47] DEBUG[27900]: chan_sip.c:2014 retrans_pkt: SIP TIMER: Rescheduling retransmission #35 (1) SIP/2.0 - 1 [Apr 10 16:10:47] DEBUG[27900]: chan_sip.c:2028 retrans_pkt: ** SIP timers: Rescheduling retransmission 2 to 4 ms (t1 2 ms (Retrans id #35)) Retransmitting #1 (NAT) to 192.168.4.11:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.4.11;branch=z9hG4bKc0a8040b0000001f461ba843000067330000003f;received=192.168.4.11;rport=5060 From: "unknown";tag=3390393732197 To: ;tag=as6a034200 Call-ID: 95DAB8BF-A247-424B-ABBC-818327C31118@192.168.4.11 CSeq: 4 INVITE User-Agent: Asterisk PBX SVN-trunk-r61184 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 252 v=0 o=root 1820935938 1820935940 IN IP4 192.168.4.155 s=session c=IN IP4 192.168.4.155 t=0 0 m=audio 12206 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 --- <--- SIP read from 192.168.4.11:5060 ---> ACK sip:103@192.168.4.155 SIP/2.0 Via: SIP/2.0/UDP 192.168.4.11;rport;branch=z9hG4bKc0a8040b0000001f461ba84300002ffc00000041 Content-Length: 0 Call-ID: 95DAB8BF-A247-424B-ABBC-818327C31118@192.168.4.11 CSeq: 4 ACK From: "unknown";tag=3390393732197 Max-Forwards: 70 To: ;tag=as6a034200 User-Agent: SJphone/1.60.289a (SJ Labs) <-------------> [Apr 10 16:10:47] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 0 [ 33]: ACK sip:103@192.168.4.155 SIP/2.0 [Apr 10 16:10:47] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 1 [ 90]: Via: SIP/2.0/UDP 192.168.4.11;rport;branch=z9hG4bKc0a8040b0000001f461ba84300002ffc00000041 [Apr 10 16:10:47] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 2 [ 17]: Content-Length: 0 [Apr 10 16:10:47] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 3 [ 58]: Call-ID: 95DAB8BF-A247-424B-ABBC-818327C31118@192.168.4.11 [Apr 10 16:10:47] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 4 [ 11]: CSeq: 4 ACK [Apr 10 16:10:47] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 5 [ 61]: From: "unknown";tag=3390393732197 [Apr 10 16:10:47] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 6 [ 16]: Max-Forwards: 70 [Apr 10 16:10:47] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 7 [ 47]: To: ;tag=as6a034200 [Apr 10 16:10:47] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 8 [ 39]: User-Agent: SJphone/1.60.289a (SJ Labs) --- (9 headers 0 lines) --- [Apr 10 16:10:47] DEBUG[27900]: chan_sip.c:15375 handle_request: **** Received ACK (6) - Command in SIP ACK [Apr 10 16:10:47] DEBUG[27900]: chan_sip.c:2226 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #35 [Apr 10 16:10:47] DEBUG[27900]: chan_sip.c:2237 __sip_ack: Stopping retransmission on '95DAB8BF-A247-424B-ABBC-818327C31118@192.168.4.11' of Response 4: Match Found <--- SIP read from 192.168.4.11:5060 ---> ACK sip:103@192.168.4.155 SIP/2.0 Via: SIP/2.0/UDP 192.168.4.11;rport;branch=z9hG4bKc0a8040b0000001f461ba843000071f500000043 Content-Length: 0 Call-ID: 95DAB8BF-A247-424B-ABBC-818327C31118@192.168.4.11 CSeq: 4 ACK From: "unknown";tag=3390393732197 Max-Forwards: 70 To: ;tag=as6a034200 User-Agent: SJphone/1.60.289a (SJ Labs) <-------------> [Apr 10 16:10:47] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 0 [ 33]: ACK sip:103@192.168.4.155 SIP/2.0 [Apr 10 16:10:47] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 1 [ 90]: Via: SIP/2.0/UDP 192.168.4.11;rport;branch=z9hG4bKc0a8040b0000001f461ba843000071f500000043 [Apr 10 16:10:47] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 2 [ 17]: Content-Length: 0 [Apr 10 16:10:47] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 3 [ 58]: Call-ID: 95DAB8BF-A247-424B-ABBC-818327C31118@192.168.4.11 [Apr 10 16:10:47] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 4 [ 11]: CSeq: 4 ACK [Apr 10 16:10:47] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 5 [ 61]: From: "unknown";tag=3390393732197 [Apr 10 16:10:47] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 6 [ 16]: Max-Forwards: 70 [Apr 10 16:10:47] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 7 [ 47]: To: ;tag=as6a034200 [Apr 10 16:10:47] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 8 [ 39]: User-Agent: SJphone/1.60.289a (SJ Labs) --- (9 headers 0 lines) --- [Apr 10 16:10:47] DEBUG[27900]: chan_sip.c:15375 handle_request: **** Received ACK (6) - Command in SIP ACK [Apr 10 16:10:50] DEBUG[27900]: rtp.c:945 ast_rtcp_read: Got RTCP report of 52 bytes [Apr 10 16:10:55] DEBUG[27900]: rtp.c:945 ast_rtcp_read: Got RTCP report of 52 bytes [Apr 10 16:10:55] DEBUG[27900]: chan_sip.c:2164 __sip_autodestruct: Auto destroying SIP dialog '67A5E3DF-487C-4AD8-80E0-76048020090D@192.168.4.11' [Apr 10 16:10:55] DEBUG[27900]: chan_sip.c:3404 sip_destroy: Destroying SIP dialog 67A5E3DF-487C-4AD8-80E0-76048020090D@192.168.4.11 Really destroying SIP dialog '67A5E3DF-487C-4AD8-80E0-76048020090D@192.168.4.11' Method: OPTIONS sip sho[Apr 10 16:11:00] DEBUG[27900]: rtp.c:945 ast_rtcp_read: Got RTCP report of 52 bytes w inuse * User name In use Limit * Peer name In use Limit 103 1/0/0 2 102 0/0/0 2 101 1/0/1 2 *CLI> co <--- SIP read from 192.168.4.11:5060 ---> OPTIONS sip:192.168.4.155:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.4.11;rport;branch=z9hG4bKc0a8040b00000008461ba8540000092a00000044 Content-Length: 0 Call-ID: 67A5E3DF-487C-4AD8-80E0-76048020090D@192.168.4.11 CSeq: 14 OPTIONS From: ;tag=3393559329377 Max-Forwards: 70 To: <-------------> [Apr 10 16:11:03] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 0 [ 38]: OPTIONS sip:192.168.4.155:5060 SIP/2.0 [Apr 10 16:11:03] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 1 [ 90]: Via: SIP/2.0/UDP 192.168.4.11;rport;branch=z9hG4bKc0a8040b00000008461ba8540000092a00000044 [Apr 10 16:11:03] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 2 [ 17]: Content-Length: 0 [Apr 10 16:11:03] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 3 [ 58]: Call-ID: 67A5E3DF-487C-4AD8-80E0-76048020090D@192.168.4.11 [Apr 10 16:11:03] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 4 [ 16]: CSeq: 14 OPTIONS [Apr 10 16:11:03] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 5 [ 52]: From: ;tag=3393559329377 [Apr 10 16:11:03] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 6 [ 16]: Max-Forwards: 70 [Apr 10 16:11:03] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 7 [ 28]: To: --- (8 headers 0 lines) --- [Apr 10 16:11:03] DEBUG[27900]: chan_sip.c:4666 sip_alloc: Allocating new SIP dialog for 67A5E3DF-487C-4AD8-80E0-76048020090D@192.168.4.11 - OPTIONS (No RTP) [Apr 10 16:11:03] DEBUG[27900]: chan_sip.c:15375 handle_request: **** Received OPTIONS (3) - Command in SIP OPTIONS Looking for s in default (domain 192.168.4.155) <--- Transmitting (no NAT) to 192.168.4.11:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.4.11;branch=z9hG4bKc0a8040b00000008461ba8540000092a00000044;received=192.168.4.11;rport=5060 From: ;tag=3393559329377 To: ;tag=as4515c00b Call-ID: 67A5E3DF-487C-4AD8-80E0-76048020090D@192.168.4.11 CSeq: 14 OPTIONS User-Agent: Asterisk PBX SVN-trunk-r61184 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Accept: application/sdp Content-Length: 0 <------------> Scheduling destruction of SIP dialog '67A5E3DF-487C-4AD8-80E0-76048020090D@192.168.4.11' in 32000 ms (Method: OPTIONS) re show hints -= Registered Asterisk Dial Plan Hints =- 103@from-sip : SIP/103 State:InUse Watchers 0 102@from-sip : SIP/102 State:Unavailable Watchers 0 101@from-sip : SIP/101 State:Hold Watchers 0 ---------------- - 3 hints registered *CLI> [Apr 10 16:11:05] DEBUG[27900]: rtp.c:945 ast_rtcp_read: Got RTCP report of 52 bytes [Apr 10 16:11:10] DEBUG[27900]: rtp.c:945 ast_rtcp_read: Got RTCP report of 52 bytes [Apr 10 16:11:15] DEBUG[27900]: rtp.c:945 ast_rtcp_read: Got RTCP report of 52 bytes [Apr 10 16:11:15] DEBUG[27900]: chan_sip.c:2164 __sip_autodestruct: Auto destroying SIP dialog '67A5E3DF-487C-4AD8-80E0-76048020090D@192.168.4.11' [Apr 10 16:11:15] DEBUG[27900]: chan_sip.c:3404 sip_destroy: Destroying SIP dialog 67A5E3DF-487C-4AD8-80E0-76048020090D@192.168.4.11 Really destroying SIP dialog '67A5E3DF-487C-4AD8-80E0-76048020090D@192.168.4.11' Method: OPTIONS [Apr 10 16:11:19] DEBUG[27900]: chan_sip.c:4666 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Apr 10 16:11:19] DEBUG[27900]: chan_sip.c:1721 initialize_initreq: Initializing initreq for method OPTIONS - callid 40fc42965155b7f451e9c2b0696d5a22@192.168.4.155 [Apr 10 16:11:19] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 0 [ 56]: OPTIONS sip:103@192.168.4.109:2051;line=0cl0sm4g SIP/2.0 [Apr 10 16:11:19] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 1 [ 64]: Via: SIP/2.0/UDP 192.168.4.155:5060;branch=z9hG4bK6b2e9ee7;rport [Apr 10 16:11:19] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 2 [ 16]: Max-Forwards: 70 [Apr 10 16:11:19] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 3 [ 60]: From: "asterisk" ;tag=as63134a25 [Apr 10 16:11:19] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 4 [ 46]: To: [Apr 10 16:11:19] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 5 [ 37]: Contact: [Apr 10 16:11:19] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 6 [ 55]: Call-ID: 40fc42965155b7f451e9c2b0696d5a22@192.168.4.155 [Apr 10 16:11:19] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 7 [ 17]: CSeq: 102 OPTIONS [Apr 10 16:11:19] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 8 [ 41]: User-Agent: Asterisk PBX SVN-trunk-r61184 [Apr 10 16:11:19] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 9 [ 35]: Date: Tue, 10 Apr 2007 14:11:19 GMT [Apr 10 16:11:19] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 10 [ 66]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY [Apr 10 16:11:19] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 11 [ 19]: Supported: replaces [Apr 10 16:11:19] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 12 [ 17]: Content-Length: 0 Reliably Transmitting (NAT) to 192.168.4.109:2051: OPTIONS sip:103@192.168.4.109:2051;line=0cl0sm4g SIP/2.0 Via: SIP/2.0/UDP 192.168.4.155:5060;branch=z9hG4bK6b2e9ee7;rport Max-Forwards: 70 From: "asterisk" ;tag=as63134a25 To: Contact: Call-ID: 40fc42965155b7f451e9c2b0696d5a22@192.168.4.155 CSeq: 102 OPTIONS User-Agent: Asterisk PBX SVN-trunk-r61184 Date: Tue, 10 Apr 2007 14:11:19 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 --- [Apr 10 16:11:19] DEBUG[27900]: chan_sip.c:2118 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #38 <--- SIP read from 192.168.4.109:2051 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.4.155:5060;branch=z9hG4bK6b2e9ee7;rport=5060 From: "asterisk" ;tag=as63134a25 To: Call-ID: 40fc42965155b7f451e9c2b0696d5a22@192.168.4.155 CSeq: 102 OPTIONS Contact: ;flow-id=1 User-Agent: snom360/6.5.8 Accept-Language: en Accept: application/sdp Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO Allow-Events: talk, hold, refer Supported: timer, 100rel, replaces, callerid Content-Length: 0 <-------------> [Apr 10 16:11:19] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 0 [ 14]: SIP/2.0 200 OK [Apr 10 16:11:19] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 1 [ 69]: Via: SIP/2.0/UDP 192.168.4.155:5060;branch=z9hG4bK6b2e9ee7;rport=5060 [Apr 10 16:11:19] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 2 [ 60]: From: "asterisk" ;tag=as63134a25 [Apr 10 16:11:19] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 3 [ 46]: To: [Apr 10 16:11:19] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 4 [ 55]: Call-ID: 40fc42965155b7f451e9c2b0696d5a22@192.168.4.155 [Apr 10 16:11:19] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 5 [ 17]: CSeq: 102 OPTIONS [Apr 10 16:11:19] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 6 [ 61]: Contact: ;flow-id=1 [Apr 10 16:11:19] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 7 [ 25]: User-Agent: snom360/6.5.8 [Apr 10 16:11:19] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 8 [ 19]: Accept-Language: en [Apr 10 16:11:19] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 9 [ 23]: Accept: application/sdp [Apr 10 16:11:19] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 10 [ 88]: Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO [Apr 10 16:11:19] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 11 [ 31]: Allow-Events: talk, hold, refer [Apr 10 16:11:19] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 12 [ 44]: Supported: timer, 100rel, replaces, callerid [Apr 10 16:11:19] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 13 [ 17]: Content-Length: 0 --- (14 headers 0 lines) --- [Apr 10 16:11:19] DEBUG[27900]: chan_sip.c:2226 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #38 [Apr 10 16:11:19] DEBUG[27900]: chan_sip.c:2237 __sip_ack: Stopping retransmission on '40fc42965155b7f451e9c2b0696d5a22@192.168.4.155' of Request 102: Match Found Really destroying SIP dialog '40fc42965155b7f451e9c2b0696d5a22@192.168.4.155' Method: OPTIONS [Apr 10 16:11:19] DEBUG[27900]: chan_sip.c:4666 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Apr 10 16:11:19] DEBUG[27900]: chan_sip.c:1721 initialize_initreq: Initializing initreq for method OPTIONS - callid 05b9c5936fbd07937c57fe7d5f94130f@192.168.4.155 [Apr 10 16:11:19] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 0 [ 41]: OPTIONS sip:101@192.168.4.11:5060 SIP/2.0 [Apr 10 16:11:19] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 1 [ 64]: Via: SIP/2.0/UDP 192.168.4.155:5060;branch=z9hG4bK03910fe7;rport [Apr 10 16:11:19] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 2 [ 16]: Max-Forwards: 70 [Apr 10 16:11:19] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 3 [ 60]: From: "asterisk" ;tag=as07def4ac [Apr 10 16:11:19] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 4 [ 31]: To: [Apr 10 16:11:19] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 5 [ 37]: Contact: [Apr 10 16:11:19] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 6 [ 55]: Call-ID: 05b9c5936fbd07937c57fe7d5f94130f@192.168.4.155 [Apr 10 16:11:19] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 7 [ 17]: CSeq: 102 OPTIONS [Apr 10 16:11:19] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 8 [ 41]: User-Agent: Asterisk PBX SVN-trunk-r61184 [Apr 10 16:11:19] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 9 [ 35]: Date: Tue, 10 Apr 2007 14:11:19 GMT [Apr 10 16:11:19] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 10 [ 66]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY [Apr 10 16:11:19] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 11 [ 19]: Supported: replaces [Apr 10 16:11:19] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 12 [ 17]: Content-Length: 0 Reliably Transmitting (NAT) to 192.168.4.11:5060: OPTIONS sip:101@192.168.4.11:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.4.155:5060;branch=z9hG4bK03910fe7;rport Max-Forwards: 70 From: "asterisk" ;tag=as07def4ac To: Contact: Call-ID: 05b9c5936fbd07937c57fe7d5f94130f@192.168.4.155 CSeq: 102 OPTIONS User-Agent: Asterisk PBX SVN-trunk-r61184 Date: Tue, 10 Apr 2007 14:11:19 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 --- [Apr 10 16:11:19] DEBUG[27900]: chan_sip.c:2118 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #41 <--- SIP read from 192.168.4.11:5060 ---> SIP/2.0 405 Method Not Allowed Via: SIP/2.0/UDP 192.168.4.155:5060;rport=5060;received=192.168.4.155;branch=z9hG4bK03910fe7 Content-Length: 0 Allow: INVITE, ACK, CANCEL, BYE, REFER, NOTIFY Call-ID: 05b9c5936fbd07937c57fe7d5f94130f@192.168.4.155 CSeq: 102 OPTIONS From: "asterisk";tag=as07def4ac Server: SJphone/1.60.289a (SJ Labs) To: "unknown" <-------------> [Apr 10 16:11:19] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 0 [ 30]: SIP/2.0 405 Method Not Allowed [Apr 10 16:11:19] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 1 [ 92]: Via: SIP/2.0/UDP 192.168.4.155:5060;rport=5060;received=192.168.4.155;branch=z9hG4bK03910fe7 [Apr 10 16:11:19] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 2 [ 17]: Content-Length: 0 [Apr 10 16:11:19] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 3 [ 46]: Allow: INVITE, ACK, CANCEL, BYE, REFER, NOTIFY [Apr 10 16:11:19] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 4 [ 55]: Call-ID: 05b9c5936fbd07937c57fe7d5f94130f@192.168.4.155 [Apr 10 16:11:19] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 5 [ 17]: CSeq: 102 OPTIONS [Apr 10 16:11:19] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 6 [ 59]: From: "asterisk";tag=as07def4ac [Apr 10 16:11:19] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 7 [ 35]: Server: SJphone/1.60.289a (SJ Labs) [Apr 10 16:11:19] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 8 [ 40]: To: "unknown" --- (9 headers 0 lines) --- [Apr 10 16:11:19] DEBUG[27900]: chan_sip.c:2226 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #41 [Apr 10 16:11:19] DEBUG[27900]: chan_sip.c:2237 __sip_ack: Stopping retransmission on '05b9c5936fbd07937c57fe7d5f94130f@192.168.4.155' of Request 102: Match Found Really destroying SIP dialog '05b9c5936fbd07937c57fe7d5f94130f@192.168.4.155' Method: OPTIONS [Apr 10 16:11:20] DEBUG[27900]: rtp.c:945 ast_rtcp_read: Got RTCP report of 52 bytes <--- SIP read from 192.168.4.11:5060 ---> OPTIONS sip:192.168.4.155:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.4.11;rport;branch=z9hG4bKc0a8040b00000008461ba86800007a1c00000047 Content-Length: 0 Call-ID: 67A5E3DF-487C-4AD8-80E0-76048020090D@192.168.4.11 CSeq: 15 OPTIONS From: ;tag=3395559329881 Max-Forwards: 70 To: <-------------> [Apr 10 16:11:23] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 0 [ 38]: OPTIONS sip:192.168.4.155:5060 SIP/2.0 [Apr 10 16:11:23] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 1 [ 90]: Via: SIP/2.0/UDP 192.168.4.11;rport;branch=z9hG4bKc0a8040b00000008461ba86800007a1c00000047 [Apr 10 16:11:23] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 2 [ 17]: Content-Length: 0 [Apr 10 16:11:23] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 3 [ 58]: Call-ID: 67A5E3DF-487C-4AD8-80E0-76048020090D@192.168.4.11 [Apr 10 16:11:23] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 4 [ 16]: CSeq: 15 OPTIONS [Apr 10 16:11:23] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 5 [ 52]: From: ;tag=3395559329881 [Apr 10 16:11:23] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 6 [ 16]: Max-Forwards: 70 [Apr 10 16:11:23] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 7 [ 28]: To: --- (8 headers 0 lines) --- [Apr 10 16:11:23] DEBUG[27900]: chan_sip.c:4666 sip_alloc: Allocating new SIP dialog for 67A5E3DF-487C-4AD8-80E0-76048020090D@192.168.4.11 - OPTIONS (No RTP) [Apr 10 16:11:23] DEBUG[27900]: chan_sip.c:15375 handle_request: **** Received OPTIONS (3) - Command in SIP OPTIONS Looking for s in default (domain 192.168.4.155) <--- Transmitting (no NAT) to 192.168.4.11:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.4.11;branch=z9hG4bKc0a8040b00000008461ba86800007a1c00000047;received=192.168.4.11;rport=5060 From: ;tag=3395559329881 To: ;tag=as5de56d17 Call-ID: 67A5E3DF-487C-4AD8-80E0-76048020090D@192.168.4.11 CSeq: 15 OPTIONS User-Agent: Asterisk PBX SVN-trunk-r61184 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Accept: application/sdp Content-Length: 0 <------------> Scheduling destruction of SIP dialog '67A5E3DF-487C-4AD8-80E0-76048020090D@192.168.4.11' in 32000 ms (Method: OPTIONS) <--- SIP read from 192.168.4.109:2051 ---> BYE sip:101@192.168.4.155 SIP/2.0 Via: SIP/2.0/UDP 192.168.4.109:2051;branch=z9hG4bK-57w8cos8fkqa;rport From: ;tag=v3o4bfn60t To: "unknown" ;tag=as633c1492 Call-ID: 16221df46b0c1cc779b6602135db084b@192.168.4.155 CSeq: 1 BYE Max-Forwards: 70 Contact: ;flow-id=1 User-Agent: snom360/6.5.8 RTP-RxStat: Total_Rx_Pkts=2289,Rx_Pkts=2289,Rx_Pkts_Lost=0,Remote_Rx_Pkts_Lost=0 RTP-TxStat: Total_Tx_Pkts=2432,Tx_Pkts=2432,Remote_Tx_Pkts=2251 Content-Length: 0 <-------------> [Apr 10 16:11:25] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 0 [ 33]: BYE sip:101@192.168.4.155 SIP/2.0 [Apr 10 16:11:25] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 1 [ 69]: Via: SIP/2.0/UDP 192.168.4.109:2051;branch=z9hG4bK-57w8cos8fkqa;rport [Apr 10 16:11:25] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 2 [ 63]: From: ;tag=v3o4bfn60t [Apr 10 16:11:25] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 3 [ 52]: To: "unknown" ;tag=as633c1492 [Apr 10 16:11:25] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 4 [ 55]: Call-ID: 16221df46b0c1cc779b6602135db084b@192.168.4.155 [Apr 10 16:11:25] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 5 [ 11]: CSeq: 1 BYE [Apr 10 16:11:25] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 6 [ 16]: Max-Forwards: 70 [Apr 10 16:11:25] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 7 [ 61]: Contact: ;flow-id=1 [Apr 10 16:11:25] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 8 [ 25]: User-Agent: snom360/6.5.8 [Apr 10 16:11:25] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 9 [ 80]: RTP-RxStat: Total_Rx_Pkts=2289,Rx_Pkts=2289,Rx_Pkts_Lost=0,Remote_Rx_Pkts_Lost=0 [Apr 10 16:11:25] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 10 [ 63]: RTP-TxStat: Total_Tx_Pkts=2432,Tx_Pkts=2432,Remote_Tx_Pkts=2251 [Apr 10 16:11:25] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 11 [ 17]: Content-Length: 0 --- (12 headers 0 lines) --- [Apr 10 16:11:25] DEBUG[27900]: chan_sip.c:15375 handle_request: **** Received BYE (8) - Command in SIP BYE [Apr 10 16:11:25] DEBUG[27900]: chan_sip.c:14881 handle_request_bye: Initializing initreq for method BYE - callid 16221df46b0c1cc779b6602135db084b@192.168.4.155 Sending to 192.168.4.109 : 2051 (NAT) [Apr 10 16:11:25] DEBUG[27900]: chan_sip.c:1734 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 16221df46b0c1cc779b6602135db084b@192.168.4.155 [Apr 10 16:11:25] DEBUG[27900]: chan_sip.c:14938 handle_request_bye: Received bye, issuing owner hangup <--- Transmitting (NAT) to 192.168.4.109:2051 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.4.109:2051;branch=z9hG4bK-57w8cos8fkqa;received=192.168.4.109;rport=2051 From: ;tag=v3o4bfn60t To: "unknown" ;tag=as633c1492 Call-ID: 16221df46b0c1cc779b6602135db084b@192.168.4.155 CSeq: 1 BYE User-Agent: Asterisk PBX SVN-trunk-r61184 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> -- Stopped music on hold on SIP/103-08202018 [Apr 10 16:11:25] DEBUG[27900]: channel.c:2822 set_format: Set channel SIP/103-08202018 to write format ulaw [Apr 10 16:11:25] DEBUG[27900]: channel.c:1964 ast_settimeout: Scheduling timer at 0 sample intervals [Apr 10 16:11:25] DEBUG[27900]: rtp.c:3248 bridge_p2p_loop: p2p-rtp-bridge: Ooh, got a hangup [Apr 10 16:11:25] DEBUG[27900]: channel.c:4050 ast_channel_bridge: Returning from native bridge, channels: SIP/101-081edb90, SIP/103-08202018 [Apr 10 16:11:25] DEBUG[27900]: channel.c:1645 ast_hangup: Hanging up channel 'SIP/103-08202018' [Apr 10 16:11:25] DEBUG[27900]: chan_sip.c:3606 sip_hangup: Hangup call SIP/103-08202018, SIP callid 16221df46b0c1cc779b6602135db084b@192.168.4.155) [Apr 10 16:11:25] DEBUG[27900]: chan_sip.c:3615 sip_hangup: update_call_counter(103) - decrement call limit counter on hangup [Apr 10 16:11:25] DEBUG[27900]: chan_sip.c:3308 update_call_counter: Updating call counter for outgoing call [Apr 10 16:11:25] DEBUG[27900]: chan_sip.c:3352 update_call_counter: Call to peer '103' removed from call limit 2 [Apr 10 16:11:25] DEBUG[27900]: devicestate.c:444 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/103 [Apr 10 16:11:25] DEBUG[27900]: devicestate.c:444 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/103-08202018 [Apr 10 16:11:25] DEBUG[27900]: rtp.c:1572 ast_rtp_early_bridge: Channel '' has no RTP, not doing anything [Apr 10 16:11:25] DEBUG[27900]: app_dial.c:1713 dial_exec_full: Exiting with DIALSTATUS=ANSWER. [Apr 10 16:11:25] DEBUG[27900]: pbx.c:2312 __ast_pbx_run: Spawn extension (from-sip,103,3) exited non-zero on 'SIP/101-081edb90' == Spawn extension (from-sip, 103, 3) exited non-zero on 'SIP/101-081edb90' [Apr 10 16:11:25] DEBUG[27900]: pbx.c:1566 pbx_substitute_variables_helper_full: Function result is '"unknown" <101>' [Apr 10 16:11:25] DEBUG[27900]: pbx.c:1566 pbx_substitute_variables_helper_full: Function result is '101' [Apr 10 16:11:25] DEBUG[27900]: pbx.c:1566 pbx_substitute_variables_helper_full: Function result is '103' [Apr 10 16:11:25] DEBUG[27900]: pbx.c:1566 pbx_substitute_variables_helper_full: Function result is 'from-sip' [Apr 10 16:11:25] DEBUG[27900]: pbx.c:1566 pbx_substitute_variables_helper_full: Function result is 'SIP/101-081edb90' [Apr 10 16:11:25] DEBUG[27900]: pbx.c:1566 pbx_substitute_variables_helper_full: Function result is 'SIP/103-08202018' [Apr 10 16:11:25] DEBUG[27900]: pbx.c:1566 pbx_substitute_variables_helper_full: Function result is 'Dial' [Apr 10 16:11:25] DEBUG[27900]: pbx.c:1566 pbx_substitute_variables_helper_full: Function result is 'SIP/103' [Apr 10 16:11:25] DEBUG[27900]: pbx.c:1566 pbx_substitute_variables_helper_full: Function result is '2007-04-10 16:10:32' [Apr 10 16:11:25] DEBUG[27900]: pbx.c:1566 pbx_substitute_variables_helper_full: Function result is '2007-04-10 16:10:35' [Apr 10 16:11:25] DEBUG[27900]: pbx.c:1566 pbx_substitute_variables_helper_full: Function result is '2007-04-10 16:11:25' [Apr 10 16:11:25] DEBUG[27900]: pbx.c:1566 pbx_substitute_variables_helper_full: Function result is '53' [Apr 10 16:11:25] DEBUG[27900]: pbx.c:1566 pbx_substitute_variables_helper_full: Function result is '50' [Apr 10 16:11:25] DEBUG[27900]: pbx.c:1566 pbx_substitute_variables_helper_full: Function result is 'ANSWERED' [Apr 10 16:11:25] DEBUG[27900]: pbx.c:1566 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' [Apr 10 16:11:25] DEBUG[27900]: pbx.c:1566 pbx_substitute_variables_helper_full: Function result is '' [Apr 10 16:11:25] DEBUG[27900]: pbx.c:1566 pbx_substitute_variables_helper_full: Function result is '1176214232.0' [Apr 10 16:11:25] DEBUG[27900]: pbx.c:1566 pbx_substitute_variables_helper_full: Function result is '' [Apr 10 16:11:25] DEBUG[27900]: channel.c:1645 ast_hangup: Hanging up channel 'SIP/101-081edb90' [Apr 10 16:11:25] DEBUG[27900]: chan_sip.c:3606 sip_hangup: Hangup call SIP/101-081edb90, SIP callid 95DAB8BF-A247-424B-ABBC-818327C31118@192.168.4.11) [Apr 10 16:11:25] DEBUG[27900]: chan_sip.c:3615 sip_hangup: update_call_counter(101) - decrement call limit counter on hangup [Apr 10 16:11:25] DEBUG[27900]: chan_sip.c:3308 update_call_counter: Updating call counter for incoming call [Apr 10 16:11:25] DEBUG[27900]: chan_sip.c:3352 update_call_counter: Call from peer '101' removed from call limit 2 [Apr 10 16:11:25] DEBUG[27900]: devicestate.c:444 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/101 Scheduling destruction of SIP dialog '95DAB8BF-A247-424B-ABBC-818327C31118@192.168.4.11' in 128 ms (Method: ACK) [Apr 10 16:11:25] DEBUG[27900]: chan_sip.c:6055 reqprep: Strict routing enforced for session 95DAB8BF-A247-424B-ABBC-818327C31118@192.168.4.11 set_destination: Parsing for address/port to send to set_destination: set destination to 192.168.4.11, port 5060 Reliably Transmitting (NAT) to 192.168.4.11:5060: BYE sip:101@192.168.4.11:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.4.155:5060;branch=z9hG4bK7bb7b0a1;rport Max-Forwards: 70 From: ;tag=as6a034200 To: "unknown";tag=3390393732197 Call-ID: 95DAB8BF-A247-424B-ABBC-818327C31118@192.168.4.11 CSeq: 102 BYE User-Agent: Asterisk PBX SVN-trunk-r61184 Content-Length: 0 --- [Apr 10 16:11:25] DEBUG[27900]: chan_sip.c:2118 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #46 [Apr 10 16:11:25] DEBUG[27900]: devicestate.c:444 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/101-081edb90 [Apr 10 16:11:25] DEBUG[27900]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 103 [Apr 10 16:11:25] DEBUG[27900]: chan_sip.c:16008 sip_devicestate: Checking device state for peer 103 [Apr 10 16:11:25] DEBUG[27900]: devicestate.c:428 do_state_change: Changing state for SIP/103 - state 1 (Not in use) [Apr 10 16:11:25] DEBUG[27900]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 103 [Apr 10 16:11:25] DEBUG[27900]: chan_sip.c:16008 sip_devicestate: Checking device state for peer 103 [Apr 10 16:11:25] DEBUG[27900]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 103 [Apr 10 16:11:25] DEBUG[27900]: chan_sip.c:16008 sip_devicestate: Checking device state for peer 103 [Apr 10 16:11:25] DEBUG[27900]: devicestate.c:428 do_state_change: Changing state for SIP/103 - state 1 (Not in use) [Apr 10 16:11:25] DEBUG[27900]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 103 [Apr 10 16:11:25] DEBUG[27900]: chan_sip.c:16008 sip_devicestate: Checking device state for peer 103 [Apr 10 16:11:25] DEBUG[27900]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 101 [Apr 10 16:11:25] DEBUG[27900]: chan_sip.c:16008 sip_devicestate: Checking device state for peer 101 [Apr 10 16:11:25] DEBUG[27900]: devicestate.c:428 do_state_change: Changing state for SIP/101 - state 8 (On Hold) [Apr 10 16:11:25] DEBUG[27900]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 101 [Apr 10 16:11:25] DEBUG[27900]: chan_sip.c:16008 sip_devicestate: Checking device state for peer 101 [Apr 10 16:11:25] DEBUG[27900]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 101 [Apr 10 16:11:25] DEBUG[27900]: chan_sip.c:16008 sip_devicestate: Checking device state for peer 101 [Apr 10 16:11:25] DEBUG[27900]: devicestate.c:428 do_state_change: Changing state for SIP/101 - state 8 (On Hold) <--- SIP read from 192.168.4.11:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.4.155:5060;rport=5060;received=192.168.4.155;branch=z9hG4bK7bb7b0a1 Content-Length: 0 Call-ID: 95DAB8BF-A247-424B-ABBC-818327C31118@192.168.4.11 CSeq: 102 BYE From: ;tag=as6a034200 Server: SJphone/1.60.289a (SJ Labs) To: "unknown";tag=3390393732197 <-------------> [Apr 10 16:11:25] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 0 [ 14]: SIP/2.0 200 OK [Apr 10 16:11:25] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 1 [ 92]: Via: SIP/2.0/UDP 192.168.4.155:5060;rport=5060;received=192.168.4.155;branch=z9hG4bK7bb7b0a1 [Apr 10 16:11:25] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 2 [ 17]: Content-Length: 0 [Apr 10 16:11:25] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 3 [ 58]: Call-ID: 95DAB8BF-A247-424B-ABBC-818327C31118@192.168.4.11 [Apr 10 16:11:25] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 4 [ 13]: CSeq: 102 BYE [Apr 10 16:11:25] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 5 [ 49]: From: ;tag=as6a034200 [Apr 10 16:11:25] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 6 [ 35]: Server: SJphone/1.60.289a (SJ Labs) [Apr 10 16:11:25] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 7 [ 59]: To: "unknown";tag=3390393732197 --- (8 headers 0 lines) --- [Apr 10 16:11:25] DEBUG[27900]: chan_sip.c:2226 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #46 [Apr 10 16:11:25] DEBUG[27900]: chan_sip.c:2237 __sip_ack: Stopping retransmission on '95DAB8BF-A247-424B-ABBC-818327C31118@192.168.4.11' of Request 102: Match Found SIP Response message for INCOMING dialog BYE arrived Really destroying SIP dialog '16221df46b0c1cc779b6602135db084b@192.168.4.155' Method: BYE Really destroying SIP dialog '95DAB8BF-A247-424B-ABBC-818327C31118@192.168.4.11' Method: ACK [Apr 10 16:11:25] DEBUG[27900]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 101 [Apr 10 16:11:25] DEBUG[27900]: chan_sip.c:16008 sip_devicestate: Checking device state for peer 101 [Apr 10 16:11:25] DEBUG[27900]: app_queue.c:568 changethread: Device 'SIP/103' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Apr 10 16:11:25] DEBUG[27900]: app_queue.c:568 changethread: Device 'SIP/103' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Apr 10 16:11:25] DEBUG[27900]: app_queue.c:568 changethread: Device 'SIP/101' changed to state '8' (On Hold) but we don't care because they're not a member of any queue. [Apr 10 16:11:25] DEBUG[27900]: app_queue.c:568 changethread: Device 'SIP/101' changed to state '8' (On Hold) but we don't care because they're not a member of any queue. sip show inuse * User name In use Limit * Peer name In use Limit 103 0/0/0 2 102 0/0/0 2 101 0/0/1 2 *CLI> core sho[Apr 10 16:11:35] DEBUG[27900]: chan_sip.c:2164 __sip_autodestruct: Auto destroying SIP dialog '67A5E3DF-487C-4AD8-80E0-76048020090D@192.168.4.11' [Apr 10 16:11:35] DEBUG[27900]: chan_sip.c:3404 sip_destroy: Destroying SIP dialog 67A5E3DF-487C-4AD8-80E0-76048020090D@192.168.4.11 Really destroying SIP dialog '67A5E3DF-487C-4AD8-80E0-76048020090D@192.168.4.11' Method: OPTIONS w hints -= Registered Asterisk Dial Plan Hints =- 103@from-sip : SIP/103 State:Idle Watchers 0 102@from-sip : SIP/102 State:Unavailable Watchers 0 101@from-sip : SIP/101 State:Hold Watchers 0 ---------------- - 3 hints registered *CLI> core show version Asterisk SVN-trunk-r61184 built by root @ asterisktest on a i686 running Linux on 2007-04-10 12:41:46 UTC *CLI> <--- SIP read from 192.168.4.11:5060 ---> OPTIONS sip:192.168.4.155:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.4.11;rport;branch=z9hG4bKc0a8040b00000008461ba87c00007df00000004a Content-Length: 0 Call-ID: 67A5E3DF-487C-4AD8-80E0-76048020090D@192.168.4.11 CSeq: 16 OPTIONS From: ;tag=3397559321615 Max-Forwards: 70 To: <-------------> [Apr 10 16:11:43] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 0 [ 38]: OPTIONS sip:192.168.4.155:5060 SIP/2.0 [Apr 10 16:11:43] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 1 [ 90]: Via: SIP/2.0/UDP 192.168.4.11;rport;branch=z9hG4bKc0a8040b00000008461ba87c00007df00000004a [Apr 10 16:11:43] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 2 [ 17]: Content-Length: 0 [Apr 10 16:11:43] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 3 [ 58]: Call-ID: 67A5E3DF-487C-4AD8-80E0-76048020090D@192.168.4.11 [Apr 10 16:11:43] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 4 [ 16]: CSeq: 16 OPTIONS [Apr 10 16:11:43] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 5 [ 52]: From: ;tag=3397559321615 [Apr 10 16:11:43] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 6 [ 16]: Max-Forwards: 70 [Apr 10 16:11:43] DEBUG[27900]: chan_sip.c:4944 parse_request: Header 7 [ 28]: To: --- (8 headers 0 lines) --- [Apr 10 16:11:43] DEBUG[27900]: chan_sip.c:4666 sip_alloc: Allocating new SIP dialog for 67A5E3DF-487C-4AD8-80E0-76048020090D@192.168.4.11 - OPTIONS (No RTP) [Apr 10 16:11:43] DEBUG[27900]: chan_sip.c:15375 handle_request: **** Received OPTIONS (3) - Command in SIP OPTIONS Looking for s in default (domain 192.168.4.155) <--- Transmitting (no NAT) to 192.168.4.11:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.4.11;branch=z9hG4bKc0a8040b00000008461ba87c00007df00000004a;received=192.168.4.11;rport=5060 From: ;tag=3397559321615 To: ;tag=as47bb8171 Call-ID: 67A5E3DF-487C-4AD8-80E0-76048020090D@192.168.4.11 CSeq: 16 OPTIONS User-Agent: Asterisk PBX SVN-trunk-r61184 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Accept: application/sdp Content-Length: 0 <------------> Scheduling destruction of SIP dialog '67A5E3DF-487C-4AD8-80E0-76048020090D@192.168.4.11' in 32000 ms (Method: OPTIONS) *CLI> stop now