# Activate debugging *CLI> core set debug 99999 Core debug was 0 and is now 99999 *CLI> sip set debug on SIP Debugging enabled *CLI> *CLI> [Oct 17 09:46:10] DEBUG[23569]: chan_sip.c:4515 __sip_autodestruct: Auto destroying SIP dialog '6de01c274fc6c610061669f85db2123d@85.255.197.100:5060' [Oct 17 09:46:10] DEBUG[23569]: chan_sip.c:6959 sip_destroy: Destroying SIP dialog 6de01c274fc6c610061669f85db2123d@85.255.197.100:5060 Really destroying SIP dialog '6de01c274fc6c610061669f85db2123d@85.255.197.100:5060' Method: OPTIONS [Oct 17 09:46:28] DEBUG[23549]: threadpool.c:1104 worker_idle: Worker thread idle timeout reached. Dying. [Oct 17 09:46:28] DEBUG[23548]: threadpool.c:1104 worker_idle: Worker thread idle timeout reached. Dying. [Oct 17 09:46:28] DEBUG[23547]: threadpool.c:1104 worker_idle: Worker thread idle timeout reached. Dying. [Oct 17 09:46:28] DEBUG[23546]: threadpool.c:1104 worker_idle: Worker thread idle timeout reached. Dying. [Oct 17 09:46:28] DEBUG[23543]: threadpool.c:965 worker_thread_destroy: Destroying worker thread 4 [Oct 17 09:46:28] DEBUG[23543]: threadpool.c:965 worker_thread_destroy: Destroying worker thread 3 [Oct 17 09:46:28] DEBUG[23543]: threadpool.c:965 worker_thread_destroy: Destroying worker thread 2 [Oct 17 09:46:28] DEBUG[23543]: threadpool.c:965 worker_thread_destroy: Destroying worker thread 1 [Oct 17 09:46:28] DEBUG[23550]: threadpool.c:1104 worker_idle: Worker thread idle timeout reached. Dying. [Oct 17 09:46:28] DEBUG[23527]: threadpool.c:965 worker_thread_destroy: Destroying worker thread 5 [Oct 17 09:46:29] DEBUG[23545]: threadpool.c:1104 worker_idle: Worker thread idle timeout reached. Dying. [Oct 17 09:46:29] DEBUG[23543]: threadpool.c:965 worker_thread_destroy: Destroying worker thread 0 #Login user wilbert *CLI> [Oct 17 09:46:50] DEBUG[23614]: http.c:696 handle_uri: HTTP Request URI is /ws [Oct 17 09:46:50] DEBUG[23614]: http.c:746 handle_uri: match request [ws] with handler [httpstatus] len 10 [Oct 17 09:46:50] DEBUG[23614]: http.c:746 handle_uri: match request [ws] with handler [phoneprov] len 9 [Oct 17 09:46:50] DEBUG[23614]: http.c:746 handle_uri: match request [ws] with handler [static] len 6 [Oct 17 09:46:50] DEBUG[23614]: http.c:746 handle_uri: match request [ws] with handler [ws] len 2 [Oct 17 09:46:50] DEBUG[23614]: http.c:762 handle_uri: Match made with [ws] == WebSocket connection from '192.168.16.187:49235' for protocol 'sip' accepted using version '13' <--- SIP read from WS:192.168.16.187:49235 ---> REGISTER sip:demoasterisk.incubaid.com SIP/2.0 Via: SIP/2.0/WSS df7jal23ls0d.invalid;branch=z9hG4bKTI4ChEe9dVMl5OTHTQ1uvOBGLGmAWKw7;rport From: "Wilbert";tag=hU8TfGSy4EMLSfgNBOEx To: "Wilbert" Contact: "Wilbert";expires=200;click2call=no;+g.oma.sip-im;+audio;language="en,fr" Call-ID: b006e3ed-3849-a165-6a17-97ee7f9d288f CSeq: 17649 REGISTER Content-Length: 0 Max-Forwards: 70 User-Agent: IM-client/OMA1.0 sipML5-v1.2013.08.10B Organization: Doubango Telecom Supported: path <-------------> [Oct 17 09:46:50] DEBUG[23614]: chan_sip.c:9809 parse_request: Header 0 [ 46]: REGISTER sip:demoasterisk.incubaid.com SIP/2.0 [Oct 17 09:46:50] DEBUG[23614]: chan_sip.c:9809 parse_request: Header 1 [ 90]: Via: SIP/2.0/WSS df7jal23ls0d.invalid;branch=z9hG4bKTI4ChEe9dVMl5OTHTQ1uvOBGLGmAWKw7;rport [Oct 17 09:46:50] DEBUG[23614]: chan_sip.c:9809 parse_request: Header 2 [ 79]: From: "Wilbert";tag=hU8TfGSy4EMLSfgNBOEx [Oct 17 09:46:50] DEBUG[23614]: chan_sip.c:9809 parse_request: Header 3 [ 52]: To: "Wilbert" [Oct 17 09:46:50] DEBUG[23614]: chan_sip.c:9809 parse_request: Header 4 [150]: Contact: "Wilbert";expires=200;click2call=no;+g.oma.sip-im;+audio;language="en,fr" [Oct 17 09:46:50] DEBUG[23614]: chan_sip.c:9809 parse_request: Header 5 [ 45]: Call-ID: b006e3ed-3849-a165-6a17-97ee7f9d288f [Oct 17 09:46:50] DEBUG[23614]: chan_sip.c:9809 parse_request: Header 6 [ 20]: CSeq: 17649 REGISTER [Oct 17 09:46:50] DEBUG[23614]: chan_sip.c:9809 parse_request: Header 7 [ 17]: Content-Length: 0 [Oct 17 09:46:50] DEBUG[23614]: chan_sip.c:9809 parse_request: Header 8 [ 16]: Max-Forwards: 70 [Oct 17 09:46:50] DEBUG[23614]: chan_sip.c:9809 parse_request: Header 9 [ 50]: User-Agent: IM-client/OMA1.0 sipML5-v1.2013.08.10B [Oct 17 09:46:50] DEBUG[23614]: chan_sip.c:9809 parse_request: Header 10 [ 30]: Organization: Doubango Telecom [Oct 17 09:46:50] DEBUG[23614]: chan_sip.c:9809 parse_request: Header 11 [ 15]: Supported: path --- (12 headers 0 lines) --- [Oct 17 09:46:50] DEBUG[23614]: chan_sip.c:9359 find_call: = Looking for Call ID: b006e3ed-3849-a165-6a17-97ee7f9d288f (Checking From) --From tag hU8TfGSy4EMLSfgNBOEx --To-tag [Oct 17 09:46:50] DEBUG[23614]: acl.c:920 ast_ouraddrfor: For destination '192.168.16.187', our source address is '10.101.0.4'. [Oct 17 09:46:50] DEBUG[23614]: chan_sip.c:4124 ast_sip_ouraddrfor: Setting AST_TRANSPORT_WS with address 10.101.0.4:5060 [Oct 17 09:46:50] DEBUG[23614]: chan_sip.c:8947 sip_alloc: Allocating new SIP dialog for b006e3ed-3849-a165-6a17-97ee7f9d288f - REGISTER (No RTP) [Oct 17 09:46:50] DEBUG[23614]: chan_sip.c:28051 handle_incoming: **** Received REGISTER (2) - Command in SIP REGISTER [Oct 17 09:46:50] DEBUG[23614]: chan_sip.c:27873 handle_request_register: Initializing initreq for method REGISTER - callid b006e3ed-3849-a165-6a17-97ee7f9d288f [Oct 17 09:46:50] DEBUG[23614]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting 'demoasterisk.incubaid.com' into... [Oct 17 09:46:50] DEBUG[23614]: netsock2.c:192 ast_sockaddr_split_hostport: ...host 'demoasterisk.incubaid.com' and port ''. <--- Transmitting (no NAT) to 192.168.16.187:5060 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/WSS df7jal23ls0d.invalid;branch=z9hG4bKTI4ChEe9dVMl5OTHTQ1uvOBGLGmAWKw7;rport;received=192.168.16.187 From: "Wilbert";tag=hU8TfGSy4EMLSfgNBOEx To: "Wilbert";tag=as7183d73e Call-ID: b006e3ed-3849-a165-6a17-97ee7f9d288f CSeq: 17649 REGISTER Server: Asterisk demo PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer WWW-Authenticate: Digest algorithm=MD5, realm="demoasterisk.incubaid.com", nonce="7c69e93c" Content-Length: 0 <------------> [Oct 17 09:46:50] DEBUG[23614]: chan_sip.c:3967 __sip_xmit: Trying to put 'SIP/2.0 401' onto WS socket destined for 192.168.16.187:5060 Scheduling destruction of SIP dialog 'b006e3ed-3849-a165-6a17-97ee7f9d288f' in 32000 ms (Method: REGISTER) <--- SIP read from WS:192.168.16.187:49235 ---> REGISTER sip:demoasterisk.incubaid.com SIP/2.0 Via: SIP/2.0/WSS df7jal23ls0d.invalid;branch=z9hG4bKEpyTf1V7lwLqzpoTiM15Cy7BnH2pfWGX;rport From: "Wilbert";tag=hU8TfGSy4EMLSfgNBOEx To: "Wilbert" Contact: "Wilbert";expires=200;click2call=no;+g.oma.sip-im;+audio;language="en,fr" Call-ID: b006e3ed-3849-a165-6a17-97ee7f9d288f CSeq: 17650 REGISTER Content-Length: 0 Max-Forwards: 70 Authorization: Digest username="wilbert",realm="demoasterisk.incubaid.com",nonce="7c69e93c",uri="sip:demoasterisk.incubaid.com",response="176ec26cc1d97bd77ac62b6b2736708a",algorithm=MD5 User-Agent: IM-client/OMA1.0 sipML5-v1.2013.08.10B Organization: Doubango Telecom Supported: path <-------------> [Oct 17 09:46:50] DEBUG[23614]: chan_sip.c:9809 parse_request: Header 0 [ 46]: REGISTER sip:demoasterisk.incubaid.com SIP/2.0 [Oct 17 09:46:50] DEBUG[23614]: chan_sip.c:9809 parse_request: Header 1 [ 90]: Via: SIP/2.0/WSS df7jal23ls0d.invalid;branch=z9hG4bKEpyTf1V7lwLqzpoTiM15Cy7BnH2pfWGX;rport [Oct 17 09:46:50] DEBUG[23614]: chan_sip.c:9809 parse_request: Header 2 [ 79]: From: "Wilbert";tag=hU8TfGSy4EMLSfgNBOEx [Oct 17 09:46:50] DEBUG[23614]: chan_sip.c:9809 parse_request: Header 3 [ 52]: To: "Wilbert" [Oct 17 09:46:50] DEBUG[23614]: chan_sip.c:9809 parse_request: Header 4 [150]: Contact: "Wilbert";expires=200;click2call=no;+g.oma.sip-im;+audio;language="en,fr" [Oct 17 09:46:50] DEBUG[23614]: chan_sip.c:9809 parse_request: Header 5 [ 45]: Call-ID: b006e3ed-3849-a165-6a17-97ee7f9d288f [Oct 17 09:46:50] DEBUG[23614]: chan_sip.c:9809 parse_request: Header 6 [ 20]: CSeq: 17650 REGISTER [Oct 17 09:46:50] DEBUG[23614]: chan_sip.c:9809 parse_request: Header 7 [ 17]: Content-Length: 0 [Oct 17 09:46:50] DEBUG[23614]: chan_sip.c:9809 parse_request: Header 8 [ 16]: Max-Forwards: 70 [Oct 17 09:46:50] DEBUG[23614]: chan_sip.c:9809 parse_request: Header 9 [185]: Authorization: Digest username="wilbert",realm="demoasterisk.incubaid.com",nonce="7c69e93c",uri="sip:demoasterisk.incubaid.com",response="176ec26cc1d97bd77ac62b6b2736708a",algorithm=MD5 [Oct 17 09:46:50] DEBUG[23614]: chan_sip.c:9809 parse_request: Header 10 [ 50]: User-Agent: IM-client/OMA1.0 sipML5-v1.2013.08.10B [Oct 17 09:46:50] DEBUG[23614]: chan_sip.c:9809 parse_request: Header 11 [ 30]: Organization: Doubango Telecom [Oct 17 09:46:50] DEBUG[23614]: chan_sip.c:9809 parse_request: Header 12 [ 15]: Supported: path --- (13 headers 0 lines) --- [Oct 17 09:46:50] DEBUG[23614]: chan_sip.c:9359 find_call: = Looking for Call ID: b006e3ed-3849-a165-6a17-97ee7f9d288f (Checking From) --From tag hU8TfGSy4EMLSfgNBOEx --To-tag [Oct 17 09:46:50] DEBUG[23614]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting 'demoasterisk.incubaid.com' into... [Oct 17 09:46:50] DEBUG[23614]: netsock2.c:192 ast_sockaddr_split_hostport: ...host 'demoasterisk.incubaid.com' and port ''. [Oct 17 09:46:50] DEBUG[23614]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting 'demoasterisk.incubaid.com' into... [Oct 17 09:46:50] DEBUG[23614]: netsock2.c:192 ast_sockaddr_split_hostport: ...host 'demoasterisk.incubaid.com' and port ''. [Oct 17 09:46:50] DEBUG[23614]: chan_sip.c:28051 handle_incoming: **** Received REGISTER (2) - Command in SIP REGISTER [Oct 17 09:46:50] DEBUG[23614]: chan_sip.c:27873 handle_request_register: Initializing initreq for method REGISTER - callid b006e3ed-3849-a165-6a17-97ee7f9d288f [Oct 17 09:46:50] DEBUG[23614]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting 'demoasterisk.incubaid.com' into... [Oct 17 09:46:50] DEBUG[23614]: netsock2.c:192 ast_sockaddr_split_hostport: ...host 'demoasterisk.incubaid.com' and port ''. [Oct 17 09:46:50] DEBUG[23614]: chan_sip.c:17272 register_verify: peer 'wilbert' has contacted us over WS even though we prefer UDP. [Oct 17 09:46:50] DEBUG[23614]: chan_sip.c:16232 parse_register_contact: Store REGISTER's src-IP:port for call routing. [Oct 17 09:46:50] DEBUG[23614]: chan_sip.c:16551 build_path: build_path: do not use Path headers -- Registered SIP 'wilbert' at 192.168.16.187:49235 > Saved useragent "IM-client/OMA1.0 sipML5-v1.2013.08.10B" for peer wilbert <--- Transmitting (no NAT) to 192.168.16.187:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/WSS df7jal23ls0d.invalid;branch=z9hG4bKEpyTf1V7lwLqzpoTiM15Cy7BnH2pfWGX;rport;received=192.168.16.187 From: "Wilbert";tag=hU8TfGSy4EMLSfgNBOEx To: "Wilbert";tag=as7183d73e Call-ID: b006e3ed-3849-a165-6a17-97ee7f9d288f CSeq: 17650 REGISTER Server: Asterisk demo PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Expires: 200 Contact: ;expires=200 Date: Thu, 17 Oct 2013 07:46:50 GMT Content-Length: 0 <------------> [Oct 17 09:46:50] DEBUG[23614]: chan_sip.c:3967 __sip_xmit: Trying to put 'SIP/2.0 200' onto WS socket destined for 192.168.16.187:5060 [Oct 17 09:46:50] DEBUG[23537]: devicestate.c:332 _ast_device_state: No provider found, checking channel drivers for SIP - wilbert [Oct 17 09:46:50] DEBUG[23537]: chan_sip.c:29564 sip_devicestate: Checking device state for peer wilbert [Oct 17 09:46:50] DEBUG[23537]: devicestate.c:425 do_state_change: Changing state for SIP/wilbert - state 1 (Not in use) [Oct 17 09:46:50] DEBUG[23530]: devicestate.c:641 devstate_change_collector_cb: Processing device state change for 'SIP/wilbert' [Oct 17 09:46:50] DEBUG[23530]: devicestate.c:536 devstate_change_aggregator_cb: Adding per-server state of 'Not in use' for 'SIP/wilbert' [Oct 17 09:46:50] DEBUG[23530]: devicestate.c:651 devstate_change_collector_cb: Aggregate devstate result is 'Not in use' for 'SIP/wilbert' [Oct 17 09:46:50] DEBUG[23530]: devicestate.c:662 devstate_change_collector_cb: Aggregate state for device 'SIP/wilbert' has changed to 'Not in use' [Oct 17 09:46:50] DEBUG[23601]: app_queue.c:2312 device_state_cb: Device 'SIP/wilbert' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. Scheduling destruction of SIP dialog 'b006e3ed-3849-a165-6a17-97ee7f9d288f' in 32000 ms (Method: REGISTER) *CLI> # Login user somerst *CLI> [Oct 17 09:47:10] DEBUG[23569]: chan_sip.c:4515 __sip_autodestruct: Auto destroying SIP dialog '7abe43e56f3921401d76153d5d0b63f1@85.255.197.100:5060' [Oct 17 09:47:10] DEBUG[23569]: chan_sip.c:6959 sip_destroy: Destroying SIP dialog 7abe43e56f3921401d76153d5d0b63f1@85.255.197.100:5060 Really destroying SIP dialog '7abe43e56f3921401d76153d5d0b63f1@85.255.197.100:5060' Method: OPTIONS [Oct 17 09:47:13] DEBUG[23619]: http.c:696 handle_uri: HTTP Request URI is /ws [Oct 17 09:47:13] DEBUG[23619]: http.c:746 handle_uri: match request [ws] with handler [httpstatus] len 10 [Oct 17 09:47:13] DEBUG[23619]: http.c:746 handle_uri: match request [ws] with handler [phoneprov] len 9 [Oct 17 09:47:13] DEBUG[23619]: http.c:746 handle_uri: match request [ws] with handler [static] len 6 [Oct 17 09:47:13] DEBUG[23619]: http.c:746 handle_uri: match request [ws] with handler [ws] len 2 [Oct 17 09:47:13] DEBUG[23619]: http.c:762 handle_uri: Match made with [ws] == WebSocket connection from '192.168.16.110:36570' for protocol 'sip' accepted using version '13' <--- SIP read from WS:192.168.16.110:36570 ---> REGISTER sip:demoasterisk.incubaid.com SIP/2.0 Via: SIP/2.0/WSS df7jal23ls0d.invalid;branch=z9hG4bK7DRdrSE9aZ8Nnh16dwk75iFC9Ov5mEVX;rport From: "Tim";tag=BImw6Z49OZlOHtwJ4PA6 To: "Tim" Contact: "Tim";expires=200;click2call=no;+g.oma.sip-im;+audio;language="en,fr" Call-ID: 9dcf2771-a654-c799-07ca-bbf943cb2889 CSeq: 52944 REGISTER Content-Length: 0 Max-Forwards: 70 User-Agent: IM-client/OMA1.0 sipML5-v1.2013.08.10B Organization: Doubango Telecom Supported: path <-------------> [Oct 17 09:47:13] DEBUG[23619]: chan_sip.c:9809 parse_request: Header 0 [ 46]: REGISTER sip:demoasterisk.incubaid.com SIP/2.0 [Oct 17 09:47:13] DEBUG[23619]: chan_sip.c:9809 parse_request: Header 1 [ 90]: Via: SIP/2.0/WSS df7jal23ls0d.invalid;branch=z9hG4bK7DRdrSE9aZ8Nnh16dwk75iFC9Ov5mEVX;rport [Oct 17 09:47:13] DEBUG[23619]: chan_sip.c:9809 parse_request: Header 2 [ 75]: From: "Tim";tag=BImw6Z49OZlOHtwJ4PA6 [Oct 17 09:47:13] DEBUG[23619]: chan_sip.c:9809 parse_request: Header 3 [ 48]: To: "Tim" [Oct 17 09:47:13] DEBUG[23619]: chan_sip.c:9809 parse_request: Header 4 [146]: Contact: "Tim";expires=200;click2call=no;+g.oma.sip-im;+audio;language="en,fr" [Oct 17 09:47:13] DEBUG[23619]: chan_sip.c:9809 parse_request: Header 5 [ 45]: Call-ID: 9dcf2771-a654-c799-07ca-bbf943cb2889 [Oct 17 09:47:13] DEBUG[23619]: chan_sip.c:9809 parse_request: Header 6 [ 20]: CSeq: 52944 REGISTER [Oct 17 09:47:13] DEBUG[23619]: chan_sip.c:9809 parse_request: Header 7 [ 17]: Content-Length: 0 [Oct 17 09:47:13] DEBUG[23619]: chan_sip.c:9809 parse_request: Header 8 [ 16]: Max-Forwards: 70 [Oct 17 09:47:13] DEBUG[23619]: chan_sip.c:9809 parse_request: Header 9 [ 50]: User-Agent: IM-client/OMA1.0 sipML5-v1.2013.08.10B [Oct 17 09:47:13] DEBUG[23619]: chan_sip.c:9809 parse_request: Header 10 [ 30]: Organization: Doubango Telecom [Oct 17 09:47:13] DEBUG[23619]: chan_sip.c:9809 parse_request: Header 11 [ 15]: Supported: path --- (12 headers 0 lines) --- [Oct 17 09:47:13] DEBUG[23619]: chan_sip.c:9359 find_call: = Looking for Call ID: 9dcf2771-a654-c799-07ca-bbf943cb2889 (Checking From) --From tag BImw6Z49OZlOHtwJ4PA6 --To-tag [Oct 17 09:47:13] DEBUG[23619]: acl.c:920 ast_ouraddrfor: For destination '192.168.16.110', our source address is '10.101.0.4'. [Oct 17 09:47:13] DEBUG[23619]: chan_sip.c:4124 ast_sip_ouraddrfor: Setting AST_TRANSPORT_WS with address 10.101.0.4:5060 [Oct 17 09:47:13] DEBUG[23619]: chan_sip.c:8947 sip_alloc: Allocating new SIP dialog for 9dcf2771-a654-c799-07ca-bbf943cb2889 - REGISTER (No RTP) [Oct 17 09:47:13] DEBUG[23619]: chan_sip.c:28051 handle_incoming: **** Received REGISTER (2) - Command in SIP REGISTER [Oct 17 09:47:13] DEBUG[23619]: chan_sip.c:27873 handle_request_register: Initializing initreq for method REGISTER - callid 9dcf2771-a654-c799-07ca-bbf943cb2889 [Oct 17 09:47:13] DEBUG[23619]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting 'demoasterisk.incubaid.com' into... [Oct 17 09:47:13] DEBUG[23619]: netsock2.c:192 ast_sockaddr_split_hostport: ...host 'demoasterisk.incubaid.com' and port ''. <--- Transmitting (no NAT) to 192.168.16.110:5060 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/WSS df7jal23ls0d.invalid;branch=z9hG4bK7DRdrSE9aZ8Nnh16dwk75iFC9Ov5mEVX;rport;received=192.168.16.110 From: "Tim";tag=BImw6Z49OZlOHtwJ4PA6 To: "Tim";tag=as49548b04 Call-ID: 9dcf2771-a654-c799-07ca-bbf943cb2889 CSeq: 52944 REGISTER Server: Asterisk demo PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer WWW-Authenticate: Digest algorithm=MD5, realm="demoasterisk.incubaid.com", nonce="6d3cd265" Content-Length: 0 <------------> [Oct 17 09:47:13] DEBUG[23619]: chan_sip.c:3967 __sip_xmit: Trying to put 'SIP/2.0 401' onto WS socket destined for 192.168.16.110:5060 Scheduling destruction of SIP dialog '9dcf2771-a654-c799-07ca-bbf943cb2889' in 32000 ms (Method: REGISTER) <--- SIP read from WS:192.168.16.110:36570 ---> REGISTER sip:demoasterisk.incubaid.com SIP/2.0 Via: SIP/2.0/WSS df7jal23ls0d.invalid;branch=z9hG4bKNUwAWbVNtDe9zKbNrrTUAvAWQNK3WvHC;rport From: "Tim";tag=BImw6Z49OZlOHtwJ4PA6 To: "Tim" Contact: "Tim";expires=200;click2call=no;+g.oma.sip-im;+audio;language="en,fr" Call-ID: 9dcf2771-a654-c799-07ca-bbf943cb2889 CSeq: 52945 REGISTER Content-Length: 0 Max-Forwards: 70 Authorization: Digest username="somerst",realm="demoasterisk.incubaid.com",nonce="6d3cd265",uri="sip:demoasterisk.incubaid.com",response="d7c5a3d33ca1da5c142c36bacab25ff4",algorithm=MD5 User-Agent: IM-client/OMA1.0 sipML5-v1.2013.08.10B Organization: Doubango Telecom Supported: path <-------------> [Oct 17 09:47:13] DEBUG[23619]: chan_sip.c:9809 parse_request: Header 0 [ 46]: REGISTER sip:demoasterisk.incubaid.com SIP/2.0 [Oct 17 09:47:13] DEBUG[23619]: chan_sip.c:9809 parse_request: Header 1 [ 90]: Via: SIP/2.0/WSS df7jal23ls0d.invalid;branch=z9hG4bKNUwAWbVNtDe9zKbNrrTUAvAWQNK3WvHC;rport [Oct 17 09:47:13] DEBUG[23619]: chan_sip.c:9809 parse_request: Header 2 [ 75]: From: "Tim";tag=BImw6Z49OZlOHtwJ4PA6 [Oct 17 09:47:13] DEBUG[23619]: chan_sip.c:9809 parse_request: Header 3 [ 48]: To: "Tim" [Oct 17 09:47:13] DEBUG[23619]: chan_sip.c:9809 parse_request: Header 4 [146]: Contact: "Tim";expires=200;click2call=no;+g.oma.sip-im;+audio;language="en,fr" [Oct 17 09:47:13] DEBUG[23619]: chan_sip.c:9809 parse_request: Header 5 [ 45]: Call-ID: 9dcf2771-a654-c799-07ca-bbf943cb2889 [Oct 17 09:47:13] DEBUG[23619]: chan_sip.c:9809 parse_request: Header 6 [ 20]: CSeq: 52945 REGISTER [Oct 17 09:47:13] DEBUG[23619]: chan_sip.c:9809 parse_request: Header 7 [ 17]: Content-Length: 0 [Oct 17 09:47:13] DEBUG[23619]: chan_sip.c:9809 parse_request: Header 8 [ 16]: Max-Forwards: 70 [Oct 17 09:47:13] DEBUG[23619]: chan_sip.c:9809 parse_request: Header 9 [185]: Authorization: Digest username="somerst",realm="demoasterisk.incubaid.com",nonce="6d3cd265",uri="sip:demoasterisk.incubaid.com",response="d7c5a3d33ca1da5c142c36bacab25ff4",algorithm=MD5 [Oct 17 09:47:13] DEBUG[23619]: chan_sip.c:9809 parse_request: Header 10 [ 50]: User-Agent: IM-client/OMA1.0 sipML5-v1.2013.08.10B [Oct 17 09:47:13] DEBUG[23619]: chan_sip.c:9809 parse_request: Header 11 [ 30]: Organization: Doubango Telecom [Oct 17 09:47:13] DEBUG[23619]: chan_sip.c:9809 parse_request: Header 12 [ 15]: Supported: path --- (13 headers 0 lines) --- [Oct 17 09:47:13] DEBUG[23619]: chan_sip.c:9359 find_call: = Looking for Call ID: 9dcf2771-a654-c799-07ca-bbf943cb2889 (Checking From) --From tag BImw6Z49OZlOHtwJ4PA6 --To-tag [Oct 17 09:47:13] DEBUG[23619]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting 'demoasterisk.incubaid.com' into... [Oct 17 09:47:13] DEBUG[23619]: netsock2.c:192 ast_sockaddr_split_hostport: ...host 'demoasterisk.incubaid.com' and port ''. [Oct 17 09:47:13] DEBUG[23619]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting 'demoasterisk.incubaid.com' into... [Oct 17 09:47:13] DEBUG[23619]: netsock2.c:192 ast_sockaddr_split_hostport: ...host 'demoasterisk.incubaid.com' and port ''. [Oct 17 09:47:13] DEBUG[23619]: chan_sip.c:28051 handle_incoming: **** Received REGISTER (2) - Command in SIP REGISTER [Oct 17 09:47:13] DEBUG[23619]: chan_sip.c:27873 handle_request_register: Initializing initreq for method REGISTER - callid 9dcf2771-a654-c799-07ca-bbf943cb2889 [Oct 17 09:47:13] DEBUG[23619]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting 'demoasterisk.incubaid.com' into... [Oct 17 09:47:13] DEBUG[23619]: netsock2.c:192 ast_sockaddr_split_hostport: ...host 'demoasterisk.incubaid.com' and port ''. [Oct 17 09:47:13] DEBUG[23619]: chan_sip.c:17272 register_verify: peer 'somerst' has contacted us over WS even though we prefer UDP. [Oct 17 09:47:13] DEBUG[23619]: chan_sip.c:16232 parse_register_contact: Store REGISTER's src-IP:port for call routing. [Oct 17 09:47:13] DEBUG[23619]: chan_sip.c:16551 build_path: build_path: do not use Path headers -- Registered SIP 'somerst' at 192.168.16.110:36570 > Saved useragent "IM-client/OMA1.0 sipML5-v1.2013.08.10B" for peer somerst <--- Transmitting (no NAT) to 192.168.16.110:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/WSS df7jal23ls0d.invalid;branch=z9hG4bKNUwAWbVNtDe9zKbNrrTUAvAWQNK3WvHC;rport;received=192.168.16.110 From: "Tim";tag=BImw6Z49OZlOHtwJ4PA6 To: "Tim";tag=as49548b04 Call-ID: 9dcf2771-a654-c799-07ca-bbf943cb2889 CSeq: 52945 REGISTER Server: Asterisk demo PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Expires: 200 Contact: ;expires=200 Date: Thu, 17 Oct 2013 07:47:13 GMT Content-Length: 0 <------------> [Oct 17 09:47:13] DEBUG[23619]: chan_sip.c:3967 __sip_xmit: Trying to put 'SIP/2.0 200' onto WS socket destined for 192.168.16.110:5060 [Oct 17 09:47:13] DEBUG[23537]: devicestate.c:332 _ast_device_state: No provider found, checking channel drivers for SIP - somerst [Oct 17 09:47:13] DEBUG[23537]: chan_sip.c:29564 sip_devicestate: Checking device state for peer somerst [Oct 17 09:47:13] DEBUG[23537]: devicestate.c:425 do_state_change: Changing state for SIP/somerst - state 1 (Not in use) [Oct 17 09:47:13] DEBUG[23530]: devicestate.c:641 devstate_change_collector_cb: Processing device state change for 'SIP/somerst' [Oct 17 09:47:13] DEBUG[23530]: devicestate.c:536 devstate_change_aggregator_cb: Adding per-server state of 'Not in use' for 'SIP/somerst' [Oct 17 09:47:13] DEBUG[23530]: devicestate.c:651 devstate_change_collector_cb: Aggregate devstate result is 'Not in use' for 'SIP/somerst' [Oct 17 09:47:13] DEBUG[23530]: devicestate.c:662 devstate_change_collector_cb: Aggregate state for device 'SIP/somerst' has changed to 'Not in use' [Oct 17 09:47:13] DEBUG[23601]: app_queue.c:2312 device_state_cb: Device 'SIP/somerst' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. Scheduling destruction of SIP dialog '9dcf2771-a654-c799-07ca-bbf943cb2889' in 32000 ms (Method: REGISTER) *CLI> *CLI> [Oct 17 09:47:22] DEBUG[23569]: chan_sip.c:4515 __sip_autodestruct: Auto destroying SIP dialog 'b006e3ed-3849-a165-6a17-97ee7f9d288f' [Oct 17 09:47:22] DEBUG[23569]: chan_sip.c:6959 sip_destroy: Destroying SIP dialog b006e3ed-3849-a165-6a17-97ee7f9d288f Really destroying SIP dialog 'b006e3ed-3849-a165-6a17-97ee7f9d288f' Method: REGISTER <--- SIP read from UDP:172.19.0.42:5060 ---> OPTIONS sip:s@10.101.0.4:5060 SIP/2.0 Via: SIP/2.0/UDP 85.255.197.100:5060;branch=z9hG4bK1552df2c;rport Max-Forwards: 70 From: "asterisk" ;tag=as1363f3e6 To: Contact: Call-ID: 50d99dd666001e596e4e054f37ec712a@85.255.197.100:5060 CSeq: 102 OPTIONS User-Agent: Asterisk PBX 1.8.13.1~dfsg-3+deb7u1 Date: Thu, 17 Oct 2013 07:47:37 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Length: 0 <-------------> [Oct 17 09:47:38] DEBUG[23569]: chan_sip.c:9809 parse_request: Header 0 [ 37]: OPTIONS sip:s@10.101.0.4:5060 SIP/2.0 [Oct 17 09:47:38] DEBUG[23569]: chan_sip.c:9809 parse_request: Header 1 [ 65]: Via: SIP/2.0/UDP 85.255.197.100:5060;branch=z9hG4bK1552df2c;rport [Oct 17 09:47:38] DEBUG[23569]: chan_sip.c:9809 parse_request: Header 2 [ 16]: Max-Forwards: 70 [Oct 17 09:47:38] DEBUG[23569]: chan_sip.c:9809 parse_request: Header 3 [ 61]: From: "asterisk" ;tag=as1363f3e6 [Oct 17 09:47:38] DEBUG[23569]: chan_sip.c:9809 parse_request: Header 4 [ 27]: To: [Oct 17 09:47:38] DEBUG[23569]: chan_sip.c:9809 parse_request: Header 5 [ 43]: Contact: [Oct 17 09:47:38] DEBUG[23569]: chan_sip.c:9809 parse_request: Header 6 [ 61]: Call-ID: 50d99dd666001e596e4e054f37ec712a@85.255.197.100:5060 [Oct 17 09:47:38] DEBUG[23569]: chan_sip.c:9809 parse_request: Header 7 [ 17]: CSeq: 102 OPTIONS [Oct 17 09:47:38] DEBUG[23569]: chan_sip.c:9809 parse_request: Header 8 [ 47]: User-Agent: Asterisk PBX 1.8.13.1~dfsg-3+deb7u1 [Oct 17 09:47:38] DEBUG[23569]: chan_sip.c:9809 parse_request: Header 9 [ 35]: Date: Thu, 17 Oct 2013 07:47:37 GMT [Oct 17 09:47:38] DEBUG[23569]: chan_sip.c:9809 parse_request: Header 10 [ 81]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH [Oct 17 09:47:38] DEBUG[23569]: chan_sip.c:9809 parse_request: Header 11 [ 26]: Supported: replaces, timer [Oct 17 09:47:38] DEBUG[23569]: chan_sip.c:9809 parse_request: Header 12 [ 17]: Content-Length: 0 --- (13 headers 0 lines) --- [Oct 17 09:47:38] DEBUG[23569]: chan_sip.c:9359 find_call: = Looking for Call ID: 50d99dd666001e596e4e054f37ec712a@85.255.197.100:5060 (Checking From) --From tag as1363f3e6 --To-tag [Oct 17 09:47:38] DEBUG[23569]: acl.c:920 ast_ouraddrfor: For destination '172.19.0.42', our source address is '10.101.0.4'. [Oct 17 09:47:38] DEBUG[23569]: chan_sip.c:4124 ast_sip_ouraddrfor: Setting AST_TRANSPORT_UDP with address 10.101.0.4:5060 [Oct 17 09:47:38] DEBUG[23569]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '85.255.197.100:5060' into... [Oct 17 09:47:38] DEBUG[23569]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '85.255.197.100' and port '5060'. [Oct 17 09:47:38] DEBUG[23569]: chan_sip.c:18380 check_for_nat: NAT detected for 85.255.197.100:5060 / 172.19.0.42:5060 Sending to 172.19.0.42:5060 (NAT) [Oct 17 09:47:38] DEBUG[23569]: chan_sip.c:8947 sip_alloc: Allocating new SIP dialog for 50d99dd666001e596e4e054f37ec712a@85.255.197.100:5060 - OPTIONS (No RTP) [Oct 17 09:47:38] DEBUG[23569]: chan_sip.c:28051 handle_incoming: **** Received OPTIONS (3) - Command in SIP OPTIONS [Oct 17 09:47:38] DEBUG[23569]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '10.101.0.4:5060' into... [Oct 17 09:47:38] DEBUG[23569]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '10.101.0.4' and port ''. [Oct 17 09:47:38] DEBUG[23569]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '85.255.197.100' into... [Oct 17 09:47:38] DEBUG[23569]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '85.255.197.100' and port ''. Looking for s in public (domain 10.101.0.4) <--- Transmitting (NAT) to 172.19.0.42:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 85.255.197.100:5060;branch=z9hG4bK1552df2c;received=172.19.0.42;rport=5060 From: "asterisk" ;tag=as1363f3e6 To: ;tag=as3491b295 Call-ID: 50d99dd666001e596e4e054f37ec712a@85.255.197.100:5060 CSeq: 102 OPTIONS Server: Asterisk demo PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Contact: Accept: application/sdp Content-Length: 0 <------------> [Oct 17 09:47:38] DEBUG[23569]: chan_sip.c:3967 __sip_xmit: Trying to put 'SIP/2.0 200' onto UDP socket destined for 172.19.0.42:5060 Scheduling destruction of SIP dialog '50d99dd666001e596e4e054f37ec712a@85.255.197.100:5060' in 32000 ms (Method: OPTIONS) *CLI> [Oct 17 09:47:45] DEBUG[23569]: chan_sip.c:4515 __sip_autodestruct: Auto destroying SIP dialog '9dcf2771-a654-c799-07ca-bbf943cb2889' [Oct 17 09:47:45] DEBUG[23569]: chan_sip.c:6959 sip_destroy: Destroying SIP dialog 9dcf2771-a654-c799-07ca-bbf943cb2889 Really destroying SIP dialog '9dcf2771-a654-c799-07ca-bbf943cb2889' Method: REGISTER # Call from wilbert to somerst (extension 507) *CLI> *CLI> [Oct 17 09:47:45] DEBUG[23569]: chan_sip.c:4515 __sip_autodestruct: Auto destroying SIP dialog '9dcf2771-a654-c799-07ca-bbf943cb2889' [Oct 17 09:47:45] DEBUG[23569]: chan_sip.c:6959 sip_destroy: Destroying SIP dialog 9dcf2771-a654-c799-07ca-bbf943cb2889 Really destroying SIP dialog '9dcf2771-a654-c799-07ca-bbf943cb2889' Method: REGISTER *CLI> *CLI> *CLI> [Oct 17 09:48:07] ERROR[23614]: res_http_websocket.c:412 __ast_websocket_read: Error reading from web socket! [Oct 17 09:48:10] DEBUG[23569]: chan_sip.c:4515 __sip_autodestruct: Auto destroying SIP dialog '50d99dd666001e596e4e054f37ec712a@85.255.197.100:5060' [Oct 17 09:48:10] DEBUG[23569]: chan_sip.c:6959 sip_destroy: Destroying SIP dialog 50d99dd666001e596e4e054f37ec712a@85.255.197.100:5060 Really destroying SIP dialog '50d99dd666001e596e4e054f37ec712a@85.255.197.100:5060' Method: OPTIONS