[Aug 11 16:31:30] 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:31:30] DEBUG[31013] config.c: Parsing /etc/asterisk/logger.conf [Aug 11 16:31:40] VERBOSE[31256] chan_sip.c: ˙<--- SIP read from WS:10.24.17.254:37587 ---> ˙INVITE sip:1000@10.24.18.124 SIP/2.0 ˙Via: SIP/2.0/WS df7jal23ls0d.invalid;branch=z9hG4bKh85AgcDeAlVPxuh9aAXDGhyuuQVkOD8g;rport ˙From: "354";tag=yB3kheDC1hkF4DX5eiCm ˙To: ˙Contact: "354";+g.oma.sip-im;+sip.ice;language="en,fr" ˙Call-ID: c2cd395f-d7d2-26da-3ae0-4b5881316cc1 ˙CSeq: 21407 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=- 8594674609699288000 2 IN IP4 127.0.0.1 ˙s=Doubango Telecom - chrome ˙t=0 0 ˙a=group:BUNDLE audio ˙a=msid-semantic: WMS pZPNqZCjAk1d9vjQ4I4IabAtNELBe3ARv2Oy ˙m=audio 58858 UDP/TLS/RTP/SAVPF 111 103 104 0 8 106 105 13 126 ˙c=IN IP4 216.207.245.1 ˙a=rtcp:58858 IN IP4 216.207.245.1 ˙a=candidate:1877610657 1 udp 2122260223 10.24.17.254 58858 typ host generation 0 ˙a=candidate:1877610657 2 udp 2122260223 10.24.17.254 58858 typ host generation 0 ˙a=candidate:2583325045 1 udp 1686052607 216.207.245.1 58858 typ srflx raddr 10.24.17.254 rport 58858 generation 0 ˙a=candidate:2583325045 2 udp 1686052607 216.207.245.1 58858 typ srflx raddr 10.24.17.254 rport 58858 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:s1o+TB82UPCSjuDE ˙a=ice-pwd:3QqmciO3GSo0x9fI+SFqkGB9 ˙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:3595826006 cname:ke4//16d6EF+2Xig ˙a=ssrc:3595826006 msid:pZPNqZCjAk1d9vjQ4I4IabAtNELBe3ARv2Oy 8456089a-ec01-4528-a3b8-65ddd6606fd1 ˙a=ssrc:3595826006 mslabel:pZPNqZCjAk1d9vjQ4I4IabAtNELBe3ARv2Oy ˙a=ssrc:3595826006 label:8456089a-ec01-4528-a3b8-65ddd6606fd1 ˙<-------------> [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Header 0 [ 36]: INVITE sip:1000@10.24.18.124 SIP/2.0 [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Header 1 [ 89]: Via: SIP/2.0/WS df7jal23ls0d.invalid;branch=z9hG4bKh85AgcDeAlVPxuh9aAXDGhyuuQVkOD8g;rport [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Header 2 [ 58]: From: "354";tag=yB3kheDC1hkF4DX5eiCm [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Header 3 [ 27]: To: [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Header 4 [129]: Contact: "354";+g.oma.sip-im;+sip.ice;language="en,fr" [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Header 5 [ 45]: Call-ID: c2cd395f-d7d2-26da-3ae0-4b5881316cc1 [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Header 6 [ 18]: CSeq: 21407 INVITE [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Header 7 [ 29]: Content-Type: application/sdp [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Header 8 [ 20]: Content-Length: 1757 [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Header 9 [ 16]: Max-Forwards: 70 [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Header 10 [ 49]: User-Agent: IM-client/OMA1.0 sipML5-v1.2014.04.18 [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Header 11 [ 30]: Organization: Doubango Telecom [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Header 12 [ 0]: [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Body 0 [ 3]: v=0 [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Body 1 [ 42]: o=- 8594674609699288000 2 IN IP4 127.0.0.1 [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Body 2 [ 27]: s=Doubango Telecom - chrome [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Body 3 [ 5]: t=0 0 [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Body 4 [ 20]: a=group:BUNDLE audio [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Body 5 [ 57]: a=msid-semantic: WMS pZPNqZCjAk1d9vjQ4I4IabAtNELBe3ARv2Oy [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Body 6 [ 62]: m=audio 58858 UDP/TLS/RTP/SAVPF 111 103 104 0 8 106 105 13 126 [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Body 7 [ 22]: c=IN IP4 216.207.245.1 [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Body 8 [ 33]: a=rtcp:58858 IN IP4 216.207.245.1 [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Body 9 [ 80]: a=candidate:1877610657 1 udp 2122260223 10.24.17.254 58858 typ host generation 0 [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Body 10 [ 80]: a=candidate:1877610657 2 udp 2122260223 10.24.17.254 58858 typ host generation 0 [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Body 11 [113]: a=candidate:2583325045 1 udp 1686052607 216.207.245.1 58858 typ srflx raddr 10.24.17.254 rport 58858 generation 0 [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Body 12 [113]: a=candidate:2583325045 2 udp 1686052607 216.207.245.1 58858 typ srflx raddr 10.24.17.254 rport 58858 generation 0 [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Body 13 [ 75]: a=candidate:560589905 1 tcp 1518280447 10.24.17.254 0 typ host generation 0 [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Body 14 [ 75]: a=candidate:560589905 2 tcp 1518280447 10.24.17.254 0 typ host generation 0 [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Body 15 [ 28]: a=ice-ufrag:s1o+TB82UPCSjuDE [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Body 16 [ 34]: a=ice-pwd:3QqmciO3GSo0x9fI+SFqkGB9 [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Body 17 [ 24]: a=ice-options:google-ice [Aug 11 16:31:40] DEBUG[31256] 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:31:40] DEBUG[31256] chan_sip.c: Body 19 [ 15]: a=setup:actpass [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Body 20 [ 11]: a=mid:audio [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Body 21 [ 54]: a=extmap:1 urn:ietf:params:rtp-hdrext:ssrc-audio-level [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Body 22 [ 69]: a=extmap:3 http://www.webrtc.org/experiments/rtp-hdrext/abs-send-time [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Body 23 [ 10]: a=sendrecv [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Body 24 [ 10]: a=rtcp-mux [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Body 25 [ 25]: a=rtpmap:111 opus/48000/2 [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Body 26 [ 22]: a=fmtp:111 minptime=10 [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Body 27 [ 23]: a=rtpmap:103 ISAC/16000 [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Body 28 [ 23]: a=rtpmap:104 ISAC/32000 [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Body 29 [ 20]: a=rtpmap:0 PCMU/8000 [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Body 30 [ 20]: a=rtpmap:8 PCMA/8000 [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Body 31 [ 21]: a=rtpmap:106 CN/32000 [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Body 32 [ 21]: a=rtpmap:105 CN/16000 [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Body 33 [ 19]: a=rtpmap:13 CN/8000 [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Body 34 [ 33]: a=rtpmap:126 telephone-event/8000 [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Body 35 [ 13]: a=maxptime:60 [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Body 36 [ 40]: a=ssrc:3595826006 cname:ke4//16d6EF+2Xig [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Body 37 [ 96]: a=ssrc:3595826006 msid:pZPNqZCjAk1d9vjQ4I4IabAtNELBe3ARv2Oy 8456089a-ec01-4528-a3b8-65ddd6606fd1 [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Body 38 [ 62]: a=ssrc:3595826006 mslabel:pZPNqZCjAk1d9vjQ4I4IabAtNELBe3ARv2Oy [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Body 39 [ 60]: a=ssrc:3595826006 label:8456089a-ec01-4528-a3b8-65ddd6606fd1 [Aug 11 16:31:40] VERBOSE[31256] chan_sip.c: --- (12 headers 40 lines) --- [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: = Looking for Call ID: c2cd395f-d7d2-26da-3ae0-4b5881316cc1 (Checking From) --From tag yB3kheDC1hkF4DX5eiCm --To-tag [Aug 11 16:31:40] DEBUG[31256] acl.c: For destination '10.24.17.254', our source address is '10.24.18.124'. [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Setting AST_TRANSPORT_WS with address 10.24.18.124:5060 [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Allocating new SIP dialog for c2cd395f-d7d2-26da-3ae0-4b5881316cc1 - INVITE (No RTP) [Aug 11 16:31:40] DEBUG[31256][C-00000005] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Aug 11 16:31:40] DEBUG[31256][C-00000005] chan_sip.c: Initializing initreq for method INVITE - callid c2cd395f-d7d2-26da-3ae0-4b5881316cc1 [Aug 11 16:31:40] VERBOSE[31256][C-00000005] chan_sip.c: Using INVITE request as basis request - c2cd395f-d7d2-26da-3ae0-4b5881316cc1 [Aug 11 16:31:40] DEBUG[31256][C-00000005] netsock2.c: Splitting '10.24.18.124' into... [Aug 11 16:31:40] DEBUG[31256][C-00000005] netsock2.c: ...host '10.24.18.124' and port ''. [Aug 11 16:31:40] VERBOSE[31256][C-00000005] chan_sip.c: Found peer '354' for '354' from 10.24.17.254:37587 [Aug 11 16:31:40] VERBOSE[31256][C-00000005] 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=z9hG4bKh85AgcDeAlVPxuh9aAXDGhyuuQVkOD8g;rport;received=10.24.17.254 ˙From: "354";tag=yB3kheDC1hkF4DX5eiCm ˙To: ;tag=as6f951eac ˙Call-ID: c2cd395f-d7d2-26da-3ae0-4b5881316cc1 ˙CSeq: 21407 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="5a8a7250" ˙Content-Length: 0 ˙ ˙ ˙<------------> [Aug 11 16:31:40] DEBUG[31256][C-00000005] chan_sip.c: Trying to put 'SIP/2.0 401' onto WS socket destined for 10.24.17.254:5060 [Aug 11 16:31:40] VERBOSE[31256][C-00000005] chan_sip.c: Scheduling destruction of SIP dialog 'c2cd395f-d7d2-26da-3ae0-4b5881316cc1' in 32000 ms (Method: INVITE) [Aug 11 16:31:40] VERBOSE[31256] chan_sip.c: ˙<--- SIP read from WS:10.24.17.254:37587 ---> ˙ACK sip:1000@10.24.18.124 SIP/2.0 ˙Via: SIP/2.0/WS df7jal23ls0d.invalid;branch=z9hG4bKh85AgcDeAlVPxuh9aAXDGhyuuQVkOD8g;rport ˙From: "354";tag=yB3kheDC1hkF4DX5eiCm ˙To: ;tag=as6f951eac ˙Call-ID: c2cd395f-d7d2-26da-3ae0-4b5881316cc1 ˙CSeq: 21407 ACK ˙Content-Length: 0 ˙Max-Forwards: 70 ˙ ˙<-------------> [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Header 0 [ 33]: ACK sip:1000@10.24.18.124 SIP/2.0 [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Header 1 [ 89]: Via: SIP/2.0/WS df7jal23ls0d.invalid;branch=z9hG4bKh85AgcDeAlVPxuh9aAXDGhyuuQVkOD8g;rport [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Header 2 [ 58]: From: "354";tag=yB3kheDC1hkF4DX5eiCm [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Header 3 [ 42]: To: ;tag=as6f951eac [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Header 4 [ 45]: Call-ID: c2cd395f-d7d2-26da-3ae0-4b5881316cc1 [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Header 5 [ 15]: CSeq: 21407 ACK [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Header 6 [ 17]: Content-Length: 0 [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Header 7 [ 16]: Max-Forwards: 70 [Aug 11 16:31:40] VERBOSE[31256] chan_sip.c: --- (8 headers 0 lines) --- [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: = Looking for Call ID: c2cd395f-d7d2-26da-3ae0-4b5881316cc1 (Checking From) --From tag yB3kheDC1hkF4DX5eiCm --To-tag as6f951eac [Aug 11 16:31:40] DEBUG[31256][C-00000005] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Aug 11 16:31:40] DEBUG[31256][C-00000005] chan_sip.c: Stopping retransmission on 'c2cd395f-d7d2-26da-3ae0-4b5881316cc1' of Response 21407: Match Not Found [Aug 11 16:31:40] VERBOSE[31256] chan_sip.c: ˙<--- SIP read from WS:10.24.17.254:37587 ---> ˙INVITE sip:1000@10.24.18.124 SIP/2.0 ˙Via: SIP/2.0/WS df7jal23ls0d.invalid;branch=z9hG4bKOae7GL7O2HpMVBpNpXAxlL1SS3WtcTVn;rport ˙From: "354";tag=yB3kheDC1hkF4DX5eiCm ˙To: ˙Contact: "354";+g.oma.sip-im;+sip.ice;language="en,fr" ˙Call-ID: c2cd395f-d7d2-26da-3ae0-4b5881316cc1 ˙CSeq: 21408 INVITE ˙Content-Type: application/sdp ˙Content-Length: 1757 ˙Max-Forwards: 70 ˙Authorization: Digest username="354",realm="10.24.18.124",nonce="5a8a7250",uri="sip:1000@10.24.18.124",response="d2268c5a07ace81e6fa50d7f2dac1ba2",algorithm=MD5 ˙User-Agent: IM-client/OMA1.0 sipML5-v1.2014.04.18 ˙Organization: Doubango Telecom ˙ ˙v=0 ˙o=- 8594674609699288000 2 IN IP4 127.0.0.1 ˙s=Doubango Telecom - chrome ˙t=0 0 ˙a=group:BUNDLE audio ˙a=msid-semantic: WMS pZPNqZCjAk1d9vjQ4I4IabAtNELBe3ARv2Oy ˙m=audio 58858 UDP/TLS/RTP/SAVPF 111 103 104 0 8 106 105 13 126 ˙c=IN IP4 216.207.245.1 ˙a=rtcp:58858 IN IP4 216.207.245.1 ˙a=candidate:1877610657 1 udp 2122260223 10.24.17.254 58858 typ host generation 0 ˙a=candidate:1877610657 2 udp 2122260223 10.24.17.254 58858 typ host generation 0 ˙a=candidate:2583325045 1 udp 1686052607 216.207.245.1 58858 typ srflx raddr 10.24.17.254 rport 58858 generation 0 ˙a=candidate:2583325045 2 udp 1686052607 216.207.245.1 58858 typ srflx raddr 10.24.17.254 rport 58858 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:s1o+TB82UPCSjuDE ˙a=ice-pwd:3QqmciO3GSo0x9fI+SFqkGB9 ˙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:3595826006 cname:ke4//16d6EF+2Xig ˙a=ssrc:3595826006 msid:pZPNqZCjAk1d9vjQ4I4IabAtNELBe3ARv2Oy 8456089a-ec01-4528-a3b8-65ddd6606fd1 ˙a=ssrc:3595826006 mslabel:pZPNqZCjAk1d9vjQ4I4IabAtNELBe3ARv2Oy ˙a=ssrc:3595826006 label:8456089a-ec01-4528-a3b8-65ddd6606fd1 ˙<-------------> [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Header 0 [ 36]: INVITE sip:1000@10.24.18.124 SIP/2.0 [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Header 1 [ 89]: Via: SIP/2.0/WS df7jal23ls0d.invalid;branch=z9hG4bKOae7GL7O2HpMVBpNpXAxlL1SS3WtcTVn;rport [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Header 2 [ 58]: From: "354";tag=yB3kheDC1hkF4DX5eiCm [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Header 3 [ 27]: To: [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Header 4 [129]: Contact: "354";+g.oma.sip-im;+sip.ice;language="en,fr" [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Header 5 [ 45]: Call-ID: c2cd395f-d7d2-26da-3ae0-4b5881316cc1 [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Header 6 [ 18]: CSeq: 21408 INVITE [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Header 7 [ 29]: Content-Type: application/sdp [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Header 8 [ 20]: Content-Length: 1757 [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Header 9 [ 16]: Max-Forwards: 70 [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Header 10 [160]: Authorization: Digest username="354",realm="10.24.18.124",nonce="5a8a7250",uri="sip:1000@10.24.18.124",response="d2268c5a07ace81e6fa50d7f2dac1ba2",algorithm=MD5 [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Header 11 [ 49]: User-Agent: IM-client/OMA1.0 sipML5-v1.2014.04.18 [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Header 12 [ 30]: Organization: Doubango Telecom [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Header 13 [ 0]: [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Body 0 [ 3]: v=0 [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Body 1 [ 42]: o=- 8594674609699288000 2 IN IP4 127.0.0.1 [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Body 2 [ 27]: s=Doubango Telecom - chrome [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Body 3 [ 5]: t=0 0 [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Body 4 [ 20]: a=group:BUNDLE audio [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Body 5 [ 57]: a=msid-semantic: WMS pZPNqZCjAk1d9vjQ4I4IabAtNELBe3ARv2Oy [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Body 6 [ 62]: m=audio 58858 UDP/TLS/RTP/SAVPF 111 103 104 0 8 106 105 13 126 [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Body 7 [ 22]: c=IN IP4 216.207.245.1 [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Body 8 [ 33]: a=rtcp:58858 IN IP4 216.207.245.1 [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Body 9 [ 80]: a=candidate:1877610657 1 udp 2122260223 10.24.17.254 58858 typ host generation 0 [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Body 10 [ 80]: a=candidate:1877610657 2 udp 2122260223 10.24.17.254 58858 typ host generation 0 [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Body 11 [113]: a=candidate:2583325045 1 udp 1686052607 216.207.245.1 58858 typ srflx raddr 10.24.17.254 rport 58858 generation 0 [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Body 12 [113]: a=candidate:2583325045 2 udp 1686052607 216.207.245.1 58858 typ srflx raddr 10.24.17.254 rport 58858 generation 0 [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Body 13 [ 75]: a=candidate:560589905 1 tcp 1518280447 10.24.17.254 0 typ host generation 0 [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Body 14 [ 75]: a=candidate:560589905 2 tcp 1518280447 10.24.17.254 0 typ host generation 0 [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Body 15 [ 28]: a=ice-ufrag:s1o+TB82UPCSjuDE [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Body 16 [ 34]: a=ice-pwd:3QqmciO3GSo0x9fI+SFqkGB9 [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Body 17 [ 24]: a=ice-options:google-ice [Aug 11 16:31:40] DEBUG[31256] 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:31:40] DEBUG[31256] chan_sip.c: Body 19 [ 15]: a=setup:actpass [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Body 20 [ 11]: a=mid:audio [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Body 21 [ 54]: a=extmap:1 urn:ietf:params:rtp-hdrext:ssrc-audio-level [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Body 22 [ 69]: a=extmap:3 http://www.webrtc.org/experiments/rtp-hdrext/abs-send-time [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Body 23 [ 10]: a=sendrecv [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Body 24 [ 10]: a=rtcp-mux [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Body 25 [ 25]: a=rtpmap:111 opus/48000/2 [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Body 26 [ 22]: a=fmtp:111 minptime=10 [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Body 27 [ 23]: a=rtpmap:103 ISAC/16000 [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Body 28 [ 23]: a=rtpmap:104 ISAC/32000 [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Body 29 [ 20]: a=rtpmap:0 PCMU/8000 [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Body 30 [ 20]: a=rtpmap:8 PCMA/8000 [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Body 31 [ 21]: a=rtpmap:106 CN/32000 [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Body 32 [ 21]: a=rtpmap:105 CN/16000 [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Body 33 [ 19]: a=rtpmap:13 CN/8000 [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Body 34 [ 33]: a=rtpmap:126 telephone-event/8000 [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Body 35 [ 13]: a=maxptime:60 [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Body 36 [ 40]: a=ssrc:3595826006 cname:ke4//16d6EF+2Xig [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Body 37 [ 96]: a=ssrc:3595826006 msid:pZPNqZCjAk1d9vjQ4I4IabAtNELBe3ARv2Oy 8456089a-ec01-4528-a3b8-65ddd6606fd1 [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Body 38 [ 62]: a=ssrc:3595826006 mslabel:pZPNqZCjAk1d9vjQ4I4IabAtNELBe3ARv2Oy [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Body 39 [ 60]: a=ssrc:3595826006 label:8456089a-ec01-4528-a3b8-65ddd6606fd1 [Aug 11 16:31:40] VERBOSE[31256] chan_sip.c: --- (13 headers 40 lines) --- [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: = Looking for Call ID: c2cd395f-d7d2-26da-3ae0-4b5881316cc1 (Checking From) --From tag yB3kheDC1hkF4DX5eiCm --To-tag [Aug 11 16:31:40] DEBUG[31256] netsock2.c: Splitting '10.24.18.124' into... [Aug 11 16:31:40] DEBUG[31256] netsock2.c: ...host '10.24.18.124' and port ''. [Aug 11 16:31:40] DEBUG[31256] netsock2.c: Splitting '10.24.18.124' into... [Aug 11 16:31:40] DEBUG[31256] netsock2.c: ...host '10.24.18.124' and port ''. [Aug 11 16:31:40] DEBUG[31256][C-00000005] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Aug 11 16:31:40] DEBUG[31256][C-00000005] chan_sip.c: Initializing initreq for method INVITE - callid c2cd395f-d7d2-26da-3ae0-4b5881316cc1 [Aug 11 16:31:40] VERBOSE[31256][C-00000005] chan_sip.c: Using INVITE request as basis request - c2cd395f-d7d2-26da-3ae0-4b5881316cc1 [Aug 11 16:31:40] DEBUG[31256][C-00000005] netsock2.c: Splitting '10.24.18.124' into... [Aug 11 16:31:40] DEBUG[31256][C-00000005] netsock2.c: ...host '10.24.18.124' and port ''. [Aug 11 16:31:40] VERBOSE[31256][C-00000005] chan_sip.c: Found peer '354' for '354' from 10.24.17.254:37587 [Aug 11 16:31:40] DEBUG[31256][C-00000005] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7f654000e968' [Aug 11 16:31:40] DEBUG[31256][C-00000005] res_rtp_asterisk.c: Allocated port 11100 for RTP instance '0x7f654000e968' [Aug 11 16:31:40] DEBUG[31256][C-00000005] pjsip: icess0x7f65400 ICE session created, comp_cnt=2, role is Unknown agent [Aug 11 16:31:40] DEBUG[31256][C-00000005] netsock2.c: Splitting '10.24.18.124' into... [Aug 11 16:31:40] DEBUG[31256][C-00000005] netsock2.c: ...host '10.24.18.124' and port ''. [Aug 11 16:31:40] DEBUG[31256][C-00000005] pjsip: icess0x7f65400 Candidate 0 added: comp_id=1, type=host, foundation=Ha18127c, addr=10.24.18.124:11100, base=10.24.18.124:11100, prio=0x7effffff (2130706431) [Aug 11 16:31:40] DEBUG[31256][C-00000005] netsock2.c: Splitting '216.207.245.1' into... [Aug 11 16:31:40] DEBUG[31256][C-00000005] netsock2.c: ...host '216.207.245.1' and port ''. [Aug 11 16:31:40] DEBUG[31256][C-00000005] pjsip: icess0x7f65400 Candidate 1 added: comp_id=1, type=srflx, foundation=Sd8cff501, addr=216.207.245.1:35477, base=10.24.18.124:11100, prio=0x64ffffff (1694498815) [Aug 11 16:31:40] DEBUG[31256][C-00000005] rtp_engine.c: RTP instance '0x7f654000e968' is setup and ready to go [Aug 11 16:31:40] DEBUG[31256][C-00000005] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7f654000e968' [Aug 11 16:31:40] DEBUG[31256][C-00000005] netsock2.c: Splitting '10.24.18.124' into... [Aug 11 16:31:40] DEBUG[31256][C-00000005] netsock2.c: ...host '10.24.18.124' and port ''. [Aug 11 16:31:40] DEBUG[31256][C-00000005] pjsip: icess0x7f65400 Candidate 2 added: comp_id=2, type=host, foundation=Ha18127c, addr=10.24.18.124:11101, base=10.24.18.124:11101, prio=0x7efffffe (2130706430) [Aug 11 16:31:40] DEBUG[31256][C-00000005] netsock2.c: Splitting '216.207.245.1' into... [Aug 11 16:31:40] DEBUG[31256][C-00000005] netsock2.c: ...host '216.207.245.1' and port ''. [Aug 11 16:31:40] DEBUG[31256][C-00000005] pjsip: icess0x7f65400 Candidate 3 added: comp_id=2, type=srflx, foundation=Sd8cff501, addr=216.207.245.1:35478, base=10.24.18.124:11101, prio=0x64fffffe (1694498814) [Aug 11 16:31:40] DEBUG[31256][C-00000005] chan_sip.c: Setting NAT on RTP to Off [Aug 11 16:31:40] DEBUG[31256][C-00000005] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED OR FAILED. [Aug 11 16:31:40] DEBUG[31256][C-00000005] chan_sip.c: Processing session-level SDP o=- 8594674609699288000 2 IN IP4 127.0.0.1... OK. [Aug 11 16:31:40] DEBUG[31256][C-00000005] chan_sip.c: Processing session-level SDP s=Doubango Telecom - chrome... UNSUPPORTED OR FAILED. [Aug 11 16:31:40] DEBUG[31256][C-00000005] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED. [Aug 11 16:31:40] DEBUG[31256][C-00000005] chan_sip.c: Processing session-level SDP a=group:BUNDLE audio... UNSUPPORTED OR FAILED. [Aug 11 16:31:40] DEBUG[31256][C-00000005] chan_sip.c: Processing session-level SDP a=msid-semantic: WMS pZPNqZCjAk1d9vjQ4I4IabAtNELBe3ARv2Oy... UNSUPPORTED OR FAILED. [Aug 11 16:31:40] VERBOSE[31256][C-00000005] chan_sip.c: Found RTP audio format 111 [Aug 11 16:31:40] DEBUG[31256][C-00000005] rtp_engine.c: Setting payload 111 based on m type on 0x7f656421f230 [Aug 11 16:31:40] VERBOSE[31256][C-00000005] chan_sip.c: Found RTP audio format 103 [Aug 11 16:31:40] DEBUG[31256][C-00000005] rtp_engine.c: Setting payload 103 based on m type on 0x7f656421f230 [Aug 11 16:31:40] VERBOSE[31256][C-00000005] chan_sip.c: Found RTP audio format 104 [Aug 11 16:31:40] DEBUG[31256][C-00000005] rtp_engine.c: Setting payload 104 based on m type on 0x7f656421f230 [Aug 11 16:31:40] VERBOSE[31256][C-00000005] chan_sip.c: Found RTP audio format 0 [Aug 11 16:31:40] DEBUG[31256][C-00000005] rtp_engine.c: Setting payload 0 based on m type on 0x7f656421f230 [Aug 11 16:31:40] VERBOSE[31256][C-00000005] chan_sip.c: Found RTP audio format 8 [Aug 11 16:31:40] DEBUG[31256][C-00000005] rtp_engine.c: Setting payload 8 based on m type on 0x7f656421f230 [Aug 11 16:31:40] VERBOSE[31256][C-00000005] chan_sip.c: Found RTP audio format 106 [Aug 11 16:31:40] DEBUG[31256][C-00000005] rtp_engine.c: Setting payload 106 based on m type on 0x7f656421f230 [Aug 11 16:31:40] VERBOSE[31256][C-00000005] chan_sip.c: Found RTP audio format 105 [Aug 11 16:31:40] DEBUG[31256][C-00000005] rtp_engine.c: Setting payload 105 based on m type on 0x7f656421f230 [Aug 11 16:31:40] VERBOSE[31256][C-00000005] chan_sip.c: Found RTP audio format 13 [Aug 11 16:31:40] DEBUG[31256][C-00000005] rtp_engine.c: Setting payload 13 based on m type on 0x7f656421f230 [Aug 11 16:31:40] VERBOSE[31256][C-00000005] chan_sip.c: Found RTP audio format 126 [Aug 11 16:31:40] DEBUG[31256][C-00000005] rtp_engine.c: Setting payload 126 based on m type on 0x7f656421f230 [Aug 11 16:31:40] DEBUG[31256][C-00000005] netsock2.c: Splitting '216.207.245.1' into... [Aug 11 16:31:40] DEBUG[31256][C-00000005] netsock2.c: ...host '216.207.245.1' and port ''. [Aug 11 16:31:40] DEBUG[31256][C-00000005] chan_sip.c: Processing media-level (audio) SDP c=IN IP4 216.207.245.1... OK. [Aug 11 16:31:40] DEBUG[31256][C-00000005] chan_sip.c: Processing media-level (audio) SDP a=rtcp:58858 IN IP4 216.207.245.1... UNSUPPORTED OR FAILED. [Aug 11 16:31:40] DEBUG[31256][C-00000005] netsock2.c: Splitting '10.24.17.254' into... [Aug 11 16:31:40] DEBUG[31256][C-00000005] netsock2.c: ...host '10.24.17.254' and port ''. [Aug 11 16:31:40] DEBUG[31256][C-00000005] netsock2.c: Splitting '0' into... [Aug 11 16:31:40] DEBUG[31256][C-00000005] netsock2.c: ...host '0' and port ''. [Aug 11 16:31:40] DEBUG[31256][C-00000005] chan_sip.c: Processing media-level (audio) SDP a=candidate:1877610657 1 udp 2122260223 10.24.17.254 58858 typ host generation 0... OK. [Aug 11 16:31:40] DEBUG[31256][C-00000005] netsock2.c: Splitting '10.24.17.254' into... [Aug 11 16:31:40] DEBUG[31256][C-00000005] netsock2.c: ...host '10.24.17.254' and port ''. [Aug 11 16:31:40] DEBUG[31256][C-00000005] netsock2.c: Splitting '0' into... [Aug 11 16:31:40] DEBUG[31256][C-00000005] netsock2.c: ...host '0' and port ''. [Aug 11 16:31:40] DEBUG[31256][C-00000005] chan_sip.c: Processing media-level (audio) SDP a=candidate:1877610657 2 udp 2122260223 10.24.17.254 58858 typ host generation 0... OK. [Aug 11 16:31:40] DEBUG[31256][C-00000005] netsock2.c: Splitting '216.207.245.1' into... [Aug 11 16:31:40] DEBUG[31256][C-00000005] netsock2.c: ...host '216.207.245.1' and port ''. [Aug 11 16:31:40] DEBUG[31256][C-00000005] netsock2.c: Splitting '10.24.17.254' into... [Aug 11 16:31:40] DEBUG[31256][C-00000005] netsock2.c: ...host '10.24.17.254' and port ''. [Aug 11 16:31:40] DEBUG[31256][C-00000005] chan_sip.c: Processing media-level (audio) SDP a=candidate:2583325045 1 udp 1686052607 216.207.245.1 58858 typ srflx raddr 10.24.17.254 rport 58858 generation 0... OK. [Aug 11 16:31:40] DEBUG[31256][C-00000005] netsock2.c: Splitting '216.207.245.1' into... [Aug 11 16:31:40] DEBUG[31256][C-00000005] netsock2.c: ...host '216.207.245.1' and port ''. [Aug 11 16:31:40] DEBUG[31256][C-00000005] netsock2.c: Splitting '10.24.17.254' into... [Aug 11 16:31:40] DEBUG[31256][C-00000005] netsock2.c: ...host '10.24.17.254' and port ''. [Aug 11 16:31:40] DEBUG[31256][C-00000005] chan_sip.c: Processing media-level (audio) SDP a=candidate:2583325045 2 udp 1686052607 216.207.245.1 58858 typ srflx raddr 10.24.17.254 rport 58858 generation 0... OK. [Aug 11 16:31:40] DEBUG[31256][C-00000005] netsock2.c: Splitting '10.24.17.254' into... [Aug 11 16:31:40] DEBUG[31256][C-00000005] netsock2.c: ...host '10.24.17.254' and port ''. [Aug 11 16:31:40] DEBUG[31256][C-00000005] netsock2.c: Splitting '0' into... [Aug 11 16:31:40] DEBUG[31256][C-00000005] netsock2.c: ...host '0' and port ''. [Aug 11 16:31:40] DEBUG[31256][C-00000005] 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:31:40] DEBUG[31256][C-00000005] netsock2.c: Splitting '10.24.17.254' into... [Aug 11 16:31:40] DEBUG[31256][C-00000005] netsock2.c: ...host '10.24.17.254' and port ''. [Aug 11 16:31:40] DEBUG[31256][C-00000005] netsock2.c: Splitting '0' into... [Aug 11 16:31:40] DEBUG[31256][C-00000005] netsock2.c: ...host '0' and port ''. [Aug 11 16:31:40] DEBUG[31256][C-00000005] 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:31:40] DEBUG[31256][C-00000005] chan_sip.c: Processing media-level (audio) SDP a=ice-ufrag:s1o+TB82UPCSjuDE... OK. [Aug 11 16:31:40] DEBUG[31256][C-00000005] chan_sip.c: Processing media-level (audio) SDP a=ice-pwd:3QqmciO3GSo0x9fI+SFqkGB9... OK. [Aug 11 16:31:40] DEBUG[31256][C-00000005] chan_sip.c: Processing media-level (audio) SDP a=ice-options:google-ice... UNSUPPORTED OR FAILED. [Aug 11 16:31:40] DEBUG[31256][C-00000005] 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:31:40] DEBUG[31256][C-00000005] chan_sip.c: Processing media-level (audio) SDP a=setup:actpass... OK. [Aug 11 16:31:40] DEBUG[31256][C-00000005] chan_sip.c: Processing media-level (audio) SDP a=mid:audio... UNSUPPORTED OR FAILED. [Aug 11 16:31:40] DEBUG[31256][C-00000005] 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:31:40] DEBUG[31256][C-00000005] 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:31:40] DEBUG[31256][C-00000005] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK. [Aug 11 16:31:40] DEBUG[31256][C-00000005] chan_sip.c: Processing media-level (audio) SDP a=rtcp-mux... UNSUPPORTED OR FAILED. [Aug 11 16:31:40] VERBOSE[31256][C-00000005] chan_sip.c: Found audio description format opus for ID 111 [Aug 11 16:31:40] DEBUG[31256][C-00000005] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:111 opus/48000/2... OK. [Aug 11 16:31:40] DEBUG[31256][C-00000005] chan_sip.c: Processing media-level (audio) SDP a=fmtp:111 minptime=10... OK. [Aug 11 16:31:40] DEBUG[31256][C-00000005] rtp_engine.c: Unsetting payload 103 on 0x7f656421f230 [Aug 11 16:31:40] VERBOSE[31256][C-00000005] chan_sip.c: Found unknown media description format ISAC for ID 103 [Aug 11 16:31:40] DEBUG[31256][C-00000005] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:103 ISAC/16000... UNSUPPORTED OR FAILED. [Aug 11 16:31:40] DEBUG[31256][C-00000005] rtp_engine.c: Unsetting payload 104 on 0x7f656421f230 [Aug 11 16:31:40] VERBOSE[31256][C-00000005] chan_sip.c: Found unknown media description format ISAC for ID 104 [Aug 11 16:31:40] DEBUG[31256][C-00000005] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:104 ISAC/32000... UNSUPPORTED OR FAILED. [Aug 11 16:31:40] VERBOSE[31256][C-00000005] chan_sip.c: Found audio description format PCMU for ID 0 [Aug 11 16:31:40] DEBUG[31256][C-00000005] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. [Aug 11 16:31:40] VERBOSE[31256][C-00000005] chan_sip.c: Found audio description format PCMA for ID 8 [Aug 11 16:31:40] DEBUG[31256][C-00000005] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK. [Aug 11 16:31:40] DEBUG[31256][C-00000005] rtp_engine.c: Unsetting payload 106 on 0x7f656421f230 [Aug 11 16:31:40] VERBOSE[31256][C-00000005] chan_sip.c: Found unknown media description format CN for ID 106 [Aug 11 16:31:40] DEBUG[31256][C-00000005] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:106 CN/32000... UNSUPPORTED OR FAILED. [Aug 11 16:31:40] DEBUG[31256][C-00000005] rtp_engine.c: Unsetting payload 105 on 0x7f656421f230 [Aug 11 16:31:40] VERBOSE[31256][C-00000005] chan_sip.c: Found unknown media description format CN for ID 105 [Aug 11 16:31:40] DEBUG[31256][C-00000005] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:105 CN/16000... UNSUPPORTED OR FAILED. [Aug 11 16:31:40] VERBOSE[31256][C-00000005] chan_sip.c: Found audio description format CN for ID 13 [Aug 11 16:31:40] DEBUG[31256][C-00000005] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:13 CN/8000... OK. [Aug 11 16:31:40] VERBOSE[31256][C-00000005] chan_sip.c: Found audio description format telephone-event for ID 126 [Aug 11 16:31:40] DEBUG[31256][C-00000005] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:126 telephone-event/8000... OK. [Aug 11 16:31:40] DEBUG[31256][C-00000005] chan_sip.c: Processing media-level (audio) SDP a=maxptime:60... UNSUPPORTED OR FAILED. [Aug 11 16:31:40] DEBUG[31256][C-00000005] chan_sip.c: Processing media-level (audio) SDP a=ssrc:3595826006 cname:ke4//16d6EF+2Xig... UNSUPPORTED OR FAILED. [Aug 11 16:31:40] DEBUG[31256][C-00000005] chan_sip.c: Processing media-level (audio) SDP a=ssrc:3595826006 msid:pZPNqZCjAk1d9vjQ4I4IabAtNELBe3ARv2Oy 8456089a-ec01-4528-a3b8-65ddd6606fd1... UNSUPPORTED OR FAILED. [Aug 11 16:31:40] DEBUG[31256][C-00000005] chan_sip.c: Processing media-level (audio) SDP a=ssrc:3595826006 mslabel:pZPNqZCjAk1d9vjQ4I4IabAtNELBe3ARv2Oy... UNSUPPORTED OR FAILED. [Aug 11 16:31:40] DEBUG[31256][C-00000005] chan_sip.c: Processing media-level (audio) SDP a=ssrc:3595826006 label:8456089a-ec01-4528-a3b8-65ddd6606fd1... UNSUPPORTED OR FAILED. [Aug 11 16:31:40] VERBOSE[31256][C-00000005] chan_sip.c: Capabilities: us - (alaw), peer - audio=(ulaw|alaw|opus)/video=(nothing)/text=(nothing), combined - (alaw) [Aug 11 16:31:40] VERBOSE[31256][C-00000005] chan_sip.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x3 (telephone-event|CN|), combined - 0x1 (telephone-event|) [Aug 11 16:31:40] DEBUG[31256][C-00000005] pjsip: icess0x7f65400 Role changed to Controlled [Aug 11 16:31:40] DEBUG[31256][C-00000005] pjsip: icess0x7f65400 Destroying ICE session 0x7f6540015bc8 [Aug 11 16:31:40] DEBUG[31256][C-00000005] pjsip: stuse0x7f65400 STUN session 0x7f654001b648 destroy request, ref_cnt=4 [Aug 11 16:31:40] DEBUG[31256][C-00000005] pjsip: stuse0x7f65400 STUN session 0x7f6540025948 destroy request, ref_cnt=3 [Aug 11 16:31:40] DEBUG[31256][C-00000005] pjsip: ice_session.c ICE session 0x7f6540015bc8 destroyed [Aug 11 16:31:40] DEBUG[31256][C-00000005] pjsip: stun_session.c STUN session 0x7f654001b648 destroyed [Aug 11 16:31:40] DEBUG[31256][C-00000005] pjsip: stun_session.c STUN session 0x7f6540025948 destroyed [Aug 11 16:31:40] DEBUG[31256][C-00000005] pjsip: icess0x7f65400 ICE session created, comp_cnt=2, role is Unknown agent [Aug 11 16:31:40] DEBUG[31256][C-00000005] netsock2.c: Splitting '10.24.18.124' into... [Aug 11 16:31:40] DEBUG[31256][C-00000005] netsock2.c: ...host '10.24.18.124' and port ''. [Aug 11 16:31:40] DEBUG[31256][C-00000005] pjsip: icess0x7f65400 Candidate 0 added: comp_id=1, type=host, foundation=Ha18127c, addr=10.24.18.124:11100, base=10.24.18.124:11100, prio=0x7effffff (2130706431) [Aug 11 16:31:40] DEBUG[31256][C-00000005] netsock2.c: Splitting '216.207.245.1' into... [Aug 11 16:31:40] DEBUG[31256][C-00000005] netsock2.c: ...host '216.207.245.1' and port ''. [Aug 11 16:31:40] DEBUG[31256][C-00000005] pjsip: icess0x7f65400 Candidate 1 added: comp_id=1, type=srflx, foundation=Sd8cff501, addr=216.207.245.1:35477, base=10.24.18.124:11100, prio=0x64ffffff (1694498815) [Aug 11 16:31:40] DEBUG[31256][C-00000005] netsock2.c: Splitting '10.24.18.124' into... [Aug 11 16:31:40] DEBUG[31256][C-00000005] netsock2.c: ...host '10.24.18.124' and port ''. [Aug 11 16:31:40] DEBUG[31256][C-00000005] pjsip: icess0x7f65400 Candidate 2 added: comp_id=2, type=host, foundation=Ha18127c, addr=10.24.18.124:11101, base=10.24.18.124:11101, prio=0x7efffffe (2130706430) [Aug 11 16:31:40] DEBUG[31256][C-00000005] netsock2.c: Splitting '216.207.245.1' into... [Aug 11 16:31:40] DEBUG[31256][C-00000005] netsock2.c: ...host '216.207.245.1' and port ''. [Aug 11 16:31:40] DEBUG[31256][C-00000005] pjsip: icess0x7f65400 Candidate 3 added: comp_id=2, type=srflx, foundation=Sd8cff501, addr=216.207.245.1:35478, base=10.24.18.124:11101, prio=0x64fffffe (1694498814) [Aug 11 16:31:40] DEBUG[31256][C-00000005] pjsip: icess0x7f65400 Role changed to Controlled [Aug 11 16:31:40] DEBUG[31256][C-00000005] pjsip: icess0x7f65400 Check 2: [1] 10.24.18.124:11100-->10.24.17.254:58858 pruned (duplicate found) [Aug 11 16:31:40] DEBUG[31256][C-00000005] pjsip: icess0x7f65400 Check 2: [2] 10.24.18.124:11101-->10.24.17.254:58858 pruned (duplicate found) [Aug 11 16:31:40] DEBUG[31256][C-00000005] pjsip: icess0x7f65400 Check 4: [1] 10.24.18.124:11100-->216.207.245.1:58858 pruned (duplicate found) [Aug 11 16:31:40] DEBUG[31256][C-00000005] pjsip: icess0x7f65400 Check 4: [2] 10.24.18.124:11101-->216.207.245.1:58858 pruned (duplicate found) [Aug 11 16:31:40] DEBUG[31256][C-00000005] pjsip: icess0x7f65400 Check 6: [1] 10.24.18.124:11100-->10.24.17.254:0 pruned (duplicate found) [Aug 11 16:31:40] DEBUG[31256][C-00000005] pjsip: icess0x7f65400 Check 6: [2] 10.24.18.124:11101-->10.24.17.254:0 pruned (duplicate found) [Aug 11 16:31:40] DEBUG[31256][C-00000005] pjsip: icess0x7f65400 Checklist created: [Aug 11 16:31:40] DEBUG[31256][C-00000005] pjsip: icess0x7f65400 0: [1] 10.24.18.124:11100-->10.24.17.254:58858 (not nominated, state=Frozen) [Aug 11 16:31:40] DEBUG[31256][C-00000005] pjsip: icess0x7f65400 1: [2] 10.24.18.124:11101-->10.24.17.254:58858 (not nominated, state=Frozen) [Aug 11 16:31:40] DEBUG[31256][C-00000005] pjsip: icess0x7f65400 2: [1] 10.24.18.124:11100-->216.207.245.1:58858 (not nominated, state=Frozen) [Aug 11 16:31:40] DEBUG[31256][C-00000005] pjsip: icess0x7f65400 3: [2] 10.24.18.124:11101-->216.207.245.1:58858 (not nominated, state=Frozen) [Aug 11 16:31:40] DEBUG[31256][C-00000005] pjsip: icess0x7f65400 4: [1] 10.24.18.124:11100-->10.24.17.254:0 (not nominated, state=Frozen) [Aug 11 16:31:40] DEBUG[31256][C-00000005] pjsip: icess0x7f65400 5: [2] 10.24.18.124:11101-->10.24.17.254:0 (not nominated, state=Frozen) [Aug 11 16:31:40] DEBUG[31256][C-00000005] pjsip: icess0x7f65400 Starting ICE check.. [Aug 11 16:31:40] DEBUG[31256][C-00000005] pjsip: icess0x7f65400 .Check 0: [1] 10.24.18.124:11100-->10.24.17.254:58858: state changed from Frozen to Waiting [Aug 11 16:31:40] DEBUG[31256][C-00000005] pjsip: icess0x7f65400 Checklist: state changed from Idle to Running [Aug 11 16:31:40] DEBUG[31256][C-00000005] pjsip: icess0x7f65400 Starting checklist periodic check [Aug 11 16:31:40] DEBUG[31256][C-00000005] pjsip: icess0x7f65400 .Sending connectivity check for check 0: [1] 10.24.18.124:11100-->10.24.17.254:58858 [Aug 11 16:31:40] DEBUG[31256][C-00000005] pjsip: stuse0x7f65400 ...TX 144 bytes STUN message to 10.24.17.254:58858: --- begin STUN message --- STUN Binding request Hdr: length=124, magic=2112a442, tsx_id=000078db41e7dde93d1cd6c0 Attributes: PRIORITY: length=4, value=1862270975 (0x6effffff) ICE-CONTROLLED: length=8, data=1a0b8a375dd49e59 SOFTWARE: length=0, value="pjnath-2.2.1" USERNAME: length=0, value="s1o+TB82UPCSjuDE:3b41517f58736edc02ae5a3e45902279" MESSAGE-INTEGRITY: length=20, data=e09456e505406064034ac5de3805ff016dcfac26 FINGERPRINT: length=4, value=4203877665 (0xfa921521) --- end of STUN message --- [Aug 11 16:31:40] DEBUG[31256][C-00000005] pjsip: utsx0x7f654002 ...STUN client transaction created [Aug 11 16:31:40] DEBUG[31256][C-00000005] pjsip: utsx0x7f654002 ...STUN sending message (transmit count=1) [Aug 11 16:31:40] DEBUG[31256][C-00000005] pjsip: icess0x7f65400 ..Check 0: [1] 10.24.18.124:11100-->10.24.17.254:58858: state changed from Waiting to In Progress [Aug 11 16:31:40] DEBUG[31256][C-00000005] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7f654000e968' [Aug 11 16:31:40] VERBOSE[31256][C-00000005] chan_sip.c: Peer audio RTP is at port 216.207.245.1:58858 [Aug 11 16:31:40] DEBUG[31256][C-00000005] rtp_engine.c: Copying payload 0 from 0x7f656421f230 to 0x7f654000eaa8 [Aug 11 16:31:40] DEBUG[31256][C-00000005] rtp_engine.c: Copying payload 8 from 0x7f656421f230 to 0x7f654000eaa8 [Aug 11 16:31:40] DEBUG[31256][C-00000005] rtp_engine.c: Copying payload 13 from 0x7f656421f230 to 0x7f654000eaa8 [Aug 11 16:31:40] DEBUG[31256][C-00000005] rtp_engine.c: Copying payload 111 from 0x7f656421f230 to 0x7f654000eaa8 [Aug 11 16:31:40] DEBUG[31256][C-00000005] rtp_engine.c: Copying payload 126 from 0x7f656421f230 to 0x7f654000eaa8 [Aug 11 16:31:40] DEBUG[31256][C-00000005] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x7f654000e968' [Aug 11 16:31:40] DEBUG[31256][C-00000005] chan_sip.c: We're settling with these formats: (alaw) [Aug 11 16:31:40] DEBUG[31256][C-00000005] chan_sip.c: Checking SIP call limits for device 354 [Aug 11 16:31:40] DEBUG[31256][C-00000005] chan_sip.c: Updating call counter for incoming call [Aug 11 16:31:40] DEBUG[31256][C-00000005] chan_sip.c: Call from peer '354' is 1 out of 100 [Aug 11 16:31:40] DEBUG[31256][C-00000005] netsock2.c: Splitting '10.24.18.124' into... [Aug 11 16:31:40] DEBUG[31256][C-00000005] netsock2.c: ...host '10.24.18.124' and port ''. [Aug 11 16:31:40] DEBUG[31256][C-00000005] netsock2.c: Splitting '10.24.18.124' into... [Aug 11 16:31:40] DEBUG[31256][C-00000005] netsock2.c: ...host '10.24.18.124' and port ''. [Aug 11 16:31:40] VERBOSE[31256][C-00000005] chan_sip.c: Looking for 1000 in default (domain 10.24.18.124) [Aug 11 16:31:40] DEBUG[31256][C-00000005] chan_sip.c: *** Our native formats are (alaw) [Aug 11 16:31:40] DEBUG[30950] devicestate.c: No provider found, checking channel drivers for SIP - 354 [Aug 11 16:31:40] DEBUG[31256][C-00000005] chan_sip.c: *** Joint capabilities are (alaw) [Aug 11 16:31:40] DEBUG[30950] chan_sip.c: Checking device state for peer 354 [Aug 11 16:31:40] DEBUG[31256][C-00000005] chan_sip.c: *** Our capabilities are (alaw) [Aug 11 16:31:40] DEBUG[31256][C-00000005] chan_sip.c: *** AST_CODEC_CHOOSE formats are alaw [Aug 11 16:31:40] DEBUG[30950] devicestate.c: Changing state for SIP/354 - state 2 (In use) [Aug 11 16:31:40] DEBUG[31256][C-00000005] chan_sip.c: This channel will not be able to handle video. [Aug 11 16:31:40] DEBUG[31010] app_queue.c: Device 'SIP/354' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Aug 11 16:31:40] DEBUG[31256][C-00000005] chan_sip.c: build_route: Contact hop: "354";+g.oma.sip-im;+sip.ice;language="en,fr" [Aug 11 16:31:40] VERBOSE[31256][C-00000005] chan_sip.c: list_route: route/path hop: [Aug 11 16:31:40] DEBUG[31256][C-00000005] chan_sip.c: SIP/354-00000005: New call is still down.... Trying... [Aug 11 16:31:40] VERBOSE[31256][C-00000005] 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=z9hG4bKOae7GL7O2HpMVBpNpXAxlL1SS3WtcTVn;rport;received=10.24.17.254 ˙From: "354";tag=yB3kheDC1hkF4DX5eiCm ˙To: ˙Call-ID: c2cd395f-d7d2-26da-3ae0-4b5881316cc1 ˙CSeq: 21408 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:31:40] DEBUG[31256][C-00000005] chan_sip.c: Trying to put 'SIP/2.0 100' onto WS socket destined for 10.24.17.254:5060 [Aug 11 16:31:40] DEBUG[30950] devicestate.c: No provider found, checking channel drivers for SIP - 354 [Aug 11 16:31:40] DEBUG[30950] chan_sip.c: Checking device state for peer 354 [Aug 11 16:31:40] DEBUG[30950] devicestate.c: Changing state for SIP/354 - state 2 (In use) [Aug 11 16:31:40] DEBUG[31269][C-00000005] pbx.c: Launching 'Answer' [Aug 11 16:31:40] DEBUG[31269][C-00000005] chan_sip.c: SIP answering channel: SIP/354-00000005 [Aug 11 16:31:40] DEBUG[31269][C-00000005] res_rtp_asterisk.c: Setting the marker bit due to a source update [Aug 11 16:31:40] DEBUG[30950] devicestate.c: No provider found, checking channel drivers for SIP - 354 [Aug 11 16:31:40] DEBUG[30950] chan_sip.c: Checking device state for peer 354 [Aug 11 16:31:40] DEBUG[30950] devicestate.c: Changing state for SIP/354 - state 2 (In use) [Aug 11 16:31:40] DEBUG[31269][C-00000005] chan_sip.c: Setting framing from config on incoming call [Aug 11 16:31:40] DEBUG[31269][C-00000005] chan_sip.c: ** Our capability: (alaw) Video flag: True Text flag: True [Aug 11 16:31:40] DEBUG[31269][C-00000005] chan_sip.c: ** Our prefcodec: (nothing) [Aug 11 16:31:40] VERBOSE[31269][C-00000005] chan_sip.c: Audio is at 11100 [Aug 11 16:31:40] VERBOSE[31269][C-00000005] chan_sip.c: Adding codec 100004 (alaw) to SDP [Aug 11 16:31:40] VERBOSE[31269][C-00000005] chan_sip.c: Adding non-codec 0x1 (telephone-event) to SDP [Aug 11 16:31:40] DEBUG[31269][C-00000005] chan_sip.c: -- Done with adding codecs to SDP [Aug 11 16:31:40] DEBUG[31269][C-00000005] chan_sip.c: Done building SDP. Settling with this capability: (alaw) [Aug 11 16:31:40] VERBOSE[31269][C-00000005] 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=z9hG4bKOae7GL7O2HpMVBpNpXAxlL1SS3WtcTVn;rport;received=10.24.17.254 ˙From: "354";tag=yB3kheDC1hkF4DX5eiCm ˙To: ;tag=as721af86d ˙Call-ID: c2cd395f-d7d2-26da-3ae0-4b5881316cc1 ˙CSeq: 21408 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: 785 ˙ ˙v=0 ˙o=root 1773304857 1773304857 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 11100 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:3b41517f58736edc02ae5a3e45902279 ˙a=ice-pwd:2bdea1a63b3f21b243b2febb3bc7ab40 ˙a=candidate:Ha18127c 1 UDP 2130706431 10.24.18.124 11100 typ host ˙a=candidate:Sd8cff501 1 UDP 1694498815 216.207.245.1 35477 typ srflx ˙a=candidate:Ha18127c 2 UDP 2130706430 10.24.18.124 11101 typ host ˙a=candidate:Sd8cff501 2 UDP 1694498814 216.207.245.1 35479 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:31:40] DEBUG[31269][C-00000005] chan_sip.c: Trying to put 'SIP/2.0 200' onto WS socket destined for 10.24.17.254:5060 [Aug 11 16:31:40] DEBUG[30973] pjsip: icess0x7f65400 Starting checklist periodic check [Aug 11 16:31:40] DEBUG[30973] pjsip: icess0x7f65400 .Sending connectivity check for check 1: [2] 10.24.18.124:11101-->10.24.17.254:58858 [Aug 11 16:31:40] DEBUG[30973] pjsip: stuse0x7f65400 ...TX 144 bytes STUN message to 10.24.17.254:58858: --- begin STUN message --- STUN Binding request Hdr: length=124, magic=2112a442, tsx_id=000078db26edbc1d3d1cd6c1 Attributes: PRIORITY: length=4, value=1862270974 (0x6efffffe) ICE-CONTROLLED: length=8, data=1a0b8a375dd49e59 SOFTWARE: length=0, value="pjnath-2.2.1" USERNAME: length=0, value="s1o+TB82UPCSjuDE:3b41517f58736edc02ae5a3e45902279" MESSAGE-INTEGRITY: length=20, data=16eb30353801fe457b65a3223ca8064589c4727d FINGERPRINT: length=4, value=3960120724 (0xec0aa594) --- end of STUN message --- [Aug 11 16:31:40] DEBUG[30973] pjsip: utsx0x7f654400 ...STUN client transaction created [Aug 11 16:31:40] DEBUG[30973] pjsip: utsx0x7f654400 ...STUN sending message (transmit count=1) [Aug 11 16:31:40] DEBUG[30973] pjsip: icess0x7f65400 ..Check 1: [2] 10.24.18.124:11101-->10.24.17.254:58858: state changed from Frozen to In Progress [Aug 11 16:31:40] DEBUG[31269][C-00000005] pjsip: stuse0x7f65400 .RX 64 bytes STUN message from 10.24.17.254:58858: --- begin STUN message --- STUN Binding success response Hdr: length=44, magic=2112a442, tsx_id=000078db26edbc1d3d1cd6c1 Attributes: XOR-MAPPED-ADDRESS: length=8, IPv4 addr=10.24.18.124:11101 MESSAGE-INTEGRITY: length=20, data=6892fafb0e351cde722cb381be4be722751c2b52 FINGERPRINT: length=4, value=3781532107 (0xe16599cb) --- end of STUN message --- [Aug 11 16:31:40] DEBUG[31269][C-00000005] pjsip: icess0x7f65400 .Check 1: [2] 10.24.18.124:11101-->10.24.17.254:58858 (not nominated): connectivity check SUCCESS [Aug 11 16:31:40] DEBUG[31269][C-00000005] pjsip: icess0x7f65400 .Check 1: [2] 10.24.18.124:11101-->10.24.17.254:58858: state changed from In Progress to Succeeded [Aug 11 16:31:40] DEBUG[31269][C-00000005] pjsip: icess0x7f65400 .Check 2: [1] 10.24.18.124:11100-->216.207.245.1:58858: state changed from Frozen to Waiting [Aug 11 16:31:40] DEBUG[31269][C-00000005] pjsip: icess0x7f65400 .Check 3: [2] 10.24.18.124:11101-->216.207.245.1:58858: state changed from Frozen to Waiting [Aug 11 16:31:40] DEBUG[31269][C-00000005] pjsip: icess0x7f65400 .Check 4: [1] 10.24.18.124:11100-->10.24.17.254:0: state changed from Frozen to Waiting [Aug 11 16:31:40] DEBUG[31269][C-00000005] pjsip: icess0x7f65400 .Check 5: [2] 10.24.18.124:11101-->10.24.17.254:0: state changed from Frozen to Waiting [Aug 11 16:31:40] DEBUG[31269][C-00000005] pjsip: icess0x7f65400 .Check 1 is successful [Aug 11 16:31:40] DEBUG[31269][C-00000005] pjsip: stun_session.c .tdata 0x7f65440013d8 destroy request, force=0, tsx=0x7f65440015b0 [Aug 11 16:31:40] DEBUG[31269][C-00000005] pjsip: utsx0x7f654400 .STUN transaction 0x7f65440015b0 schedule destroy [Aug 11 16:31:40] VERBOSE[31256] chan_sip.c: ˙<--- SIP read from WS:10.24.17.254:37587 ---> ˙ACK sip:1000@10.24.18.124:5060;transport=WS SIP/2.0 ˙Via: SIP/2.0/WS df7jal23ls0d.invalid;branch=z9hG4bKNiCoT6DD7z2GSqJpAOoe;rport ˙From: "354";tag=yB3kheDC1hkF4DX5eiCm ˙To: ;tag=as721af86d ˙Contact: "354";+g.oma.sip-im;+sip.ice;language="en,fr" ˙Call-ID: c2cd395f-d7d2-26da-3ae0-4b5881316cc1 ˙CSeq: 21408 ACK ˙Content-Length: 0 ˙Max-Forwards: 70 ˙Authorization: Digest username="354",realm="10.24.18.124",nonce="5a8a7250",uri="sip:1000@10.24.18.124:5060;transport=WS",response="c03329bc357b17f42400e42127975523",algorithm=MD5 ˙User-Agent: IM-client/OMA1.0 sipML5-v1.2014.04.18 ˙Organization: Doubango Telecom ˙ ˙<-------------> [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Header 0 [ 51]: ACK sip:1000@10.24.18.124:5060;transport=WS SIP/2.0 [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Header 1 [ 77]: Via: SIP/2.0/WS df7jal23ls0d.invalid;branch=z9hG4bKNiCoT6DD7z2GSqJpAOoe;rport [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Header 2 [ 58]: From: "354";tag=yB3kheDC1hkF4DX5eiCm [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Header 3 [ 42]: To: ;tag=as721af86d [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Header 4 [129]: Contact: "354";+g.oma.sip-im;+sip.ice;language="en,fr" [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Header 5 [ 45]: Call-ID: c2cd395f-d7d2-26da-3ae0-4b5881316cc1 [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Header 6 [ 15]: CSeq: 21408 ACK [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Header 7 [ 17]: Content-Length: 0 [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Header 8 [ 16]: Max-Forwards: 70 [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Header 9 [178]: Authorization: Digest username="354",realm="10.24.18.124",nonce="5a8a7250",uri="sip:1000@10.24.18.124:5060;transport=WS",response="c03329bc357b17f42400e42127975523",algorithm=MD5 [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Header 10 [ 49]: User-Agent: IM-client/OMA1.0 sipML5-v1.2014.04.18 [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: Header 11 [ 30]: Organization: Doubango Telecom [Aug 11 16:31:40] VERBOSE[31256] chan_sip.c: --- (12 headers 0 lines) --- [Aug 11 16:31:40] DEBUG[31256] chan_sip.c: = Looking for Call ID: c2cd395f-d7d2-26da-3ae0-4b5881316cc1 (Checking From) --From tag yB3kheDC1hkF4DX5eiCm --To-tag as721af86d [Aug 11 16:31:40] DEBUG[31256][C-00000005] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Aug 11 16:31:40] DEBUG[31256][C-00000005] chan_sip.c: Stopping retransmission on 'c2cd395f-d7d2-26da-3ae0-4b5881316cc1' of Response 21408: Match Not Found [Aug 11 16:31:40] DEBUG[30973] pjsip: icess0x7f65400 Starting checklist periodic check [Aug 11 16:31:40] DEBUG[30973] pjsip: icess0x7f65400 .Sending connectivity check for check 2: [1] 10.24.18.124:11100-->216.207.245.1:58858 [Aug 11 16:31:40] DEBUG[30973] pjsip: stuse0x7f65400 ...TX 144 bytes STUN message to 216.207.245.1:58858: --- begin STUN message --- STUN Binding request Hdr: length=124, magic=2112a442, tsx_id=000078db3210402c3d1cd6c2 Attributes: PRIORITY: length=4, value=1862270975 (0x6effffff) ICE-CONTROLLED: length=8, data=1a0b8a375dd49e59 SOFTWARE: length=0, value="pjnath-2.2.1" USERNAME: length=0, value="s1o+TB82UPCSjuDE:3b41517f58736edc02ae5a3e45902279" MESSAGE-INTEGRITY: length=20, data=6bbe2901c47aa980b1c44d7d7f3c23361d376116 FINGERPRINT: length=4, value=3373702849 (0xc9169ec1) --- end of STUN message --- [Aug 11 16:31:40] DEBUG[30973] pjsip: utsx0x7f654400 ...STUN client transaction created [Aug 11 16:31:40] DEBUG[30973] pjsip: utsx0x7f654400 ...STUN sending message (transmit count=1) [Aug 11 16:31:40] DEBUG[30973] pjsip: icess0x7f65400 ..Check 2: [1] 10.24.18.124:11100-->216.207.245.1:58858: state changed from Waiting to In Progress [Aug 11 16:31:40] DEBUG[31269][C-00000005] pjsip: stuse0x7f65400 .RX 132 bytes STUN message from 10.24.17.254:58858: --- begin STUN message --- STUN Binding request Hdr: length=112, magic=2112a442, tsx_id=6c74354c6953792b6a4f3875 Attributes: USERNAME: length=49, value="3b41517f58736edc02ae5a3e45902279:s1o+TB82UPCSjuDE" ICE-CONTROLLING: length=8, data=e14d06dfa04ef80f USE-CANDIDATE: length=0 PRIORITY: length=4, value=1853824767 (0x6e7f1eff) MESSAGE-INTEGRITY: length=20, data=f6ee4c7e9ee74f5d5bdaf3602386c4a792a93823 FINGERPRINT: length=4, value=3045352534 (0xb5846456) --- end of STUN message --- [Aug 11 16:31:40] DEBUG[31269][C-00000005] pjsip: stuse0x7f65400 ..TX 80 bytes STUN message to 10.24.17.254:58858: --- begin STUN message --- STUN Binding success response Hdr: length=60, magic=2112a442, tsx_id=6c74354c6953792b6a4f3875 Attributes: XOR-MAPPED-ADDRESS: length=8, IPv4 addr=10.24.17.254:58858 SOFTWARE: length=0, value="pjnath-2.2.1" MESSAGE-INTEGRITY: length=20, data=4aec2523dadcf335028e7387c63f51619a8ad2a0 FINGERPRINT: length=4, value=1843935661 (0x6de839ad) --- end of STUN message --- [Aug 11 16:31:40] DEBUG[31269][C-00000005] pjsip: icess0x7f65400 .Triggered check for check 0 not performed because it's in progress. Retransmitting [Aug 11 16:31:40] DEBUG[31269][C-00000005] pjsip: utsx0x7f654002 ..STUN sending message (transmit count=1) [Aug 11 16:31:40] DEBUG[31269][C-00000005] pjsip: stuse0x7f65400 .RX 64 bytes STUN message from 10.24.17.254:58858: --- begin STUN message --- STUN Binding success response Hdr: length=44, magic=2112a442, tsx_id=000078db41e7dde93d1cd6c0 Attributes: XOR-MAPPED-ADDRESS: length=8, IPv4 addr=10.24.18.124:11100 MESSAGE-INTEGRITY: length=20, data=0e9ae99296f55603db3d64d0567cd73f9feaac62 FINGERPRINT: length=4, value=3412449855 (0xcb65da3f) --- end of STUN message --- [Aug 11 16:31:40] DEBUG[31269][C-00000005] pjsip: icess0x7f65400 .Check 0: [1] 10.24.18.124:11100-->10.24.17.254:58858 (nominated): connectivity check SUCCESS [Aug 11 16:31:40] DEBUG[31269][C-00000005] pjsip: icess0x7f65400 .Check 0: [1] 10.24.18.124:11100-->10.24.17.254:58858: state changed from In Progress to Succeeded [Aug 11 16:31:40] DEBUG[31269][C-00000005] pjsip: icess0x7f65400 .Check 0 is successful and nominated [Aug 11 16:31:40] DEBUG[31269][C-00000005] pjsip: icess0x7f65400 .Cancelling check 2: [1] 10.24.18.124:11100-->216.207.245.1:58858 (In Progress) [Aug 11 16:31:40] DEBUG[31269][C-00000005] pjsip: stun_session.c .tdata 0x7f6544002658 destroy request, force=0, tsx=0x7f6544002830 [Aug 11 16:31:40] DEBUG[31269][C-00000005] pjsip: utsx0x7f654400 .STUN transaction 0x7f6544002830 schedule destroy [Aug 11 16:31:40] DEBUG[31269][C-00000005] pjsip: icess0x7f65400 .Check 2: [1] 10.24.18.124:11100-->216.207.245.1:58858: state changed from In Progress to Failed [Aug 11 16:31:40] DEBUG[31269][C-00000005] pjsip: icess0x7f65400 .Check 4: [1] 10.24.18.124:11100-->10.24.17.254:0 to be failed because state is Waiting [Aug 11 16:31:40] DEBUG[31269][C-00000005] pjsip: icess0x7f65400 .Check 4: [1] 10.24.18.124:11100-->10.24.17.254:0: state changed from Waiting to Failed [Aug 11 16:31:40] DEBUG[31269][C-00000005] pjsip: stun_session.c .tdata 0x7f6540027458 destroy request, force=0, tsx=0x7f6540027630 [Aug 11 16:31:40] DEBUG[31269][C-00000005] pjsip: utsx0x7f654002 .STUN transaction 0x7f6540027630 schedule destroy [Aug 11 16:31:40] DEBUG[30973] pjsip: icess0x7f65400 Starting checklist periodic check [Aug 11 16:31:40] DEBUG[30973] pjsip: icess0x7f65400 .Sending connectivity check for check 3: [2] 10.24.18.124:11101-->216.207.245.1:58858 [Aug 11 16:31:40] DEBUG[30973] pjsip: stuse0x7f65400 ...TX 144 bytes STUN message to 216.207.245.1:58858: --- begin STUN message --- STUN Binding request Hdr: length=124, magic=2112a442, tsx_id=000078db64c082d43d1cd6c3 Attributes: PRIORITY: length=4, value=1862270974 (0x6efffffe) ICE-CONTROLLED: length=8, data=1a0b8a375dd49e59 SOFTWARE: length=0, value="pjnath-2.2.1" USERNAME: length=0, value="s1o+TB82UPCSjuDE:3b41517f58736edc02ae5a3e45902279" MESSAGE-INTEGRITY: length=20, data=90e2992425cf58eb91792456eeeabcb6b9bedd4a FINGERPRINT: length=4, value=3167801212 (0xbcd0cf7c) --- end of STUN message --- [Aug 11 16:31:40] DEBUG[30973] pjsip: utsx0x7f654400 ...STUN client transaction created [Aug 11 16:31:40] DEBUG[30973] pjsip: utsx0x7f654400 ...STUN sending message (transmit count=1) [Aug 11 16:31:40] DEBUG[30973] pjsip: icess0x7f65400 ..Check 3: [2] 10.24.18.124:11101-->216.207.245.1:58858: state changed from Waiting to In Progress [Aug 11 16:31:40] DEBUG[30973] pjsip: icess0x7f65400 Starting checklist periodic check [Aug 11 16:31:40] DEBUG[30973] pjsip: icess0x7f65400 .Sending connectivity check for check 5: [2] 10.24.18.124:11101-->10.24.17.254:0 [Aug 11 16:31:40] DEBUG[30973] pjsip: stuse0x7f65400 ...TX 144 bytes STUN message to 10.24.17.254:0: --- begin STUN message --- STUN Binding request Hdr: length=124, magic=2112a442, tsx_id=000078db72282e133d1cd6c4 Attributes: PRIORITY: length=4, value=1862270974 (0x6efffffe) ICE-CONTROLLED: length=8, data=1a0b8a375dd49e59 SOFTWARE: length=0, value="pjnath-2.2.1" USERNAME: length=0, value="s1o+TB82UPCSjuDE:3b41517f58736edc02ae5a3e45902279" MESSAGE-INTEGRITY: length=20, data=ad245268818480fdbd76cf7b43ad04ecaec2a87e FINGERPRINT: length=4, value=1497796208 (0x59468e70) --- end of STUN message --- [Aug 11 16:31:40] DEBUG[30973] pjsip: utsx0x7f654400 ...STUN client transaction created [Aug 11 16:31:40] DEBUG[30973] pjsip: utsx0x7f654400 ...STUN sending message (transmit count=1) [Aug 11 16:31:40] DEBUG[30973] pjsip: utsx0x7f654400 ....STUN error sending message: Invalid argument [Aug 11 16:31:40] DEBUG[30973] pjsip: stun_session.c ...tdata 0x7f6544003268 destroy request, force=0, tsx=0x7f6544003440 [Aug 11 16:31:40] DEBUG[30973] pjsip: utsx0x7f654400 ...STUN transaction 0x7f6544003440 schedule destroy [Aug 11 16:31:40] DEBUG[30973] pjsip: stuse0x7f65400 ...Error sending STUN request: Invalid argument [Aug 11 16:31:40] ERROR[30973] pjsip: icess0x7f65400 ..Error sending STUN request: Invalid argument [Aug 11 16:31:40] DEBUG[31269][C-00000005] pjsip: stuse0x7f65400 .RX 132 bytes STUN message from 10.24.17.254:58858: --- begin STUN message --- STUN Binding request Hdr: length=112, magic=2112a442, tsx_id=3764574d4d33366148554732 Attributes: USERNAME: length=49, value="3b41517f58736edc02ae5a3e45902279:s1o+TB82UPCSjuDE" ICE-CONTROLLING: length=8, data=e14d06dfa04ef80f USE-CANDIDATE: length=0 PRIORITY: length=4, value=1853824767 (0x6e7f1eff) MESSAGE-INTEGRITY: length=20, data=7dce1dfcb3b15ace759a7854110e7021c6414e25 FINGERPRINT: length=4, value=3197623401 (0xbe97dc69) --- end of STUN message --- [Aug 11 16:31:40] DEBUG[31269][C-00000005] pjsip: stuse0x7f65400 ..TX 80 bytes STUN message to 10.24.17.254:58858: --- begin STUN message --- STUN Binding success response Hdr: length=60, magic=2112a442, tsx_id=3764574d4d33366148554732 Attributes: XOR-MAPPED-ADDRESS: length=8, IPv4 addr=10.24.17.254:58858 SOFTWARE: length=0, value="pjnath-2.2.1" MESSAGE-INTEGRITY: length=20, data=f00c267e68a9ce4677bdd94745f2bd8ed3926c5c FINGERPRINT: length=4, value=549733538 (0x20c444a2) --- end of STUN message --- [Aug 11 16:31:40] DEBUG[31269][C-00000005] pjsip: icess0x7f65400 .Valid check 0: [1] 10.24.18.124:11100-->10.24.17.254:58858 is nominated [Aug 11 16:31:40] DEBUG[31269][C-00000005] pjsip: icess0x7f65400 .Triggered check for check 0 not performed because it's completed [Aug 11 16:31:40] DEBUG[31269][C-00000005] pjsip: icess0x7f65400 ..Check 0 is successful and nominated [Aug 11 16:31:40] DEBUG[30973] pjsip: utsx0x7f654400 STUN sending message (transmit count=2) [Aug 11 16:31:40] DEBUG[30973] pjsip: utsx0x7f654400 STUN client transaction 0x7f65440015b0 stopped, ref_cnt=10 [Aug 11 16:31:40] DEBUG[30973] pjsip: stun_session.c STUN transaction 0x7f65440015b0 destroyed [Aug 11 16:31:40] DEBUG[30973] pjsip: utsx0x7f654400 STUN client transaction 0x7f6544002830 stopped, ref_cnt=9 [Aug 11 16:31:40] DEBUG[30973] pjsip: stun_session.c STUN transaction 0x7f6544002830 destroyed [Aug 11 16:31:40] DEBUG[30973] pjsip: utsx0x7f654002 STUN client transaction 0x7f6540027630 stopped, ref_cnt=8 [Aug 11 16:31:40] DEBUG[30973] pjsip: stun_session.c STUN transaction 0x7f6540027630 destroyed [Aug 11 16:31:40] DEBUG[30973] pjsip: utsx0x7f654400 STUN sending message (transmit count=3) [Aug 11 16:31:40] DEBUG[30973] pjsip: utsx0x7f654400 STUN client transaction 0x7f6544003440 stopped, ref_cnt=7 [Aug 11 16:31:40] DEBUG[30973] pjsip: stun_session.c STUN transaction 0x7f6544003440 destroyed [Aug 11 16:31:41] DEBUG[31269][C-00000005] channel.c: Didn't receive a media frame from SIP/354-00000005 within 500 ms of answering. Continuing anyway [Aug 11 16:31:41] DEBUG[31269][C-00000005] pbx.c: Launching 'Playback' [Aug 11 16:31:41] DEBUG[31269][C-00000005] channel.c: Set channel SIP/354-00000005 to write format gsm [Aug 11 16:31:41] DEBUG[31269][C-00000005] res_rtp_asterisk.c: Ooh, format changed from unknown to alaw [Aug 11 16:31:41] DEBUG[31269][C-00000005] res_rtp_asterisk.c: Created smoother: format: alaw ms: 20 len: 160 [Aug 11 16:31:41] DEBUG[31269][C-00000005] res_rtp_asterisk.c: Starting RTCP transmission on RTP instance '0x7f654000e968' [Aug 11 16:31:41] DEBUG[31269][C-00000005] netsock2.c: Splitting '10.24.17.254' into... [Aug 11 16:31:41] DEBUG[31269][C-00000005] netsock2.c: ...host '10.24.17.254' and port ''. [Aug 11 16:31:41] DEBUG[31269][C-00000005] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Aug 11 16:31:41] DEBUG[31269][C-00000005] netsock2.c: Splitting '10.24.17.254' into... [Aug 11 16:31:41] DEBUG[31269][C-00000005] netsock2.c: ...host '10.24.17.254' and port ''. [Aug 11 16:31:41] DEBUG[31269][C-00000005] netsock2.c: Splitting '10.24.17.254' into... [Aug 11 16:31:41] DEBUG[31269][C-00000005] netsock2.c: ...host '10.24.17.254' and port ''. [Aug 11 16:31:41] DEBUG[31269][C-00000005] netsock2.c: Splitting '10.24.17.254' into... [Aug 11 16:31:41] DEBUG[31269][C-00000005] netsock2.c: ...host '10.24.17.254' and port ''. [Aug 11 16:31:41] DEBUG[31269][C-00000005] pjsip: stuse0x7f65400 .RX 132 bytes STUN message from 10.24.17.254:58858: --- begin STUN message --- STUN Binding request Hdr: length=112, magic=2112a442, tsx_id=3739767876435479764b4a76 Attributes: USERNAME: length=49, value="3b41517f58736edc02ae5a3e45902279:s1o+TB82UPCSjuDE" ICE-CONTROLLING: length=8, data=e14d06dfa04ef80f USE-CANDIDATE: length=0 PRIORITY: length=4, value=1853824767 (0x6e7f1eff) MESSAGE-INTEGRITY: length=20, data=d51049a7a765fbe8900d0b0b04d6bd8b24d460ac FINGERPRINT: length=4, value=4079394175 (0xf3269d7f) --- end of STUN message --- [Aug 11 16:31:41] DEBUG[31269][C-00000005] pjsip: stuse0x7f65400 ..TX 80 bytes STUN message to 10.24.17.254:58858: --- begin STUN message --- STUN Binding success response Hdr: length=60, magic=2112a442, tsx_id=3739767876435479764b4a76 Attributes: XOR-MAPPED-ADDRESS: length=8, IPv4 addr=10.24.17.254:58858 SOFTWARE: length=0, value="pjnath-2.2.1" MESSAGE-INTEGRITY: length=20, data=59feff7c932bf36a8c4cf4a59903bb34d8522c0b FINGERPRINT: length=4, value=1860211625 (0x6ee093a9) --- end of STUN message --- [Aug 11 16:31:41] DEBUG[31269][C-00000005] pjsip: icess0x7f65400 .Valid check 0: [1] 10.24.18.124:11100-->10.24.17.254:58858 is nominated [Aug 11 16:31:41] DEBUG[31269][C-00000005] pjsip: icess0x7f65400 .Triggered check for check 0 not performed because it's completed [Aug 11 16:31:41] DEBUG[31269][C-00000005] pjsip: icess0x7f65400 ..Check 0 is successful and nominated [Aug 11 16:31:41] DEBUG[31269][C-00000005] netsock2.c: Splitting '10.24.17.254' into... [Aug 11 16:31:41] DEBUG[31269][C-00000005] netsock2.c: ...host '10.24.17.254' and port ''. [Aug 11 16:31:41] DEBUG[31269][C-00000005] netsock2.c: Splitting '10.24.17.254' into... [Aug 11 16:31:41] DEBUG[31269][C-00000005] netsock2.c: ...host '10.24.17.254' and port ''. [Aug 11 16:31:41] DEBUG[31269][C-00000005] netsock2.c: Splitting '10.24.17.254' into... [Aug 11 16:31:41] DEBUG[31269][C-00000005] netsock2.c: ...host '10.24.17.254' and port ''. [Aug 11 16:31:41] DEBUG[31269][C-00000005] netsock2.c: Splitting '10.24.17.254' into... [Aug 11 16:31:41] DEBUG[31269][C-00000005] netsock2.c: ...host '10.24.17.254' and port ''. [Aug 11 16:31:41] DEBUG[31269][C-00000005] netsock2.c: Splitting '10.24.17.254' into... [Aug 11 16:31:41] DEBUG[31269][C-00000005] netsock2.c: ...host '10.24.17.254' and port ''. [Aug 11 16:31:41] DEBUG[31269][C-00000005] netsock2.c: Splitting '10.24.17.254' into... [Aug 11 16:31:41] DEBUG[31269][C-00000005] netsock2.c: ...host '10.24.17.254' and port ''. [Aug 11 16:31:41] DEBUG[31269][C-00000005] netsock2.c: Splitting '10.24.17.254' into... [Aug 11 16:31:41] DEBUG[31269][C-00000005] netsock2.c: ...host '10.24.17.254' and port ''. [Aug 11 16:31:41] DEBUG[31269][C-00000005] netsock2.c: Splitting '10.24.17.254' into... [Aug 11 16:31:41] DEBUG[31269][C-00000005] netsock2.c: ...host '10.24.17.254' and port ''. [Aug 11 16:31:41] DEBUG[31269][C-00000005] netsock2.c: Splitting '10.24.17.254' into... [Aug 11 16:31:41] DEBUG[31269][C-00000005] netsock2.c: ...host '10.24.17.254' and port ''. [Aug 11 16:31:41] DEBUG[31269][C-00000005] netsock2.c: Splitting '10.24.17.254' into... [Aug 11 16:31:41] DEBUG[31269][C-00000005] netsock2.c: ...host '10.24.17.254' and port ''. [Aug 11 16:31:41] DEBUG[30973] pjsip: utsx0x7f654400 STUN sending message (transmit count=4) [Aug 11 16:31:41] DEBUG[31269][C-00000005] netsock2.c: Splitting '10.24.17.254' into... [Aug 11 16:31:41] DEBUG[31269][C-00000005] netsock2.c: ...host '10.24.17.254' and port ''. [Aug 11 16:31:41] DEBUG[31269][C-00000005] netsock2.c: Splitting '10.24.17.254' into... [Aug 11 16:31:41] DEBUG[31269][C-00000005] netsock2.c: ...host '10.24.17.254' and port ''. [Aug 11 16:31:41] DEBUG[31269][C-00000005] netsock2.c: Splitting '10.24.17.254' into... [Aug 11 16:31:41] DEBUG[31269][C-00000005] netsock2.c: ...host '10.24.17.254' and port ''. [Aug 11 16:31:41] DEBUG[31269][C-00000005] netsock2.c: Splitting '10.24.17.254' into... [Aug 11 16:31:41] DEBUG[31269][C-00000005] netsock2.c: ...host '10.24.17.254' and port ''. [Aug 11 16:31:41] DEBUG[31269][C-00000005] netsock2.c: Splitting '10.24.17.254' into... [Aug 11 16:31:41] DEBUG[31269][C-00000005] netsock2.c: ...host '10.24.17.254' and port ''. [Aug 11 16:31:41] DEBUG[31269][C-00000005] netsock2.c: Splitting '10.24.17.254' into... [Aug 11 16:31:41] DEBUG[31269][C-00000005] netsock2.c: ...host '10.24.17.254' and port ''. [Aug 11 16:31:41] DEBUG[31269][C-00000005] netsock2.c: Splitting '10.24.17.254' into... [Aug 11 16:31:41] DEBUG[31269][C-00000005] netsock2.c: ...host '10.24.17.254' and port ''. [Aug 11 16:31:41] DEBUG[31269][C-00000005] netsock2.c: Splitting '10.24.17.254' into... [Aug 11 16:31:41] DEBUG[31269][C-00000005] netsock2.c: ...host '10.24.17.254' and port ''. [Aug 11 16:31:41] DEBUG[31269][C-00000005] netsock2.c: Splitting '10.24.17.254' into... [Aug 11 16:31:41] DEBUG[31269][C-00000005] netsock2.c: ...host '10.24.17.254' and port ''. [Aug 11 16:31:41] DEBUG[31269][C-00000005] netsock2.c: Splitting '10.24.17.254' into... [Aug 11 16:31:41] DEBUG[31269][C-00000005] netsock2.c: ...host '10.24.17.254' and port ''. [Aug 11 16:31:41] DEBUG[31269][C-00000005] netsock2.c: Splitting '10.24.17.254' into... [Aug 11 16:31:41] DEBUG[31269][C-00000005] netsock2.c: ...host '10.24.17.254' and port ''. [Aug 11 16:31:41] DEBUG[31269][C-00000005] netsock2.c: Splitting '10.24.17.254' into... [Aug 11 16:31:41] DEBUG[31269][C-00000005] netsock2.c: ...host '10.24.17.254' and port ''. [Aug 11 16:31:41] ERROR[31269][C-00000005] res_rtp_asterisk.c: DTLS failure occurred on RTP instance '0x7f654000e968' due to reason '(null)', terminating [Aug 11 16:31:41] WARNING[31269][C-00000005] res_rtp_asterisk.c: RTP Read error: Unspecified. Hanging up. [Aug 11 16:31:41] DEBUG[31269][C-00000005] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Aug 11 16:31:41] DEBUG[31269][C-00000005] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Aug 11 16:31:41] DEBUG[31269][C-00000005] channel.c: Set channel SIP/354-00000005 to write format alaw [Aug 11 16:31:41] WARNING[31269][C-00000005] app_playback.c: Playback failed on SIP/354-00000005 for demo-congrats [Aug 11 16:31:41] DEBUG[31269][C-00000005] pbx.c: Extension 1000, priority 2 returned normally even though call was hung up [Aug 11 16:31:41] DEBUG[31269][C-00000005] channel.c: Soft-Hanging (0x10) up channel 'SIP/354-00000005' [Aug 11 16:31:41] DEBUG[31269][C-00000005] channel.c: Hanging up channel 'SIP/354-00000005' [Aug 11 16:31:41] DEBUG[31269][C-00000005] chan_sip.c: Hangup call SIP/354-00000005, SIP callid c2cd395f-d7d2-26da-3ae0-4b5881316cc1 [Aug 11 16:31:41] DEBUG[31269][C-00000005] chan_sip.c: update_call_counter(354) - decrement call limit counter on hangup [Aug 11 16:31:41] DEBUG[31269][C-00000005] chan_sip.c: Updating call counter for incoming call [Aug 11 16:31:41] DEBUG[31269][C-00000005] chan_sip.c: Call from peer '354' removed from call limit 100 [Aug 11 16:31:41] DEBUG[31269][C-00000005] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7f654000e968' [Aug 11 16:31:41] DEBUG[30950] devicestate.c: No provider found, checking channel drivers for SIP - 354 [Aug 11 16:31:41] VERBOSE[31269][C-00000005] chan_sip.c: Scheduling destruction of SIP dialog 'c2cd395f-d7d2-26da-3ae0-4b5881316cc1' in 32000 ms (Method: INVITE) [Aug 11 16:31:41] DEBUG[30950] chan_sip.c: Checking device state for peer 354 [Aug 11 16:31:41] DEBUG[30950] devicestate.c: Changing state for SIP/354 - state 1 (Not in use) [Aug 11 16:31:41] DEBUG[31010] 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:31:41] DEBUG[31269][C-00000005] chan_sip.c: Strict routing enforced for session c2cd395f-d7d2-26da-3ae0-4b5881316cc1 [Aug 11 16:31:41] VERBOSE[31269][C-00000005] chan_sip.c: set_destination: Parsing for address/port to send to [Aug 11 16:31:41] VERBOSE[31269][C-00000005] chan_sip.c: set_destination: URI is for WebSocket, we can't set destination [Aug 11 16:31:41] VERBOSE[31269][C-00000005] 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=z9hG4bK78bdb3ff ˙Max-Forwards: 70 ˙From: ;tag=as721af86d ˙To: "354";tag=yB3kheDC1hkF4DX5eiCm ˙Call-ID: c2cd395f-d7d2-26da-3ae0-4b5881316cc1 ˙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="5a8a7250", response="3bd93d8347838f987fa38797fa280d1d" ˙X-Asterisk-HangupCause: Unknown ˙X-Asterisk-HangupCauseCode: 0 ˙Content-Length: 0 ˙ ˙ ˙--- [Aug 11 16:31:41] DEBUG[31269][C-00000005] chan_sip.c: Trying to put 'BYE sip:354' onto WS socket destined for 10.24.17.254:5060 [Aug 11 16:31:41] DEBUG[30952] cdr.c: Finalized CDR for SIP/354-00000005 - start 1407792700.521475 answer 1407792700.522579 end 1407792701.531787 dispo ANSWERED [Aug 11 16:31:41] DEBUG[30950] devicestate.c: No provider found, checking channel drivers for SIP - 354 [Aug 11 16:31:41] DEBUG[30950] chan_sip.c: Checking device state for peer 354 [Aug 11 16:31:41] DEBUG[30950] devicestate.c: Changing state for SIP/354 - state 1 (Not in use) [Aug 11 16:31:41] VERBOSE[31256] chan_sip.c: ˙<--- SIP read from WS:10.24.17.254:37587 ---> ˙SIP/2.0 200 OK ˙Via: SIP/2.0/WS 10.24.18.124:5060;branch=z9hG4bK78bdb3ff ˙From: ;tag=as721af86d ˙To: "354";tag=yB3kheDC1hkF4DX5eiCm ˙Contact: ˙Call-ID: c2cd395f-d7d2-26da-3ae0-4b5881316cc1 ˙CSeq: 102 BYE ˙Content-Length: 0 ˙ ˙<-------------> [Aug 11 16:31:41] DEBUG[31256] chan_sip.c: Header 0 [ 14]: SIP/2.0 200 OK [Aug 11 16:31:41] DEBUG[31256] chan_sip.c: Header 1 [ 56]: Via: SIP/2.0/WS 10.24.18.124:5060;branch=z9hG4bK78bdb3ff [Aug 11 16:31:41] DEBUG[31256] chan_sip.c: Header 2 [ 44]: From: ;tag=as721af86d [Aug 11 16:31:41] DEBUG[31256] chan_sip.c: Header 3 [ 56]: To: "354";tag=yB3kheDC1hkF4DX5eiCm [Aug 11 16:31:41] DEBUG[31256] chan_sip.c: Header 4 [ 52]: Contact: [Aug 11 16:31:41] DEBUG[31256] chan_sip.c: Header 5 [ 45]: Call-ID: c2cd395f-d7d2-26da-3ae0-4b5881316cc1 [Aug 11 16:31:41] DEBUG[31256] chan_sip.c: Header 6 [ 13]: CSeq: 102 BYE [Aug 11 16:31:41] DEBUG[31256] chan_sip.c: Header 7 [ 17]: Content-Length: 0 [Aug 11 16:31:41] VERBOSE[31256] chan_sip.c: --- (8 headers 0 lines) --- [Aug 11 16:31:41] DEBUG[31256] chan_sip.c: = Looking for Call ID: c2cd395f-d7d2-26da-3ae0-4b5881316cc1 (Checking To) --From tag as721af86d --To-tag yB3kheDC1hkF4DX5eiCm [Aug 11 16:31:41] VERBOSE[31256][C-00000005] chan_sip.c: SIP Response message for INCOMING dialog BYE arrived [Aug 11 16:31:42] DEBUG[30973] pjsip: utsx0x7f654400 STUN sending message (transmit count=5) [Aug 11 16:31:42] DEBUG[30995] chan_sip.c: Destroying SIP dialog c2cd395f-d7d2-26da-3ae0-4b5881316cc1 [Aug 11 16:31:42] VERBOSE[30995] chan_sip.c: Really destroying SIP dialog 'c2cd395f-d7d2-26da-3ae0-4b5881316cc1' Method: INVITE [Aug 11 16:31:42] DEBUG[30995] pjsip: icess0x7f65400 Destroying ICE session 0x7f654003d178 [Aug 11 16:31:42] DEBUG[30995] pjsip: stuse0x7f65400 STUN session 0x7f654001b648 destroy request, ref_cnt=8 [Aug 11 16:31:42] DEBUG[30995] pjsip: stuse0x7f65400 STUN session 0x7f6540016388 destroy request, ref_cnt=4 [Aug 11 16:31:42] DEBUG[30995] pjsip: utsx0x7f654400 STUN client transaction 0x7f6544002c40 stopped, ref_cnt=4 [Aug 11 16:31:42] DEBUG[30995] pjsip: ice_session.c ICE session 0x7f654003d178 destroyed [Aug 11 16:31:42] DEBUG[30995] pjsip: stun_session.c tdata 0x7f65500272c8 destroy request, force=1, tsx=(nil) [Aug 11 16:31:42] DEBUG[30995] pjsip: stun_session.c tdata 0x7f65500280f8 destroy request, force=1, tsx=(nil) [Aug 11 16:31:42] DEBUG[30995] pjsip: stun_session.c tdata 0x7f65500288f8 destroy request, force=1, tsx=(nil) [Aug 11 16:31:42] DEBUG[30995] pjsip: stun_session.c STUN session 0x7f654001b648 destroyed [Aug 11 16:31:42] DEBUG[30995] pjsip: stun_session.c tdata 0x7f6544002a68 destroy request, force=1, tsx=0x7f6544002c40 [Aug 11 16:31:42] DEBUG[30995] pjsip: utsx0x7f654400 STUN client transaction 0x7f6544002c40 stopped, ref_cnt=0 [Aug 11 16:31:42] DEBUG[30995] pjsip: stun_session.c STUN session 0x7f6540016388 destroyed [Aug 11 16:31:42] DEBUG[30995] rtp_engine.c: Destroyed RTP instance '0x7f654000e968' [Aug 11 16:31:50] DEBUG[31013] cdr.c: CDR Engine termination request received; waiting on messages... [Aug 11 16:31:50] DEBUG[31013] taskprocessor.c: destroying taskprocessor 'ast_msg_queue' [Aug 11 16:31:50] VERBOSE[31013] asterisk.c: Asterisk cleanly ending (0). [Aug 11 16:31:50] VERBOSE[31013] asterisk.c: Executing last minute cleanups [Aug 11 16:31:50] DEBUG[31013] res_musiconhold.c: Destroying MOH class 'default' [Aug 11 16:31:50] DEBUG[31013] taskprocessor.c: destroying taskprocessor 'e7f7c424-44d3-416c-94d7-477f3412aae5' [Aug 11 16:31:50] DEBUG[31013] logger.c: Unregistered dynamic logger level 'CC' with index 16. [Aug 11 16:31:50] DEBUG[31013] taskprocessor.c: destroying taskprocessor 'CCSS core' [Aug 11 16:31:50] DEBUG[31013] tcptls.c: Stopped server :: AMI server [Aug 11 16:31:50] DEBUG[31013] tcptls.c: Stopped server :: AMI TLS server [Aug 11 16:31:50] DEBUG[31013] channel.c: Unregistering channel type 'Local' [Aug 11 16:31:50] DEBUG[31013] taskprocessor.c: destroying taskprocessor 'ba669bdb-8c7e-40b0-aa65-2a0aea87063d' [Aug 11 16:31:50] DEBUG[31013] taskprocessor.c: destroying taskprocessor 'a402a68d-c965-47b6-9604-4b49a60051c5' [Aug 11 16:31:50] DEBUG[30952] taskprocessor.c: destroying taskprocessor '13259597-0270-4b2d-82ea-065d747ea022' [Aug 11 16:31:50] DEBUG[31013] tcptls.c: Stopped server :: http server [Aug 11 16:31:50] DEBUG[31013] bridge.c: Waiting for bridge manager thread to die. [Aug 11 16:31:50] DEBUG[31013] channel.c: Unregistering channel type 'Surrogate' [Aug 11 16:31:50] DEBUG[31013] taskprocessor.c: destroying taskprocessor 'Sorcery-control' [Aug 11 16:31:50] DEBUG[31013] taskprocessor.c: destroying taskprocessor 'Sorcery' [Aug 11 16:31:50] DEBUG[31013] asterisk.c: Asterisk ending (0).