[Aug 11 16:53:12] Asterisk SVN-branch-12-r420805 built by root @ newtonr-laptop on a x86_64 running Linux on 2014-08-11 19:27:30 UTC [Aug 11 16:53:12] DEBUG[31596] config.c: Parsing /etc/asterisk/logger.conf [Aug 11 16:53:16] DEBUG[31811] http.c: HTTP opening session. Top level [Aug 11 16:53:16] DEBUG[31811] http.c: HTTP Request URI is /ws [Aug 11 16:53:16] DEBUG[31811] http.c: match request [ws] with handler [httpstatus] len 10 [Aug 11 16:53:16] DEBUG[31811] http.c: match request [ws] with handler [phoneprov] len 9 [Aug 11 16:53:16] DEBUG[31811] http.c: match request [ws] with handler [static] len 6 [Aug 11 16:53:16] DEBUG[31811] http.c: match request [ws] with handler [ari] len 3 [Aug 11 16:53:16] DEBUG[31811] http.c: match request [ws] with handler [ws] len 2 [Aug 11 16:53:16] DEBUG[31811] http.c: Match made with [ws] [Aug 11 16:53:16] VERBOSE[31811] chan_sip.c: ˙<--- SIP read from WS:10.24.17.254:37591 ---> ˙REGISTER sip:10.24.18.124 SIP/2.0 ˙Via: SIP/2.0/WS df7jal23ls0d.invalid;branch=z9hG4bKBlrIhG3rkCT68CG3rRyXQmxG6LuB9CgG;rport ˙From: "354";tag=n4pQ15uXkfQi8pTtPIHd ˙To: "354" ˙Contact: "354";expires=200;click2call=no;+g.oma.sip-im;+audio;language="en,fr" ˙Call-ID: 538aa1d2-2d44-b1be-ec14-be692c07df48 ˙CSeq: 44616 REGISTER ˙Content-Length: 0 ˙Max-Forwards: 70 ˙Authorization: Digest username="354",realm="10.24.18.124",nonce="",uri="sip:10.24.18.124",response="" ˙User-Agent: IM-client/OMA1.0 sipML5-v1.2014.04.18 ˙Organization: Doubango Telecom ˙Supported: path ˙ ˙<-------------> [Aug 11 16:53:16] DEBUG[31811] chan_sip.c: Header 0 [ 33]: REGISTER sip:10.24.18.124 SIP/2.0 [Aug 11 16:53:16] DEBUG[31811] chan_sip.c: Header 1 [ 89]: Via: SIP/2.0/WS df7jal23ls0d.invalid;branch=z9hG4bKBlrIhG3rkCT68CG3rRyXQmxG6LuB9CgG;rport [Aug 11 16:53:16] DEBUG[31811] chan_sip.c: Header 2 [ 58]: From: "354";tag=n4pQ15uXkfQi8pTtPIHd [Aug 11 16:53:16] DEBUG[31811] chan_sip.c: Header 3 [ 31]: To: "354" [Aug 11 16:53:16] DEBUG[31811] chan_sip.c: Header 4 [139]: Contact: "354";expires=200;click2call=no;+g.oma.sip-im;+audio;language="en,fr" [Aug 11 16:53:16] DEBUG[31811] chan_sip.c: Header 5 [ 45]: Call-ID: 538aa1d2-2d44-b1be-ec14-be692c07df48 [Aug 11 16:53:16] DEBUG[31811] chan_sip.c: Header 6 [ 20]: CSeq: 44616 REGISTER [Aug 11 16:53:16] DEBUG[31811] chan_sip.c: Header 7 [ 17]: Content-Length: 0 [Aug 11 16:53:16] DEBUG[31811] chan_sip.c: Header 8 [ 16]: Max-Forwards: 70 [Aug 11 16:53:16] DEBUG[31811] chan_sip.c: Header 9 [101]: Authorization: Digest username="354",realm="10.24.18.124",nonce="",uri="sip:10.24.18.124",response="" [Aug 11 16:53:16] DEBUG[31811] chan_sip.c: Header 10 [ 49]: User-Agent: IM-client/OMA1.0 sipML5-v1.2014.04.18 [Aug 11 16:53:16] DEBUG[31811] chan_sip.c: Header 11 [ 30]: Organization: Doubango Telecom [Aug 11 16:53:16] DEBUG[31811] chan_sip.c: Header 12 [ 15]: Supported: path [Aug 11 16:53:16] VERBOSE[31811] chan_sip.c: --- (13 headers 0 lines) --- [Aug 11 16:53:16] DEBUG[31811] chan_sip.c: = Looking for Call ID: 538aa1d2-2d44-b1be-ec14-be692c07df48 (Checking From) --From tag n4pQ15uXkfQi8pTtPIHd --To-tag [Aug 11 16:53:16] DEBUG[31811] acl.c: For destination '10.24.17.254', our source address is '10.24.18.124'. [Aug 11 16:53:16] DEBUG[31811] chan_sip.c: Setting AST_TRANSPORT_WS with address 10.24.18.124:5060 [Aug 11 16:53:16] DEBUG[31811] chan_sip.c: Allocating new SIP dialog for 538aa1d2-2d44-b1be-ec14-be692c07df48 - REGISTER (No RTP) [Aug 11 16:53:16] DEBUG[31811] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER [Aug 11 16:53:16] DEBUG[31811] chan_sip.c: Initializing initreq for method REGISTER - callid 538aa1d2-2d44-b1be-ec14-be692c07df48 [Aug 11 16:53:16] DEBUG[31811] netsock2.c: Splitting '10.24.18.124' into... [Aug 11 16:53:16] DEBUG[31811] netsock2.c: ...host '10.24.18.124' and port ''. [Aug 11 16:53:16] VERBOSE[31811] chan_sip.c: ˙<--- Transmitting (no NAT) to 10.24.17.254:5060 ---> ˙SIP/2.0 401 Unauthorized ˙Via: SIP/2.0/WS df7jal23ls0d.invalid;branch=z9hG4bKBlrIhG3rkCT68CG3rRyXQmxG6LuB9CgG;rport;received=10.24.17.254 ˙From: "354";tag=n4pQ15uXkfQi8pTtPIHd ˙To: "354";tag=as54f92d98 ˙Call-ID: 538aa1d2-2d44-b1be-ec14-be692c07df48 ˙CSeq: 44616 REGISTER ˙Server: Asterisk PBX SVN-branch-12-r420805 ˙Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE ˙Supported: replaces, timer ˙WWW-Authenticate: Digest algorithm=MD5, realm="10.24.18.124", nonce="43715f02" ˙Content-Length: 0 ˙ ˙ ˙<------------> [Aug 11 16:53:16] DEBUG[31811] chan_sip.c: Trying to put 'SIP/2.0 401' onto WS socket destined for 10.24.17.254:5060 [Aug 11 16:53:16] VERBOSE[31811] chan_sip.c: Scheduling destruction of SIP dialog '538aa1d2-2d44-b1be-ec14-be692c07df48' in 32000 ms (Method: REGISTER) [Aug 11 16:53:16] VERBOSE[31811] chan_sip.c: ˙<--- SIP read from WS:10.24.17.254:37591 ---> ˙REGISTER sip:10.24.18.124 SIP/2.0 ˙Via: SIP/2.0/WS df7jal23ls0d.invalid;branch=z9hG4bKFxq9lgfBTDAqamq7hQR1B9AVwTfiGbQb;rport ˙From: "354";tag=n4pQ15uXkfQi8pTtPIHd ˙To: "354" ˙Contact: "354";expires=200;click2call=no;+g.oma.sip-im;+audio;language="en,fr" ˙Call-ID: 538aa1d2-2d44-b1be-ec14-be692c07df48 ˙CSeq: 44617 REGISTER ˙Content-Length: 0 ˙Max-Forwards: 70 ˙Authorization: Digest username="354",realm="10.24.18.124",nonce="43715f02",uri="sip:10.24.18.124",response="9b4cb255d7ee54fdd261d589827a5429",algorithm=MD5 ˙User-Agent: IM-client/OMA1.0 sipML5-v1.2014.04.18 ˙Organization: Doubango Telecom ˙Supported: path ˙ ˙<-------------> [Aug 11 16:53:16] DEBUG[31811] chan_sip.c: Header 0 [ 33]: REGISTER sip:10.24.18.124 SIP/2.0 [Aug 11 16:53:16] DEBUG[31811] chan_sip.c: Header 1 [ 89]: Via: SIP/2.0/WS df7jal23ls0d.invalid;branch=z9hG4bKFxq9lgfBTDAqamq7hQR1B9AVwTfiGbQb;rport [Aug 11 16:53:16] DEBUG[31811] chan_sip.c: Header 2 [ 58]: From: "354";tag=n4pQ15uXkfQi8pTtPIHd [Aug 11 16:53:16] DEBUG[31811] chan_sip.c: Header 3 [ 31]: To: "354" [Aug 11 16:53:16] DEBUG[31811] chan_sip.c: Header 4 [139]: Contact: "354";expires=200;click2call=no;+g.oma.sip-im;+audio;language="en,fr" [Aug 11 16:53:16] DEBUG[31811] chan_sip.c: Header 5 [ 45]: Call-ID: 538aa1d2-2d44-b1be-ec14-be692c07df48 [Aug 11 16:53:16] DEBUG[31811] chan_sip.c: Header 6 [ 20]: CSeq: 44617 REGISTER [Aug 11 16:53:16] DEBUG[31811] chan_sip.c: Header 7 [ 17]: Content-Length: 0 [Aug 11 16:53:16] DEBUG[31811] chan_sip.c: Header 8 [ 16]: Max-Forwards: 70 [Aug 11 16:53:16] DEBUG[31811] chan_sip.c: Header 9 [155]: Authorization: Digest username="354",realm="10.24.18.124",nonce="43715f02",uri="sip:10.24.18.124",response="9b4cb255d7ee54fdd261d589827a5429",algorithm=MD5 [Aug 11 16:53:16] DEBUG[31811] chan_sip.c: Header 10 [ 49]: User-Agent: IM-client/OMA1.0 sipML5-v1.2014.04.18 [Aug 11 16:53:16] DEBUG[31811] chan_sip.c: Header 11 [ 30]: Organization: Doubango Telecom [Aug 11 16:53:16] DEBUG[31811] chan_sip.c: Header 12 [ 15]: Supported: path [Aug 11 16:53:16] VERBOSE[31811] chan_sip.c: --- (13 headers 0 lines) --- [Aug 11 16:53:16] DEBUG[31811] chan_sip.c: = Looking for Call ID: 538aa1d2-2d44-b1be-ec14-be692c07df48 (Checking From) --From tag n4pQ15uXkfQi8pTtPIHd --To-tag [Aug 11 16:53:16] DEBUG[31811] netsock2.c: Splitting '10.24.18.124' into... [Aug 11 16:53:16] DEBUG[31811] netsock2.c: ...host '10.24.18.124' and port ''. [Aug 11 16:53:16] DEBUG[31811] netsock2.c: Splitting '10.24.18.124' into... [Aug 11 16:53:16] DEBUG[31811] netsock2.c: ...host '10.24.18.124' and port ''. [Aug 11 16:53:16] DEBUG[31811] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER [Aug 11 16:53:16] DEBUG[31811] chan_sip.c: Initializing initreq for method REGISTER - callid 538aa1d2-2d44-b1be-ec14-be692c07df48 [Aug 11 16:53:16] DEBUG[31811] netsock2.c: Splitting '10.24.18.124' into... [Aug 11 16:53:16] DEBUG[31811] netsock2.c: ...host '10.24.18.124' and port ''. [Aug 11 16:53:16] DEBUG[31811] chan_sip.c: Store REGISTER's src-IP:port for call routing. [Aug 11 16:53:16] DEBUG[31811] chan_sip.c: build_path: do not use Path headers [Aug 11 16:53:16] VERBOSE[31811] chan_sip.c: ˙<--- Transmitting (no NAT) to 10.24.17.254:5060 ---> ˙SIP/2.0 200 OK ˙Via: SIP/2.0/WS df7jal23ls0d.invalid;branch=z9hG4bKFxq9lgfBTDAqamq7hQR1B9AVwTfiGbQb;rport;received=10.24.17.254 ˙From: "354";tag=n4pQ15uXkfQi8pTtPIHd ˙To: "354";tag=as54f92d98 ˙Call-ID: 538aa1d2-2d44-b1be-ec14-be692c07df48 ˙CSeq: 44617 REGISTER ˙Server: Asterisk PBX SVN-branch-12-r420805 ˙Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE ˙Supported: replaces, timer ˙Expires: 200 ˙Contact: ;expires=200 ˙Date: Mon, 11 Aug 2014 21:53:16 GMT ˙Content-Length: 0 ˙ ˙ ˙<------------> [Aug 11 16:53:16] DEBUG[31811] chan_sip.c: Trying to put 'SIP/2.0 200' onto WS socket destined for 10.24.17.254:5060 [Aug 11 16:53:16] DEBUG[31532] devicestate.c: No provider found, checking channel drivers for SIP - 354 [Aug 11 16:53:16] DEBUG[31532] chan_sip.c: Checking device state for peer 354 [Aug 11 16:53:16] DEBUG[31532] devicestate.c: Changing state for SIP/354 - state 1 (Not in use) [Aug 11 16:53:16] DEBUG[31593] app_queue.c: Device 'SIP/354' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Aug 11 16:53:16] VERBOSE[31811] chan_sip.c: Scheduling destruction of SIP dialog '538aa1d2-2d44-b1be-ec14-be692c07df48' in 32000 ms (Method: REGISTER) [Aug 11 16:53:21] VERBOSE[31811] chan_sip.c: ˙<--- SIP read from WS:10.24.17.254:37591 ---> ˙INVITE sip:1000@10.24.18.124 SIP/2.0 ˙Via: SIP/2.0/WS df7jal23ls0d.invalid;branch=z9hG4bKT6cDyVAJEfpUmE0qQO1q3HXT5Tfx2tFe;rport ˙From: "354";tag=fuBrKQ9Axy21s4KHXF3m ˙To: ˙Contact: "354";+g.oma.sip-im;+sip.ice;language="en,fr" ˙Call-ID: 51722c7e-ab01-35ce-45d6-d6519951892e ˙CSeq: 29673 INVITE ˙Content-Type: application/sdp ˙Content-Length: 1757 ˙Max-Forwards: 70 ˙User-Agent: IM-client/OMA1.0 sipML5-v1.2014.04.18 ˙Organization: Doubango Telecom ˙ ˙v=0 ˙o=- 2385089055052438500 2 IN IP4 127.0.0.1 ˙s=Doubango Telecom - chrome ˙t=0 0 ˙a=group:BUNDLE audio ˙a=msid-semantic: WMS zuV29lbCYPzZB9jBD6aWxIkJI6goGK9CUgn1 ˙m=audio 38999 UDP/TLS/RTP/SAVPF 111 103 104 0 8 106 105 13 126 ˙c=IN IP4 216.207.245.1 ˙a=rtcp:38999 IN IP4 216.207.245.1 ˙a=candidate:1877610657 1 udp 2122260223 10.24.17.254 38999 typ host generation 0 ˙a=candidate:1877610657 2 udp 2122260223 10.24.17.254 38999 typ host generation 0 ˙a=candidate:2583325045 1 udp 1686052607 216.207.245.1 38999 typ srflx raddr 10.24.17.254 rport 38999 generation 0 ˙a=candidate:2583325045 2 udp 1686052607 216.207.245.1 38999 typ srflx raddr 10.24.17.254 rport 38999 generation 0 ˙a=candidate:560589905 1 tcp 1518280447 10.24.17.254 0 typ host generation 0 ˙a=candidate:560589905 2 tcp 1518280447 10.24.17.254 0 typ host generation 0 ˙a=ice-ufrag:ewmqYw3SxymyweLI ˙a=ice-pwd:nv/lVCq+tdVd9Sv7N33UJHkL ˙a=ice-options:google-ice ˙a=fingerprint:sha-256 25:81:EC:F7:AC:84:A3:13:6C:80:FA:B7:84:35:85:9F:91:3F:B6:26:B3:12:92:34:B5:BE:45:CC:01:80:C9:83 ˙a=setup:actpass ˙a=mid:audio ˙a=extmap:1 urn:ietf:params:rtp-hdrext:ssrc-audio-level ˙a=extmap:3 http://www.webrtc.org/experiments/rtp-hdrext/abs-send-time ˙a=sendrecv ˙a=rtcp-mux ˙a=rtpmap:111 opus/48000/2 ˙a=fmtp:111 minptime=10 ˙a=rtpmap:103 ISAC/16000 ˙a=rtpmap:104 ISAC/32000 ˙a=rtpmap:0 PCMU/8000 ˙a=rtpmap:8 PCMA/8000 ˙a=rtpmap:106 CN/32000 ˙a=rtpmap:105 CN/16000 ˙a=rtpmap:13 CN/8000 ˙a=rtpmap:126 telephone-event/8000 ˙a=maxptime:60 ˙a=ssrc:4281046137 cname:xDaE03eQ1RsEI/Zv ˙a=ssrc:4281046137 msid:zuV29lbCYPzZB9jBD6aWxIkJI6goGK9CUgn1 77f8fec4-4364-4ff7-8efe-bfc413e407be ˙a=ssrc:4281046137 mslabel:zuV29lbCYPzZB9jBD6aWxIkJI6goGK9CUgn1 ˙a=ssrc:4281046137 label:77f8fec4-4364-4ff7-8efe-bfc413e407be ˙ ˙<-------------> [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Header 0 [ 36]: INVITE sip:1000@10.24.18.124 SIP/2.0 [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Header 1 [ 89]: Via: SIP/2.0/WS df7jal23ls0d.invalid;branch=z9hG4bKT6cDyVAJEfpUmE0qQO1q3HXT5Tfx2tFe;rport [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Header 2 [ 58]: From: "354";tag=fuBrKQ9Axy21s4KHXF3m [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Header 3 [ 27]: To: [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Header 4 [129]: Contact: "354";+g.oma.sip-im;+sip.ice;language="en,fr" [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Header 5 [ 45]: Call-ID: 51722c7e-ab01-35ce-45d6-d6519951892e [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Header 6 [ 18]: CSeq: 29673 INVITE [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Header 7 [ 29]: Content-Type: application/sdp [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Header 8 [ 20]: Content-Length: 1757 [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Header 9 [ 16]: Max-Forwards: 70 [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Header 10 [ 49]: User-Agent: IM-client/OMA1.0 sipML5-v1.2014.04.18 [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Header 11 [ 30]: Organization: Doubango Telecom [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Header 12 [ 0]: [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Body 0 [ 3]: v=0 [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Body 1 [ 42]: o=- 2385089055052438500 2 IN IP4 127.0.0.1 [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Body 2 [ 27]: s=Doubango Telecom - chrome [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Body 3 [ 5]: t=0 0 [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Body 4 [ 20]: a=group:BUNDLE audio [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Body 5 [ 57]: a=msid-semantic: WMS zuV29lbCYPzZB9jBD6aWxIkJI6goGK9CUgn1 [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Body 6 [ 62]: m=audio 38999 UDP/TLS/RTP/SAVPF 111 103 104 0 8 106 105 13 126 [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Body 7 [ 22]: c=IN IP4 216.207.245.1 [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Body 8 [ 33]: a=rtcp:38999 IN IP4 216.207.245.1 [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Body 9 [ 80]: a=candidate:1877610657 1 udp 2122260223 10.24.17.254 38999 typ host generation 0 [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Body 10 [ 80]: a=candidate:1877610657 2 udp 2122260223 10.24.17.254 38999 typ host generation 0 [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Body 11 [113]: a=candidate:2583325045 1 udp 1686052607 216.207.245.1 38999 typ srflx raddr 10.24.17.254 rport 38999 generation 0 [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Body 12 [113]: a=candidate:2583325045 2 udp 1686052607 216.207.245.1 38999 typ srflx raddr 10.24.17.254 rport 38999 generation 0 [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Body 13 [ 75]: a=candidate:560589905 1 tcp 1518280447 10.24.17.254 0 typ host generation 0 [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Body 14 [ 75]: a=candidate:560589905 2 tcp 1518280447 10.24.17.254 0 typ host generation 0 [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Body 15 [ 28]: a=ice-ufrag:ewmqYw3SxymyweLI [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Body 16 [ 34]: a=ice-pwd:nv/lVCq+tdVd9Sv7N33UJHkL [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Body 17 [ 24]: a=ice-options:google-ice [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Body 18 [117]: a=fingerprint:sha-256 25:81:EC:F7:AC:84:A3:13:6C:80:FA:B7:84:35:85:9F:91:3F:B6:26:B3:12:92:34:B5:BE:45:CC:01:80:C9:83 [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Body 19 [ 15]: a=setup:actpass [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Body 20 [ 11]: a=mid:audio [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Body 21 [ 54]: a=extmap:1 urn:ietf:params:rtp-hdrext:ssrc-audio-level [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Body 22 [ 69]: a=extmap:3 http://www.webrtc.org/experiments/rtp-hdrext/abs-send-time [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Body 23 [ 10]: a=sendrecv [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Body 24 [ 10]: a=rtcp-mux [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Body 25 [ 25]: a=rtpmap:111 opus/48000/2 [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Body 26 [ 22]: a=fmtp:111 minptime=10 [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Body 27 [ 23]: a=rtpmap:103 ISAC/16000 [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Body 28 [ 23]: a=rtpmap:104 ISAC/32000 [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Body 29 [ 20]: a=rtpmap:0 PCMU/8000 [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Body 30 [ 20]: a=rtpmap:8 PCMA/8000 [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Body 31 [ 21]: a=rtpmap:106 CN/32000 [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Body 32 [ 21]: a=rtpmap:105 CN/16000 [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Body 33 [ 19]: a=rtpmap:13 CN/8000 [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Body 34 [ 33]: a=rtpmap:126 telephone-event/8000 [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Body 35 [ 13]: a=maxptime:60 [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Body 36 [ 40]: a=ssrc:4281046137 cname:xDaE03eQ1RsEI/Zv [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Body 37 [ 96]: a=ssrc:4281046137 msid:zuV29lbCYPzZB9jBD6aWxIkJI6goGK9CUgn1 77f8fec4-4364-4ff7-8efe-bfc413e407be [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Body 38 [ 62]: a=ssrc:4281046137 mslabel:zuV29lbCYPzZB9jBD6aWxIkJI6goGK9CUgn1 [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Body 39 [ 60]: a=ssrc:4281046137 label:77f8fec4-4364-4ff7-8efe-bfc413e407be [Aug 11 16:53:21] VERBOSE[31811] chan_sip.c: --- (12 headers 40 lines) --- [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: = Looking for Call ID: 51722c7e-ab01-35ce-45d6-d6519951892e (Checking From) --From tag fuBrKQ9Axy21s4KHXF3m --To-tag [Aug 11 16:53:21] DEBUG[31811] acl.c: For destination '10.24.17.254', our source address is '10.24.18.124'. [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Setting AST_TRANSPORT_WS with address 10.24.18.124:5060 [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Allocating new SIP dialog for 51722c7e-ab01-35ce-45d6-d6519951892e - INVITE (No RTP) [Aug 11 16:53:21] DEBUG[31811][C-00000000] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Aug 11 16:53:21] DEBUG[31811][C-00000000] chan_sip.c: Initializing initreq for method INVITE - callid 51722c7e-ab01-35ce-45d6-d6519951892e [Aug 11 16:53:21] VERBOSE[31811][C-00000000] chan_sip.c: Using INVITE request as basis request - 51722c7e-ab01-35ce-45d6-d6519951892e [Aug 11 16:53:21] DEBUG[31811][C-00000000] netsock2.c: Splitting '10.24.18.124' into... [Aug 11 16:53:21] DEBUG[31811][C-00000000] netsock2.c: ...host '10.24.18.124' and port ''. [Aug 11 16:53:21] VERBOSE[31811][C-00000000] chan_sip.c: Found peer '354' for '354' from 10.24.17.254:37591 [Aug 11 16:53:21] VERBOSE[31811][C-00000000] chan_sip.c: ˙<--- Reliably Transmitting (no NAT) to 10.24.17.254:5060 ---> ˙SIP/2.0 401 Unauthorized ˙Via: SIP/2.0/WS df7jal23ls0d.invalid;branch=z9hG4bKT6cDyVAJEfpUmE0qQO1q3HXT5Tfx2tFe;rport;received=10.24.17.254 ˙From: "354";tag=fuBrKQ9Axy21s4KHXF3m ˙To: ;tag=as264b7112 ˙Call-ID: 51722c7e-ab01-35ce-45d6-d6519951892e ˙CSeq: 29673 INVITE ˙Server: Asterisk PBX SVN-branch-12-r420805 ˙Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE ˙Supported: replaces, timer ˙WWW-Authenticate: Digest algorithm=MD5, realm="10.24.18.124", nonce="15cfa349" ˙Content-Length: 0 ˙ ˙ ˙<------------> [Aug 11 16:53:21] DEBUG[31811][C-00000000] chan_sip.c: Trying to put 'SIP/2.0 401' onto WS socket destined for 10.24.17.254:5060 [Aug 11 16:53:21] VERBOSE[31811][C-00000000] chan_sip.c: Scheduling destruction of SIP dialog '51722c7e-ab01-35ce-45d6-d6519951892e' in 32000 ms (Method: INVITE) [Aug 11 16:53:21] VERBOSE[31811] chan_sip.c: ˙<--- SIP read from WS:10.24.17.254:37591 ---> ˙ACK sip:1000@10.24.18.124 SIP/2.0 ˙Via: SIP/2.0/WS df7jal23ls0d.invalid;branch=z9hG4bKT6cDyVAJEfpUmE0qQO1q3HXT5Tfx2tFe;rport ˙From: "354";tag=fuBrKQ9Axy21s4KHXF3m ˙To: ;tag=as264b7112 ˙Call-ID: 51722c7e-ab01-35ce-45d6-d6519951892e ˙CSeq: 29673 ACK ˙Content-Length: 0 ˙Max-Forwards: 70 ˙ ˙<-------------> [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Header 0 [ 33]: ACK sip:1000@10.24.18.124 SIP/2.0 [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Header 1 [ 89]: Via: SIP/2.0/WS df7jal23ls0d.invalid;branch=z9hG4bKT6cDyVAJEfpUmE0qQO1q3HXT5Tfx2tFe;rport [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Header 2 [ 58]: From: "354";tag=fuBrKQ9Axy21s4KHXF3m [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Header 3 [ 42]: To: ;tag=as264b7112 [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Header 4 [ 45]: Call-ID: 51722c7e-ab01-35ce-45d6-d6519951892e [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Header 5 [ 15]: CSeq: 29673 ACK [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Header 6 [ 17]: Content-Length: 0 [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Header 7 [ 16]: Max-Forwards: 70 [Aug 11 16:53:21] VERBOSE[31811] chan_sip.c: --- (8 headers 0 lines) --- [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: = Looking for Call ID: 51722c7e-ab01-35ce-45d6-d6519951892e (Checking From) --From tag fuBrKQ9Axy21s4KHXF3m --To-tag as264b7112 [Aug 11 16:53:21] DEBUG[31811][C-00000000] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Aug 11 16:53:21] DEBUG[31811][C-00000000] chan_sip.c: Stopping retransmission on '51722c7e-ab01-35ce-45d6-d6519951892e' of Response 29673: Match Not Found [Aug 11 16:53:21] VERBOSE[31811] chan_sip.c: ˙<--- SIP read from WS:10.24.17.254:37591 ---> ˙INVITE sip:1000@10.24.18.124 SIP/2.0 ˙Via: SIP/2.0/WS df7jal23ls0d.invalid;branch=z9hG4bKB77hSFuAvWd44BymOTS2iX25qwTUgB3o;rport ˙From: "354";tag=fuBrKQ9Axy21s4KHXF3m ˙To: ˙Contact: "354";+g.oma.sip-im;+sip.ice;language="en,fr" ˙Call-ID: 51722c7e-ab01-35ce-45d6-d6519951892e ˙CSeq: 29674 INVITE ˙Content-Type: application/sdp ˙Content-Length: 1757 ˙Max-Forwards: 70 ˙Authorization: Digest username="354",realm="10.24.18.124",nonce="15cfa349",uri="sip:1000@10.24.18.124",response="fb3e3949bbd796babe8fe0b704e2fbd4",algorithm=MD5 ˙User-Agent: IM-client/OMA1.0 sipML5-v1.2014.04.18 ˙Organization: Doubango Telecom ˙ ˙v=0 ˙o=- 2385089055052438500 2 IN IP4 127.0.0.1 ˙s=Doubango Telecom - chrome ˙t=0 0 ˙a=group:BUNDLE audio ˙a=msid-semantic: WMS zuV29lbCYPzZB9jBD6aWxIkJI6goGK9CUgn1 ˙m=audio 38999 UDP/TLS/RTP/SAVPF 111 103 104 0 8 106 105 13 126 ˙c=IN IP4 216.207.245.1 ˙a=rtcp:38999 IN IP4 216.207.245.1 ˙a=candidate:1877610657 1 udp 2122260223 10.24.17.254 38999 typ host generation 0 ˙a=candidate:1877610657 2 udp 2122260223 10.24.17.254 38999 typ host generation 0 ˙a=candidate:2583325045 1 udp 1686052607 216.207.245.1 38999 typ srflx raddr 10.24.17.254 rport 38999 generation 0 ˙a=candidate:2583325045 2 udp 1686052607 216.207.245.1 38999 typ srflx raddr 10.24.17.254 rport 38999 generation 0 ˙a=candidate:560589905 1 tcp 1518280447 10.24.17.254 0 typ host generation 0 ˙a=candidate:560589905 2 tcp 1518280447 10.24.17.254 0 typ host generation 0 ˙a=ice-ufrag:ewmqYw3SxymyweLI ˙a=ice-pwd:nv/lVCq+tdVd9Sv7N33UJHkL ˙a=ice-options:google-ice ˙a=fingerprint:sha-256 25:81:EC:F7:AC:84:A3:13:6C:80:FA:B7:84:35:85:9F:91:3F:B6:26:B3:12:92:34:B5:BE:45:CC:01:80:C9:83 ˙a=setup:actpass ˙a=mid:audio ˙a=extmap:1 urn:ietf:params:rtp-hdrext:ssrc-audio-level ˙a=extmap:3 http://www.webrtc.org/experiments/rtp-hdrext/abs-send-time ˙a=sendrecv ˙a=rtcp-mux ˙a=rtpmap:111 opus/48000/2 ˙a=fmtp:111 minptime=10 ˙a=rtpmap:103 ISAC/16000 ˙a=rtpmap:104 ISAC/32000 ˙a=rtpmap:0 PCMU/8000 ˙a=rtpmap:8 PCMA/8000 ˙a=rtpmap:106 CN/32000 ˙a=rtpmap:105 CN/16000 ˙a=rtpmap:13 CN/8000 ˙a=rtpmap:126 telephone-event/8000 ˙a=maxptime:60 ˙a=ssrc:4281046137 cname:xDaE03eQ1RsEI/Zv ˙a=ssrc:4281046137 msid:zuV29lbCYPzZB9jBD6aWxIkJI6goGK9CUgn1 77f8fec4-4364-4ff7-8efe-bfc413e407be ˙a=ssrc:4281046137 mslabel:zuV29lbCYPzZB9jBD6aWxIkJI6goGK9CUgn1 ˙a=ssrc:4281046137 label:77f8fec4-4364-4ff7-8efe-bfc413e407be ˙<-------------> [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Header 0 [ 36]: INVITE sip:1000@10.24.18.124 SIP/2.0 [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Header 1 [ 89]: Via: SIP/2.0/WS df7jal23ls0d.invalid;branch=z9hG4bKB77hSFuAvWd44BymOTS2iX25qwTUgB3o;rport [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Header 2 [ 58]: From: "354";tag=fuBrKQ9Axy21s4KHXF3m [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Header 3 [ 27]: To: [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Header 4 [129]: Contact: "354";+g.oma.sip-im;+sip.ice;language="en,fr" [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Header 5 [ 45]: Call-ID: 51722c7e-ab01-35ce-45d6-d6519951892e [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Header 6 [ 18]: CSeq: 29674 INVITE [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Header 7 [ 29]: Content-Type: application/sdp [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Header 8 [ 20]: Content-Length: 1757 [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Header 9 [ 16]: Max-Forwards: 70 [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Header 10 [160]: Authorization: Digest username="354",realm="10.24.18.124",nonce="15cfa349",uri="sip:1000@10.24.18.124",response="fb3e3949bbd796babe8fe0b704e2fbd4",algorithm=MD5 [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Header 11 [ 49]: User-Agent: IM-client/OMA1.0 sipML5-v1.2014.04.18 [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Header 12 [ 30]: Organization: Doubango Telecom [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Header 13 [ 0]: [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Body 0 [ 3]: v=0 [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Body 1 [ 42]: o=- 2385089055052438500 2 IN IP4 127.0.0.1 [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Body 2 [ 27]: s=Doubango Telecom - chrome [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Body 3 [ 5]: t=0 0 [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Body 4 [ 20]: a=group:BUNDLE audio [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Body 5 [ 57]: a=msid-semantic: WMS zuV29lbCYPzZB9jBD6aWxIkJI6goGK9CUgn1 [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Body 6 [ 62]: m=audio 38999 UDP/TLS/RTP/SAVPF 111 103 104 0 8 106 105 13 126 [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Body 7 [ 22]: c=IN IP4 216.207.245.1 [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Body 8 [ 33]: a=rtcp:38999 IN IP4 216.207.245.1 [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Body 9 [ 80]: a=candidate:1877610657 1 udp 2122260223 10.24.17.254 38999 typ host generation 0 [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Body 10 [ 80]: a=candidate:1877610657 2 udp 2122260223 10.24.17.254 38999 typ host generation 0 [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Body 11 [113]: a=candidate:2583325045 1 udp 1686052607 216.207.245.1 38999 typ srflx raddr 10.24.17.254 rport 38999 generation 0 [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Body 12 [113]: a=candidate:2583325045 2 udp 1686052607 216.207.245.1 38999 typ srflx raddr 10.24.17.254 rport 38999 generation 0 [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Body 13 [ 75]: a=candidate:560589905 1 tcp 1518280447 10.24.17.254 0 typ host generation 0 [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Body 14 [ 75]: a=candidate:560589905 2 tcp 1518280447 10.24.17.254 0 typ host generation 0 [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Body 15 [ 28]: a=ice-ufrag:ewmqYw3SxymyweLI [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Body 16 [ 34]: a=ice-pwd:nv/lVCq+tdVd9Sv7N33UJHkL [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Body 17 [ 24]: a=ice-options:google-ice [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Body 18 [117]: a=fingerprint:sha-256 25:81:EC:F7:AC:84:A3:13:6C:80:FA:B7:84:35:85:9F:91:3F:B6:26:B3:12:92:34:B5:BE:45:CC:01:80:C9:83 [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Body 19 [ 15]: a=setup:actpass [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Body 20 [ 11]: a=mid:audio [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Body 21 [ 54]: a=extmap:1 urn:ietf:params:rtp-hdrext:ssrc-audio-level [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Body 22 [ 69]: a=extmap:3 http://www.webrtc.org/experiments/rtp-hdrext/abs-send-time [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Body 23 [ 10]: a=sendrecv [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Body 24 [ 10]: a=rtcp-mux [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Body 25 [ 25]: a=rtpmap:111 opus/48000/2 [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Body 26 [ 22]: a=fmtp:111 minptime=10 [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Body 27 [ 23]: a=rtpmap:103 ISAC/16000 [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Body 28 [ 23]: a=rtpmap:104 ISAC/32000 [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Body 29 [ 20]: a=rtpmap:0 PCMU/8000 [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Body 30 [ 20]: a=rtpmap:8 PCMA/8000 [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Body 31 [ 21]: a=rtpmap:106 CN/32000 [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Body 32 [ 21]: a=rtpmap:105 CN/16000 [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Body 33 [ 19]: a=rtpmap:13 CN/8000 [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Body 34 [ 33]: a=rtpmap:126 telephone-event/8000 [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Body 35 [ 13]: a=maxptime:60 [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Body 36 [ 40]: a=ssrc:4281046137 cname:xDaE03eQ1RsEI/Zv [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Body 37 [ 96]: a=ssrc:4281046137 msid:zuV29lbCYPzZB9jBD6aWxIkJI6goGK9CUgn1 77f8fec4-4364-4ff7-8efe-bfc413e407be [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Body 38 [ 62]: a=ssrc:4281046137 mslabel:zuV29lbCYPzZB9jBD6aWxIkJI6goGK9CUgn1 [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Body 39 [ 60]: a=ssrc:4281046137 label:77f8fec4-4364-4ff7-8efe-bfc413e407be [Aug 11 16:53:21] VERBOSE[31811] chan_sip.c: --- (13 headers 40 lines) --- [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: = Looking for Call ID: 51722c7e-ab01-35ce-45d6-d6519951892e (Checking From) --From tag fuBrKQ9Axy21s4KHXF3m --To-tag [Aug 11 16:53:21] DEBUG[31811] netsock2.c: Splitting '10.24.18.124' into... [Aug 11 16:53:21] DEBUG[31811] netsock2.c: ...host '10.24.18.124' and port ''. [Aug 11 16:53:21] DEBUG[31811] netsock2.c: Splitting '10.24.18.124' into... [Aug 11 16:53:21] DEBUG[31811] netsock2.c: ...host '10.24.18.124' and port ''. [Aug 11 16:53:21] DEBUG[31811][C-00000000] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Aug 11 16:53:21] DEBUG[31811][C-00000000] chan_sip.c: Initializing initreq for method INVITE - callid 51722c7e-ab01-35ce-45d6-d6519951892e [Aug 11 16:53:21] VERBOSE[31811][C-00000000] chan_sip.c: Using INVITE request as basis request - 51722c7e-ab01-35ce-45d6-d6519951892e [Aug 11 16:53:21] DEBUG[31811][C-00000000] netsock2.c: Splitting '10.24.18.124' into... [Aug 11 16:53:21] DEBUG[31811][C-00000000] netsock2.c: ...host '10.24.18.124' and port ''. [Aug 11 16:53:21] VERBOSE[31811][C-00000000] chan_sip.c: Found peer '354' for '354' from 10.24.17.254:37591 [Aug 11 16:53:21] DEBUG[31811][C-00000000] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7fafa0024d08' [Aug 11 16:53:21] DEBUG[31811][C-00000000] res_rtp_asterisk.c: Allocated port 16208 for RTP instance '0x7fafa0024d08' [Aug 11 16:53:21] DEBUG[31811][C-00000000] pjsip: icess0x7fafa00 ICE session created, comp_cnt=2, role is Unknown agent [Aug 11 16:53:21] DEBUG[31811][C-00000000] netsock2.c: Splitting '10.24.18.124' into... [Aug 11 16:53:21] DEBUG[31811][C-00000000] netsock2.c: ...host '10.24.18.124' and port ''. [Aug 11 16:53:21] DEBUG[31811][C-00000000] pjsip: icess0x7fafa00 Candidate 0 added: comp_id=1, type=host, foundation=Ha18127c, addr=10.24.18.124:16208, base=10.24.18.124:16208, prio=0x7effffff (2130706431) [Aug 11 16:53:21] DEBUG[31811][C-00000000] netsock2.c: Splitting '216.207.245.1' into... [Aug 11 16:53:21] DEBUG[31811][C-00000000] netsock2.c: ...host '216.207.245.1' and port ''. [Aug 11 16:53:21] DEBUG[31811][C-00000000] pjsip: icess0x7fafa00 Candidate 1 added: comp_id=1, type=srflx, foundation=Sd8cff501, addr=216.207.245.1:16208, base=10.24.18.124:16208, prio=0x64ffffff (1694498815) [Aug 11 16:53:21] DEBUG[31811][C-00000000] rtp_engine.c: RTP instance '0x7fafa0024d08' is setup and ready to go [Aug 11 16:53:21] DEBUG[31811][C-00000000] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7fafa0024d08' [Aug 11 16:53:21] DEBUG[31811][C-00000000] netsock2.c: Splitting '10.24.18.124' into... [Aug 11 16:53:21] DEBUG[31811][C-00000000] netsock2.c: ...host '10.24.18.124' and port ''. [Aug 11 16:53:21] DEBUG[31811][C-00000000] pjsip: icess0x7fafa00 Candidate 2 added: comp_id=2, type=host, foundation=Ha18127c, addr=10.24.18.124:16209, base=10.24.18.124:16209, prio=0x7efffffe (2130706430) [Aug 11 16:53:21] DEBUG[31811][C-00000000] netsock2.c: Splitting '216.207.245.1' into... [Aug 11 16:53:21] DEBUG[31811][C-00000000] netsock2.c: ...host '216.207.245.1' and port ''. [Aug 11 16:53:21] DEBUG[31811][C-00000000] pjsip: icess0x7fafa00 Candidate 3 added: comp_id=2, type=srflx, foundation=Sd8cff501, addr=216.207.245.1:16209, base=10.24.18.124:16209, prio=0x64fffffe (1694498814) [Aug 11 16:53:21] DEBUG[31811][C-00000000] chan_sip.c: Setting NAT on RTP to Off [Aug 11 16:53:21] DEBUG[31811][C-00000000] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED OR FAILED. [Aug 11 16:53:21] DEBUG[31811][C-00000000] chan_sip.c: Processing session-level SDP o=- 2385089055052438500 2 IN IP4 127.0.0.1... OK. [Aug 11 16:53:21] DEBUG[31811][C-00000000] chan_sip.c: Processing session-level SDP s=Doubango Telecom - chrome... UNSUPPORTED OR FAILED. [Aug 11 16:53:21] DEBUG[31811][C-00000000] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED. [Aug 11 16:53:21] DEBUG[31811][C-00000000] chan_sip.c: Processing session-level SDP a=group:BUNDLE audio... UNSUPPORTED OR FAILED. [Aug 11 16:53:21] DEBUG[31811][C-00000000] chan_sip.c: Processing session-level SDP a=msid-semantic: WMS zuV29lbCYPzZB9jBD6aWxIkJI6goGK9CUgn1... UNSUPPORTED OR FAILED. [Aug 11 16:53:21] VERBOSE[31811][C-00000000] chan_sip.c: Found RTP audio format 111 [Aug 11 16:53:21] DEBUG[31811][C-00000000] rtp_engine.c: Setting payload 111 based on m type on 0x7faff0132230 [Aug 11 16:53:21] VERBOSE[31811][C-00000000] chan_sip.c: Found RTP audio format 103 [Aug 11 16:53:21] DEBUG[31811][C-00000000] rtp_engine.c: Setting payload 103 based on m type on 0x7faff0132230 [Aug 11 16:53:21] VERBOSE[31811][C-00000000] chan_sip.c: Found RTP audio format 104 [Aug 11 16:53:21] DEBUG[31811][C-00000000] rtp_engine.c: Setting payload 104 based on m type on 0x7faff0132230 [Aug 11 16:53:21] VERBOSE[31811][C-00000000] chan_sip.c: Found RTP audio format 0 [Aug 11 16:53:21] DEBUG[31811][C-00000000] rtp_engine.c: Setting payload 0 based on m type on 0x7faff0132230 [Aug 11 16:53:21] VERBOSE[31811][C-00000000] chan_sip.c: Found RTP audio format 8 [Aug 11 16:53:21] DEBUG[31811][C-00000000] rtp_engine.c: Setting payload 8 based on m type on 0x7faff0132230 [Aug 11 16:53:21] VERBOSE[31811][C-00000000] chan_sip.c: Found RTP audio format 106 [Aug 11 16:53:21] DEBUG[31811][C-00000000] rtp_engine.c: Setting payload 106 based on m type on 0x7faff0132230 [Aug 11 16:53:21] VERBOSE[31811][C-00000000] chan_sip.c: Found RTP audio format 105 [Aug 11 16:53:21] DEBUG[31811][C-00000000] rtp_engine.c: Setting payload 105 based on m type on 0x7faff0132230 [Aug 11 16:53:21] VERBOSE[31811][C-00000000] chan_sip.c: Found RTP audio format 13 [Aug 11 16:53:21] DEBUG[31811][C-00000000] rtp_engine.c: Setting payload 13 based on m type on 0x7faff0132230 [Aug 11 16:53:21] VERBOSE[31811][C-00000000] chan_sip.c: Found RTP audio format 126 [Aug 11 16:53:21] DEBUG[31811][C-00000000] rtp_engine.c: Setting payload 126 based on m type on 0x7faff0132230 [Aug 11 16:53:21] DEBUG[31811][C-00000000] netsock2.c: Splitting '216.207.245.1' into... [Aug 11 16:53:21] DEBUG[31811][C-00000000] netsock2.c: ...host '216.207.245.1' and port ''. [Aug 11 16:53:21] DEBUG[31811][C-00000000] chan_sip.c: Processing media-level (audio) SDP c=IN IP4 216.207.245.1... OK. [Aug 11 16:53:21] DEBUG[31811][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=rtcp:38999 IN IP4 216.207.245.1... UNSUPPORTED OR FAILED. [Aug 11 16:53:21] DEBUG[31811][C-00000000] netsock2.c: Splitting '10.24.17.254' into... [Aug 11 16:53:21] DEBUG[31811][C-00000000] netsock2.c: ...host '10.24.17.254' and port ''. [Aug 11 16:53:21] DEBUG[31811][C-00000000] netsock2.c: Splitting '0' into... [Aug 11 16:53:21] DEBUG[31811][C-00000000] netsock2.c: ...host '0' and port ''. [Aug 11 16:53:21] DEBUG[31811][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=candidate:1877610657 1 udp 2122260223 10.24.17.254 38999 typ host generation 0... OK. [Aug 11 16:53:21] DEBUG[31811][C-00000000] netsock2.c: Splitting '10.24.17.254' into... [Aug 11 16:53:21] DEBUG[31811][C-00000000] netsock2.c: ...host '10.24.17.254' and port ''. [Aug 11 16:53:21] DEBUG[31811][C-00000000] netsock2.c: Splitting '0' into... [Aug 11 16:53:21] DEBUG[31811][C-00000000] netsock2.c: ...host '0' and port ''. [Aug 11 16:53:21] DEBUG[31811][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=candidate:1877610657 2 udp 2122260223 10.24.17.254 38999 typ host generation 0... OK. [Aug 11 16:53:21] DEBUG[31811][C-00000000] netsock2.c: Splitting '216.207.245.1' into... [Aug 11 16:53:21] DEBUG[31811][C-00000000] netsock2.c: ...host '216.207.245.1' and port ''. [Aug 11 16:53:21] DEBUG[31811][C-00000000] netsock2.c: Splitting '10.24.17.254' into... [Aug 11 16:53:21] DEBUG[31811][C-00000000] netsock2.c: ...host '10.24.17.254' and port ''. [Aug 11 16:53:21] DEBUG[31811][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=candidate:2583325045 1 udp 1686052607 216.207.245.1 38999 typ srflx raddr 10.24.17.254 rport 38999 generation 0... OK. [Aug 11 16:53:21] DEBUG[31811][C-00000000] netsock2.c: Splitting '216.207.245.1' into... [Aug 11 16:53:21] DEBUG[31811][C-00000000] netsock2.c: ...host '216.207.245.1' and port ''. [Aug 11 16:53:21] DEBUG[31811][C-00000000] netsock2.c: Splitting '10.24.17.254' into... [Aug 11 16:53:21] DEBUG[31811][C-00000000] netsock2.c: ...host '10.24.17.254' and port ''. [Aug 11 16:53:21] DEBUG[31811][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=candidate:2583325045 2 udp 1686052607 216.207.245.1 38999 typ srflx raddr 10.24.17.254 rport 38999 generation 0... OK. [Aug 11 16:53:21] DEBUG[31811][C-00000000] netsock2.c: Splitting '10.24.17.254' into... [Aug 11 16:53:21] DEBUG[31811][C-00000000] netsock2.c: ...host '10.24.17.254' and port ''. [Aug 11 16:53:21] DEBUG[31811][C-00000000] netsock2.c: Splitting '0' into... [Aug 11 16:53:21] DEBUG[31811][C-00000000] netsock2.c: ...host '0' and port ''. [Aug 11 16:53:21] DEBUG[31811][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=candidate:560589905 1 tcp 1518280447 10.24.17.254 0 typ host generation 0... OK. [Aug 11 16:53:21] DEBUG[31811][C-00000000] netsock2.c: Splitting '10.24.17.254' into... [Aug 11 16:53:21] DEBUG[31811][C-00000000] netsock2.c: ...host '10.24.17.254' and port ''. [Aug 11 16:53:21] DEBUG[31811][C-00000000] netsock2.c: Splitting '0' into... [Aug 11 16:53:21] DEBUG[31811][C-00000000] netsock2.c: ...host '0' and port ''. [Aug 11 16:53:21] DEBUG[31811][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=candidate:560589905 2 tcp 1518280447 10.24.17.254 0 typ host generation 0... OK. [Aug 11 16:53:21] DEBUG[31811][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=ice-ufrag:ewmqYw3SxymyweLI... OK. [Aug 11 16:53:21] DEBUG[31811][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=ice-pwd:nv/lVCq+tdVd9Sv7N33UJHkL... OK. [Aug 11 16:53:21] DEBUG[31811][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=ice-options:google-ice... UNSUPPORTED OR FAILED. [Aug 11 16:53:21] DEBUG[31811][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=fingerprint:sha-256 25:81:EC:F7:AC:84:A3:13:6C:80:FA:B7:84:35:85:9F:91:3F:B6:26:B3:12:92:34:B5:BE:45:CC:01:80:C9:83... OK. [Aug 11 16:53:21] DEBUG[31811][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=setup:actpass... OK. [Aug 11 16:53:21] DEBUG[31811][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=mid:audio... UNSUPPORTED OR FAILED. [Aug 11 16:53:21] DEBUG[31811][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=extmap:1 urn:ietf:params:rtp-hdrext:ssrc-audio-level... UNSUPPORTED OR FAILED. [Aug 11 16:53:21] DEBUG[31811][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=extmap:3 http://www.webrtc.org/experiments/rtp-hdrext/abs-send-time... UNSUPPORTED OR FAILED. [Aug 11 16:53:21] DEBUG[31811][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK. [Aug 11 16:53:21] DEBUG[31811][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=rtcp-mux... UNSUPPORTED OR FAILED. [Aug 11 16:53:21] VERBOSE[31811][C-00000000] chan_sip.c: Found audio description format opus for ID 111 [Aug 11 16:53:21] DEBUG[31811][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:111 opus/48000/2... OK. [Aug 11 16:53:21] DEBUG[31811][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=fmtp:111 minptime=10... OK. [Aug 11 16:53:21] DEBUG[31811][C-00000000] rtp_engine.c: Unsetting payload 103 on 0x7faff0132230 [Aug 11 16:53:21] VERBOSE[31811][C-00000000] chan_sip.c: Found unknown media description format ISAC for ID 103 [Aug 11 16:53:21] DEBUG[31811][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:103 ISAC/16000... UNSUPPORTED OR FAILED. [Aug 11 16:53:21] DEBUG[31811][C-00000000] rtp_engine.c: Unsetting payload 104 on 0x7faff0132230 [Aug 11 16:53:21] VERBOSE[31811][C-00000000] chan_sip.c: Found unknown media description format ISAC for ID 104 [Aug 11 16:53:21] DEBUG[31811][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:104 ISAC/32000... UNSUPPORTED OR FAILED. [Aug 11 16:53:21] VERBOSE[31811][C-00000000] chan_sip.c: Found audio description format PCMU for ID 0 [Aug 11 16:53:21] DEBUG[31811][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. [Aug 11 16:53:21] VERBOSE[31811][C-00000000] chan_sip.c: Found audio description format PCMA for ID 8 [Aug 11 16:53:21] DEBUG[31811][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK. [Aug 11 16:53:21] DEBUG[31811][C-00000000] rtp_engine.c: Unsetting payload 106 on 0x7faff0132230 [Aug 11 16:53:21] VERBOSE[31811][C-00000000] chan_sip.c: Found unknown media description format CN for ID 106 [Aug 11 16:53:21] DEBUG[31811][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:106 CN/32000... UNSUPPORTED OR FAILED. [Aug 11 16:53:21] DEBUG[31811][C-00000000] rtp_engine.c: Unsetting payload 105 on 0x7faff0132230 [Aug 11 16:53:21] VERBOSE[31811][C-00000000] chan_sip.c: Found unknown media description format CN for ID 105 [Aug 11 16:53:21] DEBUG[31811][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:105 CN/16000... UNSUPPORTED OR FAILED. [Aug 11 16:53:21] VERBOSE[31811][C-00000000] chan_sip.c: Found audio description format CN for ID 13 [Aug 11 16:53:21] DEBUG[31811][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:13 CN/8000... OK. [Aug 11 16:53:21] VERBOSE[31811][C-00000000] chan_sip.c: Found audio description format telephone-event for ID 126 [Aug 11 16:53:21] DEBUG[31811][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:126 telephone-event/8000... OK. [Aug 11 16:53:21] DEBUG[31811][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=maxptime:60... UNSUPPORTED OR FAILED. [Aug 11 16:53:21] DEBUG[31811][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=ssrc:4281046137 cname:xDaE03eQ1RsEI/Zv... UNSUPPORTED OR FAILED. [Aug 11 16:53:21] DEBUG[31811][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=ssrc:4281046137 msid:zuV29lbCYPzZB9jBD6aWxIkJI6goGK9CUgn1 77f8fec4-4364-4ff7-8efe-bfc413e407be... UNSUPPORTED OR FAILED. [Aug 11 16:53:21] DEBUG[31811][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=ssrc:4281046137 mslabel:zuV29lbCYPzZB9jBD6aWxIkJI6goGK9CUgn1... UNSUPPORTED OR FAILED. [Aug 11 16:53:21] DEBUG[31811][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=ssrc:4281046137 label:77f8fec4-4364-4ff7-8efe-bfc413e407be... UNSUPPORTED OR FAILED. [Aug 11 16:53:21] VERBOSE[31811][C-00000000] chan_sip.c: Capabilities: us - (alaw), peer - audio=(ulaw|alaw|opus)/video=(nothing)/text=(nothing), combined - (alaw) [Aug 11 16:53:21] VERBOSE[31811][C-00000000] chan_sip.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x3 (telephone-event|CN|), combined - 0x1 (telephone-event|) [Aug 11 16:53:21] DEBUG[31811][C-00000000] pjsip: icess0x7fafa00 Role changed to Controlled [Aug 11 16:53:21] DEBUG[31811][C-00000000] pjsip: icess0x7fafa00 Destroying ICE session 0x7fafa00185a8 [Aug 11 16:53:21] DEBUG[31811][C-00000000] pjsip: stuse0x7fafa00 STUN session 0x7fafa001a5b8 destroy request, ref_cnt=4 [Aug 11 16:53:21] DEBUG[31811][C-00000000] pjsip: stuse0x7fafa00 STUN session 0x7fafa001ad98 destroy request, ref_cnt=3 [Aug 11 16:53:21] DEBUG[31811][C-00000000] pjsip: ice_session.c ICE session 0x7fafa00185a8 destroyed [Aug 11 16:53:21] DEBUG[31811][C-00000000] pjsip: stun_session.c STUN session 0x7fafa001a5b8 destroyed [Aug 11 16:53:21] DEBUG[31811][C-00000000] pjsip: stun_session.c STUN session 0x7fafa001ad98 destroyed [Aug 11 16:53:21] DEBUG[31811][C-00000000] pjsip: icess0x7fafa00 ICE session created, comp_cnt=2, role is Unknown agent [Aug 11 16:53:21] DEBUG[31811][C-00000000] netsock2.c: Splitting '10.24.18.124' into... [Aug 11 16:53:21] DEBUG[31811][C-00000000] netsock2.c: ...host '10.24.18.124' and port ''. [Aug 11 16:53:21] DEBUG[31811][C-00000000] pjsip: icess0x7fafa00 Candidate 0 added: comp_id=1, type=host, foundation=Ha18127c, addr=10.24.18.124:16208, base=10.24.18.124:16208, prio=0x7effffff (2130706431) [Aug 11 16:53:21] DEBUG[31811][C-00000000] netsock2.c: Splitting '216.207.245.1' into... [Aug 11 16:53:21] DEBUG[31811][C-00000000] netsock2.c: ...host '216.207.245.1' and port ''. [Aug 11 16:53:21] DEBUG[31811][C-00000000] pjsip: icess0x7fafa00 Candidate 1 added: comp_id=1, type=srflx, foundation=Sd8cff501, addr=216.207.245.1:16208, base=10.24.18.124:16208, prio=0x64ffffff (1694498815) [Aug 11 16:53:21] DEBUG[31811][C-00000000] netsock2.c: Splitting '10.24.18.124' into... [Aug 11 16:53:21] DEBUG[31811][C-00000000] netsock2.c: ...host '10.24.18.124' and port ''. [Aug 11 16:53:21] DEBUG[31811][C-00000000] pjsip: icess0x7fafa00 Candidate 2 added: comp_id=2, type=host, foundation=Ha18127c, addr=10.24.18.124:16209, base=10.24.18.124:16209, prio=0x7efffffe (2130706430) [Aug 11 16:53:21] DEBUG[31811][C-00000000] netsock2.c: Splitting '216.207.245.1' into... [Aug 11 16:53:21] DEBUG[31811][C-00000000] netsock2.c: ...host '216.207.245.1' and port ''. [Aug 11 16:53:21] DEBUG[31811][C-00000000] pjsip: icess0x7fafa00 Candidate 3 added: comp_id=2, type=srflx, foundation=Sd8cff501, addr=216.207.245.1:16209, base=10.24.18.124:16209, prio=0x64fffffe (1694498814) [Aug 11 16:53:21] DEBUG[31811][C-00000000] pjsip: icess0x7fafa00 Role changed to Controlled [Aug 11 16:53:21] DEBUG[31811][C-00000000] pjsip: icess0x7fafa00 Check 2: [1] 10.24.18.124:16208-->10.24.17.254:38999 pruned (duplicate found) [Aug 11 16:53:21] DEBUG[31811][C-00000000] pjsip: icess0x7fafa00 Check 2: [2] 10.24.18.124:16209-->10.24.17.254:38999 pruned (duplicate found) [Aug 11 16:53:21] DEBUG[31811][C-00000000] pjsip: icess0x7fafa00 Check 4: [1] 10.24.18.124:16208-->216.207.245.1:38999 pruned (duplicate found) [Aug 11 16:53:21] DEBUG[31811][C-00000000] pjsip: icess0x7fafa00 Check 4: [2] 10.24.18.124:16209-->216.207.245.1:38999 pruned (duplicate found) [Aug 11 16:53:21] DEBUG[31811][C-00000000] pjsip: icess0x7fafa00 Check 6: [1] 10.24.18.124:16208-->10.24.17.254:0 pruned (duplicate found) [Aug 11 16:53:21] DEBUG[31811][C-00000000] pjsip: icess0x7fafa00 Check 6: [2] 10.24.18.124:16209-->10.24.17.254:0 pruned (duplicate found) [Aug 11 16:53:21] DEBUG[31811][C-00000000] pjsip: icess0x7fafa00 Checklist created: [Aug 11 16:53:21] DEBUG[31811][C-00000000] pjsip: icess0x7fafa00 0: [1] 10.24.18.124:16208-->10.24.17.254:38999 (not nominated, state=Frozen) [Aug 11 16:53:21] DEBUG[31811][C-00000000] pjsip: icess0x7fafa00 1: [2] 10.24.18.124:16209-->10.24.17.254:38999 (not nominated, state=Frozen) [Aug 11 16:53:21] DEBUG[31811][C-00000000] pjsip: icess0x7fafa00 2: [1] 10.24.18.124:16208-->216.207.245.1:38999 (not nominated, state=Frozen) [Aug 11 16:53:21] DEBUG[31811][C-00000000] pjsip: icess0x7fafa00 3: [2] 10.24.18.124:16209-->216.207.245.1:38999 (not nominated, state=Frozen) [Aug 11 16:53:21] DEBUG[31811][C-00000000] pjsip: icess0x7fafa00 4: [1] 10.24.18.124:16208-->10.24.17.254:0 (not nominated, state=Frozen) [Aug 11 16:53:21] DEBUG[31811][C-00000000] pjsip: icess0x7fafa00 5: [2] 10.24.18.124:16209-->10.24.17.254:0 (not nominated, state=Frozen) [Aug 11 16:53:21] DEBUG[31811][C-00000000] pjsip: icess0x7fafa00 Starting ICE check.. [Aug 11 16:53:21] DEBUG[31811][C-00000000] pjsip: icess0x7fafa00 .Check 0: [1] 10.24.18.124:16208-->10.24.17.254:38999: state changed from Frozen to Waiting [Aug 11 16:53:21] DEBUG[31811][C-00000000] pjsip: icess0x7fafa00 Checklist: state changed from Idle to Running [Aug 11 16:53:21] DEBUG[31811][C-00000000] pjsip: icess0x7fafa00 Starting checklist periodic check [Aug 11 16:53:21] DEBUG[31811][C-00000000] pjsip: icess0x7fafa00 .Sending connectivity check for check 0: [1] 10.24.18.124:16208-->10.24.17.254:38999 [Aug 11 16:53:21] DEBUG[31811][C-00000000] pjsip: stuse0x7fafa00 ...TX 144 bytes STUN message to 10.24.17.254:38999: --- begin STUN message --- STUN Binding request Hdr: length=124, magic=2112a442, tsx_id=00007b2158cfd9e255651f92 Attributes: PRIORITY: length=4, value=1862270975 (0x6effffff) ICE-CONTROLLED: length=8, data=79096e8043510184 SOFTWARE: length=0, value="pjnath-2.2.1" USERNAME: length=0, value="ewmqYw3SxymyweLI:106e517c25a1e1030ddb32f52c5938a2" MESSAGE-INTEGRITY: length=20, data=1ffc9bfad6b7fb8e5cf9d42e4a657937031f4fde FINGERPRINT: length=4, value=784731424 (0x2ec60d20) --- end of STUN message --- [Aug 11 16:53:21] DEBUG[31811][C-00000000] pjsip: utsx0x7fafa003 ...STUN client transaction created [Aug 11 16:53:21] DEBUG[31811][C-00000000] pjsip: utsx0x7fafa003 ...STUN sending message (transmit count=1) [Aug 11 16:53:21] DEBUG[31811][C-00000000] pjsip: icess0x7fafa00 ..Check 0: [1] 10.24.18.124:16208-->10.24.17.254:38999: state changed from Waiting to In Progress [Aug 11 16:53:21] DEBUG[31811][C-00000000] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fafa0024d08' [Aug 11 16:53:21] VERBOSE[31811][C-00000000] chan_sip.c: Peer audio RTP is at port 216.207.245.1:38999 [Aug 11 16:53:21] DEBUG[31811][C-00000000] rtp_engine.c: Copying payload 0 from 0x7faff0132230 to 0x7fafa0024e48 [Aug 11 16:53:21] DEBUG[31811][C-00000000] rtp_engine.c: Copying payload 8 from 0x7faff0132230 to 0x7fafa0024e48 [Aug 11 16:53:21] DEBUG[31811][C-00000000] rtp_engine.c: Copying payload 13 from 0x7faff0132230 to 0x7fafa0024e48 [Aug 11 16:53:21] DEBUG[31811][C-00000000] rtp_engine.c: Copying payload 111 from 0x7faff0132230 to 0x7fafa0024e48 [Aug 11 16:53:21] DEBUG[31811][C-00000000] rtp_engine.c: Copying payload 126 from 0x7faff0132230 to 0x7fafa0024e48 [Aug 11 16:53:21] DEBUG[31811][C-00000000] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x7fafa0024d08' [Aug 11 16:53:21] DEBUG[31811][C-00000000] chan_sip.c: We're settling with these formats: (alaw) [Aug 11 16:53:21] DEBUG[31811][C-00000000] chan_sip.c: Checking SIP call limits for device 354 [Aug 11 16:53:21] DEBUG[31811][C-00000000] chan_sip.c: Updating call counter for incoming call [Aug 11 16:53:21] DEBUG[31811][C-00000000] netsock2.c: Splitting '10.24.18.124' into... [Aug 11 16:53:21] DEBUG[31811][C-00000000] netsock2.c: ...host '10.24.18.124' and port ''. [Aug 11 16:53:21] DEBUG[31811][C-00000000] netsock2.c: Splitting '10.24.18.124' into... [Aug 11 16:53:21] DEBUG[31811][C-00000000] netsock2.c: ...host '10.24.18.124' and port ''. [Aug 11 16:53:21] VERBOSE[31811][C-00000000] chan_sip.c: Looking for 1000 in default (domain 10.24.18.124) [Aug 11 16:53:21] DEBUG[31811][C-00000000] chan_sip.c: *** Our native formats are (alaw) [Aug 11 16:53:21] DEBUG[31811][C-00000000] chan_sip.c: *** Joint capabilities are (alaw) [Aug 11 16:53:21] DEBUG[31811][C-00000000] chan_sip.c: *** Our capabilities are (alaw) [Aug 11 16:53:21] DEBUG[31811][C-00000000] chan_sip.c: *** AST_CODEC_CHOOSE formats are alaw [Aug 11 16:53:21] DEBUG[31811][C-00000000] chan_sip.c: This channel will not be able to handle video. [Aug 11 16:53:21] DEBUG[31811][C-00000000] chan_sip.c: build_route: Contact hop: "354";+g.oma.sip-im;+sip.ice;language="en,fr" [Aug 11 16:53:21] VERBOSE[31811][C-00000000] chan_sip.c: list_route: route/path hop: [Aug 11 16:53:21] DEBUG[31811][C-00000000] chan_sip.c: SIP/354-00000000: New call is still down.... Trying... [Aug 11 16:53:21] VERBOSE[31811][C-00000000] chan_sip.c: ˙<--- Transmitting (no NAT) to 10.24.17.254:5060 ---> ˙SIP/2.0 100 Trying ˙Via: SIP/2.0/WS df7jal23ls0d.invalid;branch=z9hG4bKB77hSFuAvWd44BymOTS2iX25qwTUgB3o;rport;received=10.24.17.254 ˙From: "354";tag=fuBrKQ9Axy21s4KHXF3m ˙To: ˙Call-ID: 51722c7e-ab01-35ce-45d6-d6519951892e ˙CSeq: 29674 INVITE ˙Server: Asterisk PBX SVN-branch-12-r420805 ˙Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE ˙Supported: replaces, timer ˙Contact: ˙Content-Length: 0 ˙ ˙ ˙<------------> [Aug 11 16:53:21] DEBUG[31811][C-00000000] chan_sip.c: Trying to put 'SIP/2.0 100' onto WS socket destined for 10.24.17.254:5060 [Aug 11 16:53:21] DEBUG[31532] devicestate.c: No provider found, checking channel drivers for SIP - 354 [Aug 11 16:53:21] DEBUG[31532] chan_sip.c: Checking device state for peer 354 [Aug 11 16:53:21] DEBUG[31532] devicestate.c: Changing state for SIP/354 - state 1 (Not in use) [Aug 11 16:53:21] DEBUG[31812][C-00000000] pbx.c: Launching 'Answer' [Aug 11 16:53:21] DEBUG[31812][C-00000000] chan_sip.c: SIP answering channel: SIP/354-00000000 [Aug 11 16:53:21] DEBUG[31532] devicestate.c: No provider found, checking channel drivers for SIP - 354 [Aug 11 16:53:21] DEBUG[31812][C-00000000] res_rtp_asterisk.c: Setting the marker bit due to a source update [Aug 11 16:53:21] DEBUG[31532] chan_sip.c: Checking device state for peer 354 [Aug 11 16:53:21] DEBUG[31532] devicestate.c: Changing state for SIP/354 - state 1 (Not in use) [Aug 11 16:53:21] DEBUG[31812][C-00000000] chan_sip.c: Setting framing from config on incoming call [Aug 11 16:53:21] DEBUG[31812][C-00000000] chan_sip.c: ** Our capability: (alaw) Video flag: True Text flag: True [Aug 11 16:53:21] DEBUG[31812][C-00000000] chan_sip.c: ** Our prefcodec: (nothing) [Aug 11 16:53:21] VERBOSE[31812][C-00000000] chan_sip.c: Audio is at 16208 [Aug 11 16:53:21] VERBOSE[31812][C-00000000] chan_sip.c: Adding codec 100004 (alaw) to SDP [Aug 11 16:53:21] VERBOSE[31812][C-00000000] chan_sip.c: Adding non-codec 0x1 (telephone-event) to SDP [Aug 11 16:53:21] DEBUG[31812][C-00000000] chan_sip.c: -- Done with adding codecs to SDP [Aug 11 16:53:21] DEBUG[31812][C-00000000] chan_sip.c: Done building SDP. Settling with this capability: (alaw) [Aug 11 16:53:21] VERBOSE[31812][C-00000000] chan_sip.c: ˙<--- Reliably Transmitting (no NAT) to 10.24.17.254:5060 ---> ˙SIP/2.0 200 OK ˙Via: SIP/2.0/WS df7jal23ls0d.invalid;branch=z9hG4bKB77hSFuAvWd44BymOTS2iX25qwTUgB3o;rport;received=10.24.17.254 ˙From: "354";tag=fuBrKQ9Axy21s4KHXF3m ˙To: ;tag=as3ddd4046 ˙Call-ID: 51722c7e-ab01-35ce-45d6-d6519951892e ˙CSeq: 29674 INVITE ˙Server: Asterisk PBX SVN-branch-12-r420805 ˙Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE ˙Supported: replaces, timer ˙Contact: ˙Content-Type: application/sdp ˙Content-Length: 783 ˙ ˙v=0 ˙o=root 786508144 786508144 IN IP4 10.24.18.124 ˙s=Asterisk PBX SVN-branch-12-r420805 ˙c=IN IP4 10.24.18.124 ˙t=0 0 ˙m=audio 16208 RTP/SAVPF 8 126 ˙a=rtpmap:8 PCMA/8000 ˙a=rtpmap:126 telephone-event/8000 ˙a=fmtp:126 0-16 ˙a=ptime:20 ˙a=maxptime:150 ˙a=ice-ufrag:106e517c25a1e1030ddb32f52c5938a2 ˙a=ice-pwd:59bef19c067f6d0e50f34a1344d57884 ˙a=candidate:Ha18127c 1 UDP 2130706431 10.24.18.124 16208 typ host ˙a=candidate:Sd8cff501 1 UDP 1694498815 216.207.245.1 16208 typ srflx ˙a=candidate:Ha18127c 2 UDP 2130706430 10.24.18.124 16209 typ host ˙a=candidate:Sd8cff501 2 UDP 1694498814 216.207.245.1 16210 typ srflx ˙a=connection:new ˙a=setup:active ˙a=fingerprint:SHA-256 D3:4C:64:80:0A:5D:BA:49:A1:CD:56:90:20:D1:5B:B3:B5:BA:CF:41:C1:5F:F6:6A:31:C4:11:36:5F:B8:33:26 ˙a=sendrecv ˙ ˙<------------> [Aug 11 16:53:21] DEBUG[31812][C-00000000] chan_sip.c: Trying to put 'SIP/2.0 200' onto WS socket destined for 10.24.17.254:5060 [Aug 11 16:53:21] DEBUG[31556] pjsip: icess0x7fafa00 Starting checklist periodic check [Aug 11 16:53:21] DEBUG[31556] pjsip: icess0x7fafa00 .Sending connectivity check for check 1: [2] 10.24.18.124:16209-->10.24.17.254:38999 [Aug 11 16:53:21] DEBUG[31556] pjsip: stuse0x7fafa00 ...TX 144 bytes STUN message to 10.24.17.254:38999: --- begin STUN message --- STUN Binding request Hdr: length=124, magic=2112a442, tsx_id=00007b2128c9497c55651f93 Attributes: PRIORITY: length=4, value=1862270974 (0x6efffffe) ICE-CONTROLLED: length=8, data=79096e8043510184 SOFTWARE: length=0, value="pjnath-2.2.1" USERNAME: length=0, value="ewmqYw3SxymyweLI:106e517c25a1e1030ddb32f52c5938a2" MESSAGE-INTEGRITY: length=20, data=93851b1a36626858f7eb673d1224039fa6979828 FINGERPRINT: length=4, value=2698257463 (0xa0d42437) --- end of STUN message --- [Aug 11 16:53:21] DEBUG[31556] pjsip: utsx0x7faf9000 ...STUN client transaction created [Aug 11 16:53:21] DEBUG[31556] pjsip: utsx0x7faf9000 ...STUN sending message (transmit count=1) [Aug 11 16:53:21] DEBUG[31556] pjsip: icess0x7fafa00 ..Check 1: [2] 10.24.18.124:16209-->10.24.17.254:38999: state changed from Frozen to In Progress [Aug 11 16:53:21] DEBUG[31812][C-00000000] pjsip: stuse0x7fafa00 .RX 64 bytes STUN message from 10.24.17.254:38999: --- begin STUN message --- STUN Binding success response Hdr: length=44, magic=2112a442, tsx_id=00007b2128c9497c55651f93 Attributes: XOR-MAPPED-ADDRESS: length=8, IPv4 addr=10.24.18.124:16209 MESSAGE-INTEGRITY: length=20, data=a3263c1d4480ad2645f7f487f8fe2c169a998b74 FINGERPRINT: length=4, value=1715173430 (0x663b7836) --- end of STUN message --- [Aug 11 16:53:21] DEBUG[31812][C-00000000] pjsip: icess0x7fafa00 .Check 1: [2] 10.24.18.124:16209-->10.24.17.254:38999 (not nominated): connectivity check SUCCESS [Aug 11 16:53:21] DEBUG[31812][C-00000000] pjsip: icess0x7fafa00 .Check 1: [2] 10.24.18.124:16209-->10.24.17.254:38999: state changed from In Progress to Succeeded [Aug 11 16:53:21] DEBUG[31812][C-00000000] pjsip: icess0x7fafa00 .Check 2: [1] 10.24.18.124:16208-->216.207.245.1:38999: state changed from Frozen to Waiting [Aug 11 16:53:21] DEBUG[31812][C-00000000] pjsip: icess0x7fafa00 .Check 3: [2] 10.24.18.124:16209-->216.207.245.1:38999: state changed from Frozen to Waiting [Aug 11 16:53:21] DEBUG[31812][C-00000000] pjsip: icess0x7fafa00 .Check 4: [1] 10.24.18.124:16208-->10.24.17.254:0: state changed from Frozen to Waiting [Aug 11 16:53:21] DEBUG[31812][C-00000000] pjsip: icess0x7fafa00 .Check 5: [2] 10.24.18.124:16209-->10.24.17.254:0: state changed from Frozen to Waiting [Aug 11 16:53:21] DEBUG[31812][C-00000000] pjsip: icess0x7fafa00 .Check 1 is successful [Aug 11 16:53:21] DEBUG[31812][C-00000000] pjsip: stun_session.c .tdata 0x7faf900015b8 destroy request, force=0, tsx=0x7faf90001790 [Aug 11 16:53:21] DEBUG[31812][C-00000000] pjsip: utsx0x7faf9000 .STUN transaction 0x7faf90001790 schedule destroy [Aug 11 16:53:21] VERBOSE[31811] chan_sip.c: ˙<--- SIP read from WS:10.24.17.254:37591 ---> ˙ACK sip:1000@10.24.18.124:5060;transport=WS SIP/2.0 ˙Via: SIP/2.0/WS df7jal23ls0d.invalid;branch=z9hG4bKnCOupy8iyvbnMN6kr70e;rport ˙From: "354";tag=fuBrKQ9Axy21s4KHXF3m ˙To: ;tag=as3ddd4046 ˙Contact: "354";+g.oma.sip-im;+sip.ice;language="en,fr" ˙Call-ID: 51722c7e-ab01-35ce-45d6-d6519951892e ˙CSeq: 29674 ACK ˙Content-Length: 0 ˙Max-Forwards: 70 ˙Authorization: Digest username="354",realm="10.24.18.124",nonce="15cfa349",uri="sip:1000@10.24.18.124:5060;transport=WS",response="41995c15f2921ab8323d7a8b0c1a2fae",algorithm=MD5 ˙User-Agent: IM-client/OMA1.0 sipML5-v1.2014.04.18 ˙Organization: Doubango Telecom ˙ ˙<-------------> [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Header 0 [ 51]: ACK sip:1000@10.24.18.124:5060;transport=WS SIP/2.0 [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Header 1 [ 77]: Via: SIP/2.0/WS df7jal23ls0d.invalid;branch=z9hG4bKnCOupy8iyvbnMN6kr70e;rport [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Header 2 [ 58]: From: "354";tag=fuBrKQ9Axy21s4KHXF3m [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Header 3 [ 42]: To: ;tag=as3ddd4046 [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Header 4 [129]: Contact: "354";+g.oma.sip-im;+sip.ice;language="en,fr" [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Header 5 [ 45]: Call-ID: 51722c7e-ab01-35ce-45d6-d6519951892e [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Header 6 [ 15]: CSeq: 29674 ACK [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Header 7 [ 17]: Content-Length: 0 [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Header 8 [ 16]: Max-Forwards: 70 [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Header 9 [178]: Authorization: Digest username="354",realm="10.24.18.124",nonce="15cfa349",uri="sip:1000@10.24.18.124:5060;transport=WS",response="41995c15f2921ab8323d7a8b0c1a2fae",algorithm=MD5 [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Header 10 [ 49]: User-Agent: IM-client/OMA1.0 sipML5-v1.2014.04.18 [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: Header 11 [ 30]: Organization: Doubango Telecom [Aug 11 16:53:21] VERBOSE[31811] chan_sip.c: --- (12 headers 0 lines) --- [Aug 11 16:53:21] DEBUG[31811] chan_sip.c: = Looking for Call ID: 51722c7e-ab01-35ce-45d6-d6519951892e (Checking From) --From tag fuBrKQ9Axy21s4KHXF3m --To-tag as3ddd4046 [Aug 11 16:53:21] DEBUG[31811][C-00000000] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Aug 11 16:53:21] DEBUG[31811][C-00000000] chan_sip.c: Stopping retransmission on '51722c7e-ab01-35ce-45d6-d6519951892e' of Response 29674: Match Not Found [Aug 11 16:53:21] DEBUG[31556] pjsip: icess0x7fafa00 Starting checklist periodic check [Aug 11 16:53:21] DEBUG[31556] pjsip: icess0x7fafa00 .Sending connectivity check for check 2: [1] 10.24.18.124:16208-->216.207.245.1:38999 [Aug 11 16:53:21] DEBUG[31556] pjsip: stuse0x7fafa00 ...TX 144 bytes STUN message to 216.207.245.1:38999: --- begin STUN message --- STUN Binding request Hdr: length=124, magic=2112a442, tsx_id=00007b212bd74ba855651f94 Attributes: PRIORITY: length=4, value=1862270975 (0x6effffff) ICE-CONTROLLED: length=8, data=79096e8043510184 SOFTWARE: length=0, value="pjnath-2.2.1" USERNAME: length=0, value="ewmqYw3SxymyweLI:106e517c25a1e1030ddb32f52c5938a2" MESSAGE-INTEGRITY: length=20, data=856be49a5b68ec91fcab17cd13dbec779cfeafee FINGERPRINT: length=4, value=589471175 (0x23229dc7) --- end of STUN message --- [Aug 11 16:53:21] DEBUG[31556] pjsip: utsx0x7faf9000 ...STUN client transaction created [Aug 11 16:53:21] DEBUG[31556] pjsip: utsx0x7faf9000 ...STUN sending message (transmit count=1) [Aug 11 16:53:21] DEBUG[31556] pjsip: icess0x7fafa00 ..Check 2: [1] 10.24.18.124:16208-->216.207.245.1:38999: state changed from Waiting to In Progress [Aug 11 16:53:21] DEBUG[31812][C-00000000] pjsip: stuse0x7fafa00 .RX 132 bytes STUN message from 10.24.17.254:38999: --- begin STUN message --- STUN Binding request Hdr: length=112, magic=2112a442, tsx_id=43737654644c396c3879614c Attributes: USERNAME: length=49, value="106e517c25a1e1030ddb32f52c5938a2:ewmqYw3SxymyweLI" ICE-CONTROLLING: length=8, data=f1bade5d101a3489 USE-CANDIDATE: length=0 PRIORITY: length=4, value=1853824767 (0x6e7f1eff) MESSAGE-INTEGRITY: length=20, data=d78ef5fb1f2b108aee73c2c23f691ae9aadbec79 FINGERPRINT: length=4, value=3188492527 (0xbe0c88ef) --- end of STUN message --- [Aug 11 16:53:21] DEBUG[31812][C-00000000] pjsip: stuse0x7fafa00 ..TX 80 bytes STUN message to 10.24.17.254:38999: --- begin STUN message --- STUN Binding success response Hdr: length=60, magic=2112a442, tsx_id=43737654644c396c3879614c Attributes: XOR-MAPPED-ADDRESS: length=8, IPv4 addr=10.24.17.254:38999 SOFTWARE: length=0, value="pjnath-2.2.1" MESSAGE-INTEGRITY: length=20, data=10ea13dde15c04244d9626bf73bc2ba667958a50 FINGERPRINT: length=4, value=493951058 (0x1d711852) --- end of STUN message --- [Aug 11 16:53:21] DEBUG[31812][C-00000000] pjsip: icess0x7fafa00 .New triggered check added: 6 [Aug 11 16:53:21] DEBUG[31812][C-00000000] pjsip: icess0x7fafa00 ..Sending connectivity check for check 6: [2] 10.24.18.124:16209-->10.24.17.254:38999 [Aug 11 16:53:21] DEBUG[31812][C-00000000] pjsip: stuse0x7fafa00 ....TX 144 bytes STUN message to 10.24.17.254:38999: --- begin STUN message --- STUN Binding request Hdr: length=124, magic=2112a442, tsx_id=00007b21792bc82d55651f95 Attributes: PRIORITY: length=4, value=1862270974 (0x6efffffe) ICE-CONTROLLED: length=8, data=79096e8043510184 SOFTWARE: length=0, value="pjnath-2.2.1" USERNAME: length=0, value="ewmqYw3SxymyweLI:106e517c25a1e1030ddb32f52c5938a2" MESSAGE-INTEGRITY: length=20, data=8e920b7d5e7ad2f9333004f1fd6fc6ec5cbefdcd FINGERPRINT: length=4, value=3811682 (0x3a2962) --- end of STUN message --- [Aug 11 16:53:21] DEBUG[31812][C-00000000] pjsip: utsx0x7faf8c00 ....STUN client transaction created [Aug 11 16:53:21] DEBUG[31812][C-00000000] pjsip: utsx0x7faf8c00 ....STUN sending message (transmit count=1) [Aug 11 16:53:21] DEBUG[31812][C-00000000] pjsip: icess0x7fafa00 ...Check 6: [2] 10.24.18.124:16209-->10.24.17.254:38999: state changed from Waiting to In Progress [Aug 11 16:53:21] DEBUG[31812][C-00000000] pjsip: stuse0x7fafa00 .RX 132 bytes STUN message from 10.24.17.254:38999: --- begin STUN message --- STUN Binding request Hdr: length=112, magic=2112a442, tsx_id=6d62796d724c735a4252756e Attributes: USERNAME: length=49, value="106e517c25a1e1030ddb32f52c5938a2:ewmqYw3SxymyweLI" ICE-CONTROLLING: length=8, data=f1bade5d101a3489 USE-CANDIDATE: length=0 PRIORITY: length=4, value=1853824767 (0x6e7f1eff) MESSAGE-INTEGRITY: length=20, data=fe6bae136851ca5c372b1bdd4f7c4d3a268044db FINGERPRINT: length=4, value=2962728811 (0xb097a76b) --- end of STUN message --- [Aug 11 16:53:21] DEBUG[31812][C-00000000] pjsip: stuse0x7fafa00 ..TX 80 bytes STUN message to 10.24.17.254:38999: --- begin STUN message --- STUN Binding success response Hdr: length=60, magic=2112a442, tsx_id=6d62796d724c735a4252756e Attributes: XOR-MAPPED-ADDRESS: length=8, IPv4 addr=10.24.17.254:38999 SOFTWARE: length=0, value="pjnath-2.2.1" MESSAGE-INTEGRITY: length=20, data=bcb645fa88ce274aa68645bb0e9abcf36fd4c9ea FINGERPRINT: length=4, value=3074205617 (0xb73ca7b1) --- end of STUN message --- [Aug 11 16:53:21] DEBUG[31812][C-00000000] pjsip: icess0x7fafa00 .Triggered check for check 0 not performed because it's in progress. Retransmitting [Aug 11 16:53:21] DEBUG[31812][C-00000000] pjsip: utsx0x7fafa003 ..STUN sending message (transmit count=1) [Aug 11 16:53:21] DEBUG[31812][C-00000000] pjsip: stuse0x7fafa00 .RX 64 bytes STUN message from 10.24.17.254:38999: --- begin STUN message --- STUN Binding success response Hdr: length=44, magic=2112a442, tsx_id=00007b21792bc82d55651f95 Attributes: XOR-MAPPED-ADDRESS: length=8, IPv4 addr=10.24.18.124:16209 MESSAGE-INTEGRITY: length=20, data=2b425253ed606ebc3417c093f7c39028d85c24a2 FINGERPRINT: length=4, value=887367661 (0x34e427ed) --- end of STUN message --- [Aug 11 16:53:21] DEBUG[31812][C-00000000] pjsip: icess0x7fafa00 .Check 6: [2] 10.24.18.124:16209-->10.24.17.254:38999 (nominated): connectivity check SUCCESS [Aug 11 16:53:21] DEBUG[31812][C-00000000] pjsip: icess0x7fafa00 .Check 6: [2] 10.24.18.124:16209-->10.24.17.254:38999: state changed from In Progress to Succeeded [Aug 11 16:53:21] DEBUG[31812][C-00000000] pjsip: icess0x7fafa00 .Check 6 is successful and nominated [Aug 11 16:53:21] DEBUG[31812][C-00000000] pjsip: icess0x7fafa00 .Check 3: [2] 10.24.18.124:16209-->216.207.245.1:38999 to be failed because state is Waiting [Aug 11 16:53:21] DEBUG[31812][C-00000000] pjsip: icess0x7fafa00 .Check 3: [2] 10.24.18.124:16209-->216.207.245.1:38999: state changed from Waiting to Failed [Aug 11 16:53:21] DEBUG[31812][C-00000000] pjsip: icess0x7fafa00 .Check 5: [2] 10.24.18.124:16209-->10.24.17.254:0 to be failed because state is Waiting [Aug 11 16:53:21] DEBUG[31812][C-00000000] pjsip: icess0x7fafa00 .Check 5: [2] 10.24.18.124:16209-->10.24.17.254:0: state changed from Waiting to Failed [Aug 11 16:53:21] DEBUG[31812][C-00000000] pjsip: stun_session.c .tdata 0x7faf8c004508 destroy request, force=0, tsx=0x7faf8c0046e0 [Aug 11 16:53:21] DEBUG[31812][C-00000000] pjsip: utsx0x7faf8c00 .STUN transaction 0x7faf8c0046e0 schedule destroy [Aug 11 16:53:21] DEBUG[31556] pjsip: icess0x7fafa00 Starting checklist periodic check [Aug 11 16:53:21] DEBUG[31556] pjsip: icess0x7fafa00 .Sending connectivity check for check 4: [1] 10.24.18.124:16208-->10.24.17.254:0 [Aug 11 16:53:21] DEBUG[31556] pjsip: stuse0x7fafa00 ...TX 144 bytes STUN message to 10.24.17.254:0: --- begin STUN message --- STUN Binding request Hdr: length=124, magic=2112a442, tsx_id=00007b2144b8ff4155651f96 Attributes: PRIORITY: length=4, value=1862270975 (0x6effffff) ICE-CONTROLLED: length=8, data=79096e8043510184 SOFTWARE: length=0, value="pjnath-2.2.1" USERNAME: length=0, value="ewmqYw3SxymyweLI:106e517c25a1e1030ddb32f52c5938a2" MESSAGE-INTEGRITY: length=20, data=2ff328e96d62c424388736edcaa894aaad4c2155 FINGERPRINT: length=4, value=1776306042 (0x69e0477a) --- end of STUN message --- [Aug 11 16:53:21] DEBUG[31556] pjsip: utsx0x7faf9000 ...STUN client transaction created [Aug 11 16:53:21] DEBUG[31556] pjsip: utsx0x7faf9000 ...STUN sending message (transmit count=1) [Aug 11 16:53:21] DEBUG[31556] pjsip: utsx0x7faf9000 ....STUN error sending message: Invalid argument [Aug 11 16:53:21] DEBUG[31556] pjsip: stun_session.c ...tdata 0x7faf90002828 destroy request, force=0, tsx=0x7faf90002a00 [Aug 11 16:53:21] DEBUG[31556] pjsip: utsx0x7faf9000 ...STUN transaction 0x7faf90002a00 schedule destroy [Aug 11 16:53:21] DEBUG[31556] pjsip: stuse0x7fafa00 ...Error sending STUN request: Invalid argument [Aug 11 16:53:21] ERROR[31556] pjsip: icess0x7fafa00 ..Error sending STUN request: Invalid argument [Aug 11 16:53:21] DEBUG[31812][C-00000000] pjsip: stuse0x7fafa00 .RX 132 bytes STUN message from 10.24.17.254:38999: --- begin STUN message --- STUN Binding request Hdr: length=112, magic=2112a442, tsx_id=724e684b4d482f5847523774 Attributes: USERNAME: length=49, value="106e517c25a1e1030ddb32f52c5938a2:ewmqYw3SxymyweLI" ICE-CONTROLLING: length=8, data=f1bade5d101a3489 USE-CANDIDATE: length=0 PRIORITY: length=4, value=1853824767 (0x6e7f1eff) MESSAGE-INTEGRITY: length=20, data=5ff5e5e05db7ce7f6662cee3a85d93de740bb22d FINGERPRINT: length=4, value=1148126671 (0x446f05cf) --- end of STUN message --- [Aug 11 16:53:21] DEBUG[31812][C-00000000] pjsip: stuse0x7fafa00 ..TX 80 bytes STUN message to 10.24.17.254:38999: --- begin STUN message --- STUN Binding success response Hdr: length=60, magic=2112a442, tsx_id=724e684b4d482f5847523774 Attributes: XOR-MAPPED-ADDRESS: length=8, IPv4 addr=10.24.17.254:38999 SOFTWARE: length=0, value="pjnath-2.2.1" MESSAGE-INTEGRITY: length=20, data=fa94cb9aab4c5ad9efba378605cb7ec94a4a1cd4 FINGERPRINT: length=4, value=613641537 (0x24936d41) --- end of STUN message --- [Aug 11 16:53:21] DEBUG[31812][C-00000000] pjsip: icess0x7fafa00 .Valid check 1: [2] 10.24.18.124:16209-->10.24.17.254:38999 is nominated [Aug 11 16:53:21] DEBUG[31812][C-00000000] pjsip: icess0x7fafa00 .Triggered check for check 6 not performed because it's completed [Aug 11 16:53:21] DEBUG[31812][C-00000000] pjsip: icess0x7fafa00 ..Check 6 is successful and nominated [Aug 11 16:53:21] DEBUG[31812][C-00000000] pjsip: stuse0x7fafa00 .RX 64 bytes STUN message from 10.24.17.254:38999: --- begin STUN message --- STUN Binding success response Hdr: length=44, magic=2112a442, tsx_id=00007b2158cfd9e255651f92 Attributes: XOR-MAPPED-ADDRESS: length=8, IPv4 addr=10.24.18.124:16208 MESSAGE-INTEGRITY: length=20, data=d6025a50ce371c681e2a56f3a2f5c372a1e6f379 FINGERPRINT: length=4, value=3822649346 (0xe3d90002) --- end of STUN message --- [Aug 11 16:53:21] DEBUG[31812][C-00000000] pjsip: icess0x7fafa00 .Check 0: [1] 10.24.18.124:16208-->10.24.17.254:38999 (nominated): connectivity check SUCCESS [Aug 11 16:53:21] DEBUG[31812][C-00000000] pjsip: icess0x7fafa00 .Check 0: [1] 10.24.18.124:16208-->10.24.17.254:38999: state changed from In Progress to Succeeded [Aug 11 16:53:21] DEBUG[31812][C-00000000] pjsip: icess0x7fafa00 .Check 0 is successful and nominated [Aug 11 16:53:21] DEBUG[31812][C-00000000] pjsip: icess0x7fafa00 .Cancelling check 2: [1] 10.24.18.124:16208-->216.207.245.1:38999 (In Progress) [Aug 11 16:53:21] DEBUG[31812][C-00000000] pjsip: stun_session.c .tdata 0x7faf90002028 destroy request, force=0, tsx=0x7faf90002200 [Aug 11 16:53:21] DEBUG[31812][C-00000000] pjsip: utsx0x7faf9000 .STUN transaction 0x7faf90002200 schedule destroy [Aug 11 16:53:21] DEBUG[31812][C-00000000] pjsip: icess0x7fafa00 .Check 2: [1] 10.24.18.124:16208-->216.207.245.1:38999: state changed from In Progress to Failed [Aug 11 16:53:21] DEBUG[31812][C-00000000] pjsip: icess0x7fafa00 .Check 4: [1] 10.24.18.124:16208-->10.24.17.254:0 to be failed because state is Waiting [Aug 11 16:53:21] DEBUG[31812][C-00000000] pjsip: icess0x7fafa00 .Check 4: [1] 10.24.18.124:16208-->10.24.17.254:0: state changed from Waiting to Failed [Aug 11 16:53:21] DEBUG[31812][C-00000000] pjsip: icess0x7fafa00 .ICE process complete, status=Success [Aug 11 16:53:21] DEBUG[31812][C-00000000] pjsip: icess0x7fafa00 .Valid list [Aug 11 16:53:21] DEBUG[31812][C-00000000] pjsip: icess0x7fafa00 . 0: [1] 10.24.18.124:16208-->10.24.17.254:38999 (nominated, state=Succeeded) [Aug 11 16:53:21] DEBUG[31812][C-00000000] pjsip: icess0x7fafa00 . 1: [2] 10.24.18.124:16209-->10.24.17.254:38999 (nominated, state=Succeeded) [Aug 11 16:53:21] DEBUG[31812][C-00000000] pjsip: icess0x7fafa00 . 2: [2] 10.24.18.124:16209-->10.24.17.254:38999 (not nominated, state=Succeeded) [Aug 11 16:53:21] DEBUG[31812][C-00000000] pjsip: stun_session.c .tdata 0x7fafa0033cc8 destroy request, force=0, tsx=0x7fafa0033ea0 [Aug 11 16:53:21] DEBUG[31812][C-00000000] pjsip: utsx0x7fafa003 .STUN transaction 0x7fafa0033ea0 schedule destroy [Aug 11 16:53:21] DEBUG[31812][C-00000000] pjsip: stuse0x7fafa00 .RX 132 bytes STUN message from 10.24.17.254:38999: --- begin STUN message --- STUN Binding request Hdr: length=112, magic=2112a442, tsx_id=4669766b33596356316e7670 Attributes: USERNAME: length=49, value="106e517c25a1e1030ddb32f52c5938a2:ewmqYw3SxymyweLI" ICE-CONTROLLING: length=8, data=f1bade5d101a3489 USE-CANDIDATE: length=0 PRIORITY: length=4, value=1853824767 (0x6e7f1eff) MESSAGE-INTEGRITY: length=20, data=172243b1a0a1ff91b8c352b22630dab07ba1c605 FINGERPRINT: length=4, value=858898566 (0x3331c086) --- end of STUN message --- [Aug 11 16:53:21] DEBUG[31812][C-00000000] pjsip: stuse0x7fafa00 ..TX 80 bytes STUN message to 10.24.17.254:38999: --- begin STUN message --- STUN Binding success response Hdr: length=60, magic=2112a442, tsx_id=4669766b33596356316e7670 Attributes: XOR-MAPPED-ADDRESS: length=8, IPv4 addr=10.24.17.254:38999 SOFTWARE: length=0, value="pjnath-2.2.1" MESSAGE-INTEGRITY: length=20, data=f29231d5d7366edbd03b8647fe57b9c1a4e207d7 FINGERPRINT: length=4, value=4040216963 (0xf0d0d183) --- end of STUN message --- [Aug 11 16:53:21] DEBUG[31812][C-00000000] pjsip: icess0x7fafa00 .Valid check 0: [1] 10.24.18.124:16208-->10.24.17.254:38999 is nominated [Aug 11 16:53:21] DEBUG[31812][C-00000000] pjsip: icess0x7fafa00 .Triggered check for check 0 not performed because it's completed [Aug 11 16:53:21] DEBUG[31812][C-00000000] pjsip: icess0x7fafa00 ..Check 0 is successful and nominated [Aug 11 16:53:21] DEBUG[31556] pjsip: utsx0x7faf9000 STUN client transaction 0x7faf90001790 stopped, ref_cnt=13 [Aug 11 16:53:21] DEBUG[31556] pjsip: stun_session.c STUN transaction 0x7faf90001790 destroyed [Aug 11 16:53:22] DEBUG[31556] pjsip: utsx0x7faf8c00 STUN client transaction 0x7faf8c0046e0 stopped, ref_cnt=12 [Aug 11 16:53:22] DEBUG[31556] pjsip: stun_session.c STUN transaction 0x7faf8c0046e0 destroyed [Aug 11 16:53:22] DEBUG[31556] pjsip: utsx0x7faf9000 STUN client transaction 0x7faf90002a00 stopped, ref_cnt=11 [Aug 11 16:53:22] DEBUG[31556] pjsip: stun_session.c STUN transaction 0x7faf90002a00 destroyed [Aug 11 16:53:22] DEBUG[31556] pjsip: utsx0x7fafa003 STUN client transaction 0x7fafa0033ea0 stopped, ref_cnt=10 [Aug 11 16:53:22] DEBUG[31556] pjsip: stun_session.c STUN transaction 0x7fafa0033ea0 destroyed [Aug 11 16:53:22] DEBUG[31556] pjsip: utsx0x7faf9000 STUN client transaction 0x7faf90002200 stopped, ref_cnt=9 [Aug 11 16:53:22] DEBUG[31556] pjsip: stun_session.c STUN transaction 0x7faf90002200 destroyed [Aug 11 16:53:22] DEBUG[31812][C-00000000] channel.c: Didn't receive a media frame from SIP/354-00000000 within 500 ms of answering. Continuing anyway [Aug 11 16:53:22] DEBUG[31812][C-00000000] pbx.c: Launching 'Playback' [Aug 11 16:53:22] DEBUG[31812][C-00000000] channel.c: Set channel SIP/354-00000000 to write format gsm [Aug 11 16:53:22] DEBUG[31812][C-00000000] res_rtp_asterisk.c: Ooh, format changed from unknown to alaw [Aug 11 16:53:22] DEBUG[31812][C-00000000] res_rtp_asterisk.c: Created smoother: format: alaw ms: 20 len: 160 [Aug 11 16:53:22] DEBUG[31812][C-00000000] res_rtp_asterisk.c: Starting RTCP transmission on RTP instance '0x7fafa0024d08' [Aug 11 16:53:22] DEBUG[31812][C-00000000] netsock2.c: Splitting '10.24.17.254' into... [Aug 11 16:53:22] DEBUG[31812][C-00000000] netsock2.c: ...host '10.24.17.254' and port ''. [Aug 11 16:53:22] DEBUG[31812][C-00000000] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Aug 11 16:53:22] DEBUG[31812][C-00000000] netsock2.c: Splitting '10.24.17.254' into... [Aug 11 16:53:22] DEBUG[31812][C-00000000] netsock2.c: ...host '10.24.17.254' and port ''. [Aug 11 16:53:22] DEBUG[31812][C-00000000] netsock2.c: Splitting '10.24.17.254' into... [Aug 11 16:53:22] DEBUG[31812][C-00000000] netsock2.c: ...host '10.24.17.254' and port ''. [Aug 11 16:53:22] DEBUG[31812][C-00000000] netsock2.c: Splitting '10.24.17.254' into... [Aug 11 16:53:22] DEBUG[31812][C-00000000] netsock2.c: ...host '10.24.17.254' and port ''. [Aug 11 16:53:22] DEBUG[31812][C-00000000] pjsip: stuse0x7fafa00 .RX 132 bytes STUN message from 10.24.17.254:38999: --- begin STUN message --- STUN Binding request Hdr: length=112, magic=2112a442, tsx_id=34474b345354336f2f2f6777 Attributes: USERNAME: length=49, value="106e517c25a1e1030ddb32f52c5938a2:ewmqYw3SxymyweLI" ICE-CONTROLLING: length=8, data=f1bade5d101a3489 USE-CANDIDATE: length=0 PRIORITY: length=4, value=1853824767 (0x6e7f1eff) MESSAGE-INTEGRITY: length=20, data=5d449a9ae03ce67233e498bd258e19e98e77c3fe FINGERPRINT: length=4, value=2202401494 (0x8345fad6) --- end of STUN message --- [Aug 11 16:53:22] DEBUG[31812][C-00000000] pjsip: stuse0x7fafa00 ..TX 80 bytes STUN message to 10.24.17.254:38999: --- begin STUN message --- STUN Binding success response Hdr: length=60, magic=2112a442, tsx_id=34474b345354336f2f2f6777 Attributes: XOR-MAPPED-ADDRESS: length=8, IPv4 addr=10.24.17.254:38999 SOFTWARE: length=0, value="pjnath-2.2.1" MESSAGE-INTEGRITY: length=20, data=23cc1486535d66f343dc427653a330b4ceebf9d9 FINGERPRINT: length=4, value=1568418775 (0x5d7c2bd7) --- end of STUN message --- [Aug 11 16:53:22] DEBUG[31812][C-00000000] pjsip: icess0x7fafa00 .Valid check 1: [2] 10.24.18.124:16209-->10.24.17.254:38999 is nominated [Aug 11 16:53:22] DEBUG[31812][C-00000000] pjsip: icess0x7fafa00 .Triggered check for check 6 not performed because it's completed [Aug 11 16:53:22] DEBUG[31812][C-00000000] pjsip: icess0x7fafa00 ..Check 6 is successful and nominated [Aug 11 16:53:22] DEBUG[31812][C-00000000] netsock2.c: Splitting '10.24.17.254' into... [Aug 11 16:53:22] DEBUG[31812][C-00000000] netsock2.c: ...host '10.24.17.254' and port ''. [Aug 11 16:53:22] DEBUG[31812][C-00000000] netsock2.c: Splitting '10.24.17.254' into... [Aug 11 16:53:22] DEBUG[31812][C-00000000] netsock2.c: ...host '10.24.17.254' and port ''. [Aug 11 16:53:22] DEBUG[31812][C-00000000] netsock2.c: Splitting '10.24.17.254' into... [Aug 11 16:53:22] DEBUG[31812][C-00000000] netsock2.c: ...host '10.24.17.254' and port ''. [Aug 11 16:53:22] DEBUG[31812][C-00000000] pjsip: stuse0x7fafa00 .RX 132 bytes STUN message from 10.24.17.254:38999: --- begin STUN message --- STUN Binding request Hdr: length=112, magic=2112a442, tsx_id=656b34766f397635734e4d6e Attributes: USERNAME: length=49, value="106e517c25a1e1030ddb32f52c5938a2:ewmqYw3SxymyweLI" ICE-CONTROLLING: length=8, data=f1bade5d101a3489 USE-CANDIDATE: length=0 PRIORITY: length=4, value=1853824767 (0x6e7f1eff) MESSAGE-INTEGRITY: length=20, data=3afa2b02125f4a2890510a9a5daba08a9c6df395 FINGERPRINT: length=4, value=1546937320 (0x5c3463e8) --- end of STUN message --- [Aug 11 16:53:22] DEBUG[31812][C-00000000] pjsip: stuse0x7fafa00 ..TX 80 bytes STUN message to 10.24.17.254:38999: --- begin STUN message --- STUN Binding success response Hdr: length=60, magic=2112a442, tsx_id=656b34766f397635734e4d6e Attributes: XOR-MAPPED-ADDRESS: length=8, IPv4 addr=10.24.17.254:38999 SOFTWARE: length=0, value="pjnath-2.2.1" MESSAGE-INTEGRITY: length=20, data=60c20286b9994e13169d4952699a8e96817894cc FINGERPRINT: length=4, value=4193798093 (0xf9f847cd) --- end of STUN message --- [Aug 11 16:53:22] DEBUG[31812][C-00000000] pjsip: icess0x7fafa00 .Valid check 0: [1] 10.24.18.124:16208-->10.24.17.254:38999 is nominated [Aug 11 16:53:22] DEBUG[31812][C-00000000] pjsip: icess0x7fafa00 .Triggered check for check 0 not performed because it's completed [Aug 11 16:53:22] DEBUG[31812][C-00000000] pjsip: icess0x7fafa00 ..Check 0 is successful and nominated [Aug 11 16:53:22] DEBUG[31812][C-00000000] netsock2.c: Splitting '10.24.17.254' into... [Aug 11 16:53:22] DEBUG[31812][C-00000000] netsock2.c: ...host '10.24.17.254' and port ''. [Aug 11 16:53:22] DEBUG[31812][C-00000000] netsock2.c: Splitting '10.24.17.254' into... [Aug 11 16:53:22] DEBUG[31812][C-00000000] netsock2.c: ...host '10.24.17.254' and port ''. [Aug 11 16:53:22] DEBUG[31812][C-00000000] netsock2.c: Splitting '10.24.17.254' into... [Aug 11 16:53:22] DEBUG[31812][C-00000000] netsock2.c: ...host '10.24.17.254' and port ''. [Aug 11 16:53:22] DEBUG[31812][C-00000000] netsock2.c: Splitting '10.24.17.254' into... [Aug 11 16:53:22] DEBUG[31812][C-00000000] netsock2.c: ...host '10.24.17.254' and port ''. [Aug 11 16:53:22] DEBUG[31812][C-00000000] netsock2.c: Splitting '10.24.17.254' into... [Aug 11 16:53:22] DEBUG[31812][C-00000000] netsock2.c: ...host '10.24.17.254' and port ''. [Aug 11 16:53:22] DEBUG[31812][C-00000000] netsock2.c: Splitting '10.24.17.254' into... [Aug 11 16:53:22] DEBUG[31812][C-00000000] netsock2.c: ...host '10.24.17.254' and port ''. [Aug 11 16:53:22] DEBUG[31812][C-00000000] netsock2.c: Splitting '10.24.17.254' into... [Aug 11 16:53:22] DEBUG[31812][C-00000000] netsock2.c: ...host '10.24.17.254' and port ''. [Aug 11 16:53:22] DEBUG[31812][C-00000000] netsock2.c: Splitting '10.24.17.254' into... [Aug 11 16:53:22] DEBUG[31812][C-00000000] netsock2.c: ...host '10.24.17.254' and port ''. [Aug 11 16:53:22] DEBUG[31812][C-00000000] netsock2.c: Splitting '10.24.17.254' into... [Aug 11 16:53:22] DEBUG[31812][C-00000000] netsock2.c: ...host '10.24.17.254' and port ''. [Aug 11 16:53:22] DEBUG[31812][C-00000000] netsock2.c: Splitting '10.24.17.254' into... [Aug 11 16:53:22] DEBUG[31812][C-00000000] netsock2.c: ...host '10.24.17.254' and port ''. [Aug 11 16:53:22] DEBUG[31812][C-00000000] netsock2.c: Splitting '10.24.17.254' into... [Aug 11 16:53:22] DEBUG[31812][C-00000000] netsock2.c: ...host '10.24.17.254' and port ''. [Aug 11 16:53:22] DEBUG[31812][C-00000000] netsock2.c: Splitting '10.24.17.254' into... [Aug 11 16:53:22] DEBUG[31812][C-00000000] netsock2.c: ...host '10.24.17.254' and port ''. [Aug 11 16:53:22] DEBUG[31812][C-00000000] netsock2.c: Splitting '10.24.17.254' into... [Aug 11 16:53:22] DEBUG[31812][C-00000000] netsock2.c: ...host '10.24.17.254' and port ''. [Aug 11 16:53:22] DEBUG[31812][C-00000000] netsock2.c: Splitting '10.24.17.254' into... [Aug 11 16:53:22] DEBUG[31812][C-00000000] netsock2.c: ...host '10.24.17.254' and port ''. [Aug 11 16:53:22] DEBUG[31812][C-00000000] netsock2.c: Splitting '10.24.17.254' into... [Aug 11 16:53:22] DEBUG[31812][C-00000000] netsock2.c: ...host '10.24.17.254' and port ''. [Aug 11 16:53:22] DEBUG[31812][C-00000000] netsock2.c: Splitting '10.24.17.254' into... [Aug 11 16:53:22] DEBUG[31812][C-00000000] netsock2.c: ...host '10.24.17.254' and port ''. [Aug 11 16:53:22] DEBUG[31812][C-00000000] netsock2.c: Splitting '10.24.17.254' into... [Aug 11 16:53:22] DEBUG[31812][C-00000000] netsock2.c: ...host '10.24.17.254' and port ''. [Aug 11 16:53:22] DEBUG[31812][C-00000000] netsock2.c: Splitting '10.24.17.254' into... [Aug 11 16:53:22] DEBUG[31812][C-00000000] netsock2.c: ...host '10.24.17.254' and port ''. [Aug 11 16:53:22] DEBUG[31812][C-00000000] netsock2.c: Splitting '10.24.17.254' into... [Aug 11 16:53:22] DEBUG[31812][C-00000000] netsock2.c: ...host '10.24.17.254' and port ''. [Aug 11 16:53:22] ERROR[31812][C-00000000] res_rtp_asterisk.c: DTLS failure occurred on RTP instance '0x7fafa0024d08' due to reason '(null)', terminating [Aug 11 16:53:22] WARNING[31812][C-00000000] res_rtp_asterisk.c: RTP Read error: Unspecified. Hanging up. [Aug 11 16:53:22] DEBUG[31812][C-00000000] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Aug 11 16:53:22] DEBUG[31812][C-00000000] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Aug 11 16:53:22] DEBUG[31812][C-00000000] channel.c: Set channel SIP/354-00000000 to write format alaw [Aug 11 16:53:22] WARNING[31812][C-00000000] app_playback.c: Playback failed on SIP/354-00000000 for demo-congrats [Aug 11 16:53:22] DEBUG[31812][C-00000000] pbx.c: Extension 1000, priority 2 returned normally even though call was hung up [Aug 11 16:53:22] DEBUG[31812][C-00000000] channel.c: Soft-Hanging (0x10) up channel 'SIP/354-00000000' [Aug 11 16:53:22] DEBUG[31812][C-00000000] channel.c: Hanging up channel 'SIP/354-00000000' [Aug 11 16:53:22] DEBUG[31812][C-00000000] chan_sip.c: Hangup call SIP/354-00000000, SIP callid 51722c7e-ab01-35ce-45d6-d6519951892e [Aug 11 16:53:22] DEBUG[31812][C-00000000] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fafa0024d08' [Aug 11 16:53:22] VERBOSE[31812][C-00000000] chan_sip.c: Scheduling destruction of SIP dialog '51722c7e-ab01-35ce-45d6-d6519951892e' in 32000 ms (Method: INVITE) [Aug 11 16:53:22] DEBUG[31812][C-00000000] chan_sip.c: Strict routing enforced for session 51722c7e-ab01-35ce-45d6-d6519951892e [Aug 11 16:53:22] VERBOSE[31812][C-00000000] chan_sip.c: set_destination: Parsing for address/port to send to [Aug 11 16:53:22] VERBOSE[31812][C-00000000] chan_sip.c: set_destination: URI is for WebSocket, we can't set destination [Aug 11 16:53:22] VERBOSE[31812][C-00000000] chan_sip.c: Reliably Transmitting (no NAT) to 10.24.17.254:5060: ˙BYE sip:354@df7jal23ls0d.invalid;rtcweb-breaker=no;click2call=no;transport=ws SIP/2.0 ˙Via: SIP/2.0/WS 10.24.18.124:5060;branch=z9hG4bK7f63662e ˙Max-Forwards: 70 ˙From: ;tag=as3ddd4046 ˙To: "354";tag=fuBrKQ9Axy21s4KHXF3m ˙Call-ID: 51722c7e-ab01-35ce-45d6-d6519951892e ˙CSeq: 102 BYE ˙User-Agent: Asterisk PBX SVN-branch-12-r420805 ˙Proxy-Authorization: Digest username="354", realm="10.24.18.124", algorithm=MD5, uri="sip:10.24.18.124", nonce="15cfa349", response="2a7ebfa6a5ba5a047b63ab9d2a5be793" ˙X-Asterisk-HangupCause: Unknown ˙X-Asterisk-HangupCauseCode: 0 ˙Content-Length: 0 ˙ ˙ ˙--- [Aug 11 16:53:22] DEBUG[31812][C-00000000] chan_sip.c: Trying to put 'BYE sip:354' onto WS socket destined for 10.24.17.254:5060 [Aug 11 16:53:22] DEBUG[31534] cdr.c: Finalized CDR for SIP/354-00000000 - start 1407794001.643590 answer 1407794001.645146 end 1407794002.652939 dispo ANSWERED [Aug 11 16:53:22] DEBUG[31532] devicestate.c: No provider found, checking channel drivers for SIP - 354 [Aug 11 16:53:22] DEBUG[31532] chan_sip.c: Checking device state for peer 354 [Aug 11 16:53:22] DEBUG[31532] devicestate.c: Changing state for SIP/354 - state 1 (Not in use) [Aug 11 16:53:22] VERBOSE[31811] chan_sip.c: ˙<--- SIP read from WS:10.24.17.254:37591 ---> ˙SIP/2.0 200 OK ˙Via: SIP/2.0/WS 10.24.18.124:5060;branch=z9hG4bK7f63662e ˙From: ;tag=as3ddd4046 ˙To: "354";tag=fuBrKQ9Axy21s4KHXF3m ˙Contact: ˙Call-ID: 51722c7e-ab01-35ce-45d6-d6519951892e ˙CSeq: 102 BYE ˙Content-Length: 0 ˙ ˙<-------------> [Aug 11 16:53:22] DEBUG[31811] chan_sip.c: Header 0 [ 14]: SIP/2.0 200 OK [Aug 11 16:53:22] DEBUG[31811] chan_sip.c: Header 1 [ 56]: Via: SIP/2.0/WS 10.24.18.124:5060;branch=z9hG4bK7f63662e [Aug 11 16:53:22] DEBUG[31811] chan_sip.c: Header 2 [ 44]: From: ;tag=as3ddd4046 [Aug 11 16:53:22] DEBUG[31811] chan_sip.c: Header 3 [ 56]: To: "354";tag=fuBrKQ9Axy21s4KHXF3m [Aug 11 16:53:22] DEBUG[31811] chan_sip.c: Header 4 [ 52]: Contact: [Aug 11 16:53:22] DEBUG[31811] chan_sip.c: Header 5 [ 45]: Call-ID: 51722c7e-ab01-35ce-45d6-d6519951892e [Aug 11 16:53:22] DEBUG[31811] chan_sip.c: Header 6 [ 13]: CSeq: 102 BYE [Aug 11 16:53:22] DEBUG[31811] chan_sip.c: Header 7 [ 17]: Content-Length: 0 [Aug 11 16:53:22] VERBOSE[31811] chan_sip.c: --- (8 headers 0 lines) --- [Aug 11 16:53:22] DEBUG[31811] chan_sip.c: = Looking for Call ID: 51722c7e-ab01-35ce-45d6-d6519951892e (Checking To) --From tag as3ddd4046 --To-tag fuBrKQ9Axy21s4KHXF3m [Aug 11 16:53:22] VERBOSE[31811][C-00000000] chan_sip.c: SIP Response message for INCOMING dialog BYE arrived [Aug 11 16:53:23] DEBUG[31578] chan_sip.c: Destroying SIP dialog 51722c7e-ab01-35ce-45d6-d6519951892e [Aug 11 16:53:23] VERBOSE[31578] chan_sip.c: Really destroying SIP dialog '51722c7e-ab01-35ce-45d6-d6519951892e' Method: INVITE [Aug 11 16:53:23] DEBUG[31578] pjsip: icess0x7fafa00 Destroying ICE session 0x7fafa00185a8 [Aug 11 16:53:23] DEBUG[31578] pjsip: stuse0x7fafa00 STUN session 0x7fafa0038108 destroy request, ref_cnt=10 [Aug 11 16:53:23] DEBUG[31578] pjsip: stuse0x7fafa00 STUN session 0x7fafa0015b28 destroy request, ref_cnt=6 [Aug 11 16:53:23] DEBUG[31578] pjsip: ice_session.c ICE session 0x7fafa00185a8 destroyed [Aug 11 16:53:23] DEBUG[31578] pjsip: stun_session.c tdata 0x7faf8c027d88 destroy request, force=1, tsx=(nil) [Aug 11 16:53:23] DEBUG[31578] pjsip: stun_session.c tdata 0x7faf8c0050f8 destroy request, force=1, tsx=(nil) [Aug 11 16:53:23] DEBUG[31578] pjsip: stun_session.c tdata 0x7faf8c038368 destroy request, force=1, tsx=(nil) [Aug 11 16:53:23] DEBUG[31578] pjsip: stun_session.c STUN session 0x7fafa0038108 destroyed [Aug 11 16:53:23] DEBUG[31578] pjsip: stun_session.c tdata 0x7faf8c0023e8 destroy request, force=1, tsx=(nil) [Aug 11 16:53:23] DEBUG[31578] pjsip: stun_session.c tdata 0x7faf8c0258e8 destroy request, force=1, tsx=(nil) [Aug 11 16:53:23] DEBUG[31578] pjsip: stun_session.c tdata 0x7faf8c037b68 destroy request, force=1, tsx=(nil) [Aug 11 16:53:23] DEBUG[31578] pjsip: stun_session.c STUN session 0x7fafa0015b28 destroyed [Aug 11 16:53:23] DEBUG[31578] rtp_engine.c: Destroyed RTP instance '0x7fafa0024d08' [Aug 11 16:53:34] DEBUG[31596] cdr.c: CDR Engine termination request received; waiting on messages... [Aug 11 16:53:34] DEBUG[31596] taskprocessor.c: destroying taskprocessor 'ast_msg_queue' [Aug 11 16:53:34] VERBOSE[31596] asterisk.c: Asterisk cleanly ending (0). [Aug 11 16:53:34] VERBOSE[31596] asterisk.c: Executing last minute cleanups [Aug 11 16:53:34] DEBUG[31596] res_musiconhold.c: Destroying MOH class 'default' [Aug 11 16:53:34] DEBUG[31596] taskprocessor.c: destroying taskprocessor 'e83280c9-3e17-4cdf-87ba-f4882f12e82f' [Aug 11 16:53:35] DEBUG[31596] logger.c: Unregistered dynamic logger level 'CC' with index 16. [Aug 11 16:53:35] DEBUG[31596] taskprocessor.c: destroying taskprocessor 'CCSS core' [Aug 11 16:53:35] DEBUG[31596] tcptls.c: Stopped server :: AMI server [Aug 11 16:53:35] DEBUG[31596] tcptls.c: Stopped server :: AMI TLS server [Aug 11 16:53:35] DEBUG[31596] channel.c: Unregistering channel type 'Local' [Aug 11 16:53:35] DEBUG[31596] taskprocessor.c: destroying taskprocessor '131f191b-1a0d-43ef-9c2f-3cc306f4a75c' [Aug 11 16:53:35] DEBUG[31596] taskprocessor.c: destroying taskprocessor '683153d2-8ed0-47d4-aa7f-bafa432f8e09' [Aug 11 16:53:35] DEBUG[31534] taskprocessor.c: destroying taskprocessor '537e9469-c989-45e7-92e8-2756afe7b74c' [Aug 11 16:53:35] DEBUG[31596] tcptls.c: Stopped server :: http server [Aug 11 16:53:35] DEBUG[31596] bridge.c: Waiting for bridge manager thread to die. [Aug 11 16:53:35] DEBUG[31596] channel.c: Unregistering channel type 'Surrogate' [Aug 11 16:53:35] DEBUG[31596] taskprocessor.c: destroying taskprocessor 'Sorcery-control' [Aug 11 16:53:35] DEBUG[31596] taskprocessor.c: destroying taskprocessor 'Sorcery' [Aug 11 16:53:35] DEBUG[31596] asterisk.c: Asterisk ending (0).