[Home]

Summary:ASTERISK-24205: DTLS-SRTP fails on SIP over WebSockets call from SIPML5(chrome) to Asterisk
Reporter:Rusty Newton (rnewton)Labels:
Date Opened:2014-08-11 16:30:20Date Closed:
Priority:MajorRegression?
Status:Open/NewComponents:Resources/res_rtp_asterisk
Versions:SVN 12.4.0 13.1.0 Frequency of
Occurrence
Related
Issues:
is related toASTERISK-24334 Crash with chan_sip on SIP to SIP over WebSockets call (WebRTC, SIPML5)
Environment:Asterisk SVN-branch-12-r420805 (August 11th 2014), SVN-branch-13-r429983(Dec 22nd 2014, Chrome (38.0.2114.2 dev), Chrome (36.0.1985.125). Firefox 34.0 , SIPML5 live demo (?svn=224), OpenSSL( 1.0.1-4ubuntu5.20)Attachments:( 0) full_2.pcap
( 1) full_2.txt
( 2) full.txt
( 3) sip.conf.txt
( 4) sipDtls.conf
Description:[Edit by Rusty - Environment updated on 12/22/14 as I ran into this issue with a newer environment (Asterisk, pjproject and openssl.)

Attempting to make a call from SIPML5 in Chrome to a Playback of demo-congrats in Asterisk. Call fails upon hitting the playback.

{noformat}
 == Using SIP RTP CoS mark 5
   -- Executing [1000@default:1] Answer("SIP/354-00000004", "") in new stack
   -- Executing [1000@default:2] Playback("SIP/354-00000004", "demo-congrats") in new stack
   -- <SIP/354-00000004> Playing 'demo-congrats.gsm' (language 'en')
[Aug 11 16:28:52] ERROR[31257][C-00000004]: res_rtp_asterisk.c:1732 __rtp_recvfrom: DTLS failure occurred on RTP instance '0x7f6540009138' due to reason '(null)', terminating
[Aug 11 16:28:52] WARNING[31257][C-00000004]: res_rtp_asterisk.c:3944 ast_rtp_read: RTP Read error: Unspecified.  Hanging up.
[Aug 11 16:28:52] WARNING[31257][C-00000004]: app_playback.c:493 playback_exec: Playback failed on SIP/354-00000004 for demo-congrats
{noformat}

Once Asterisk hits the sound, we see a DTLS failure and the call disconnects.
Attached full debug file with SIP trace.

h2. Environment detail:

Asterisk SVN-branch-12-r420805 (August 11th 2014), Chrome (38.0.2114.2 dev), Chrome (36.0.1985.125). SIPML5 live demo (?svn=224)

Machines involved:
* Chrome(SIPML5) at 10.24.17.254
* Asterisk at 10.24.18.124

Comments:By: Rusty Newton (rnewton) 2014-08-11 16:55:32.711-0500

Attaching another debug log of call attempt along with a pcap. The packet capture was wide open on eth0 (10.24.18.124) during time of the call.
By: Aleksei Kulakov (Each) 2014-08-12 05:59:05.535-0500

Works as expected on 12.4.0 with my  [^sipDtls.conf]: call estabilished, sound is heard on both sides(but if call picked up in less than 7 sec, for details see ASTERISK-24146)
By: Matt Jordan (mjordan) 2014-08-14 10:33:16.873-0500

I'm not sure this is a bug in Asterisk. The part where {{res_rtp_asterisk}} kicks out with the {{ERROR}} is due to {{SSL_Read}} returning an error, indicating that we couldn't read any data.

Looking at the {{pcap}}, I don't see any RTP packets flowing from the WebRTC client to Asterisk: so it's not surprising the {{SSL_Read}} would fail. Looking at the {{pcap}}, we attempted a DTLS handshake with 216.207.245.1, which is what the WebRTC client negotiated with us in the SDP:

{noformat}
�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
{noformat}

However, as we can tell from the later STUN checks (as this is also an ICE candidate), the IP address/port negotiated with Asterisk is unreachable:

{noformat}
[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 ---
{noformat}

...

{noformat}
[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
{noformat}

This matches what the pcap tells us.

This appears to be a bug in SIPml5 and/or a networking issue. It shouldn't be negotiating an unreachable IP address/port, or there is something in the network preventing us from reaching the offered IP address/port.
By: Joshua C. Colp (jcolp) 2014-08-14 10:40:48.590-0500

Your analysis doesn't appear to be correct. While Asterisk may have initially attempted the public IP address for some reason it moved on to the ICE negotiation candidates when the ICE negotiation completed. The DTLS traffic was received by Chrome and it responded accordingly. Why the DTLS negotiation then failed I'm not sure.
By: Aleksei Kulakov (Each) 2014-08-14 13:31:22.294-0500

I believe it is about "incorrect"(lack of right magic) config. Just try using sipDtls.conf with keys generated by ast_tls_cert contrib script. If this not helps, then it is probably environment/build related issue, because it works fine on my side.
By: Rusty Newton (rnewton) 2014-09-16 19:19:32.765-0500

[~Each] I tested with your config and got the same behavior as I did previously. There likely is something different about the environment or topology. Can you post more details on your SIPML5 configuration and network topology concerning the devices involved?

In addition, when calling from a local SIP phone to the WebRTC client, SIPML5 I triggered a crash, which I've filed at ASTERISK-24334.
By: Rusty Newton (rnewton) 2014-09-23 16:20:22.937-0500

This issue also occurs for me when using PJSIP.

I've worked with a co-worker to at least track the issue to my Asterisk environment. Using a configuration that works for another system I still end up with the same failures as seen here, and yet a different failure if using wss instead of ws. I'll have to try with a completely fresh install on a new system/VM.
By: Rusty Newton (rnewton) 2014-12-22 17:53:00.769-0600

While running into this: ASTERISK-24639

I also ran into this issue again as well. It happens with the latest pjproject, Asterisk 13, openssl, etc and with pjsip instead of chan_sip.

{noformat}
   -- Executing [1000@from-internal:2] Playback("Local/1000@from-internal-00000000;2", "demo-congrats") in new stack
   -- <Local/1000@from-internal-00000000;2> Playing 'demo-congrats.gsm' (language 'en')
   -- Call on PJSIP/101-00000000 placed on hold
   -- Started music on hold, class 'default', on channel 'Local/1000@from-internal-00000000;1'
   -- PJSIP/101-00000000 answered Local/1000@from-internal-00000000;1
   -- Stopped music on hold on Local/1000@from-internal-00000000;1
   -- Channel Local/1000@from-internal-00000000;1 joined 'simple_bridge' basic-bridge <134f1ae7-5ccd-4d01-917e-83120ed8e971>
   -- Channel PJSIP/101-00000000 joined 'simple_bridge' basic-bridge <134f1ae7-5ccd-4d01-917e-83120ed8e971>
[Dec 22 17:17:05] ERROR[6521][C-00000001]: res_rtp_asterisk.c:2040 __rtp_recvfrom: DTLS failure occurred on RTP instance '0x7f0be0010c18' due to reason '(null)', terminating
[Dec 22 17:17:05] WARNING[6521][C-00000001]: res_rtp_asterisk.c:4245 ast_rtp_read: RTP Read error: Unspecified.  Hanging up.
   -- Channel PJSIP/101-00000000 left 'simple_bridge' basic-bridge <134f1ae7-5ccd-4d01-917e-83120ed8e971>
   -- Channel Local/1000@from-internal-00000000;1 left 'simple_bridge' basic-bridge <134f1ae7-5ccd-4d01-917e-83120ed8e971>
 == Spawn extension (from-internal, 101, 1) exited non-zero on 'Local/1000@from-internal-00000000;1'
[Dec 22 17:17:05] WARNING[6504][C-00000000]: app_playback.c:493 playback_exec: Playback failed on Local/1000@from-internal-00000000;2 for demo-congrats
{noformat}

Reproduction in this case occurred when originating between a Local channel dialing a playback and a Dial app dialing the SIPML5 client.

If the messages above do not appear, then we see this crash ASTERISK-24639.

That is, when attempting to make a call you either get the DTLS failure messages or you end up with the crash.
By: Kirill Marchuk (62mkv) 2015-08-05 02:31:13.612-0500

Can anybody let me know: is this message also due to this bug or is it something different:

[2015-07-30 14:42:12] ERROR[29498][C-0000025d]: res_rtp_asterisk.c:2042 __rtp_recvfrom: DTLS failure occurred on RTP instance '0x7f86fd035f48' due to reason 'bad message type', terminating
[2015-07-30 14:42:12] WARNING[29498][C-0000025d]: res_rtp_asterisk.c:3909 ast_rtcp_read: RTCP Read error: Unspecified.  Hanging up.

? thanks
By: Abhay Gupta (agupta) 2015-09-11 06:13:02.307-0500

I am also getting this issue in asterisk 13.5 'bad message type', terminating. This is a intermittent problem though.

Any update on this issue and any solution please ?

By: Joshua C. Colp (jcolp) 2015-09-11 06:15:35.861-0500

Any updates relevant to this issue will be posted here.
By: Dmitry Komov (akacob) 2015-09-28 03:43:36.516-0500

Also have an intermittent issue  "DTLS failure occurred on RTP instance '0x7f8654508938' due to reason 'bad message type', terminating" on asterisk 13.5.
I collected tcpdump trace on asterisk and see that when error occurs STUN frame comes to the same server port right after client sends DTLS Client Hello frame. I suppose this STUN message is considered as 'bad message type'.
By: Sean Bright (seanbright) 2021-12-30 11:24:34.771-0600

Is anyone still experiencing this specific problem with a supported version of Asterisk? Asterisk 16+ at the time of this comment.