2.6.2: DTLS failed

[ibc]

Bug Report

• Operating system: Debian
• mediasoup version: 2.6.2

Issue description

It seems that DTLS fails randomly:

RTC::DtlsTransport::SetTimeout() | DTLS timeout too high (31999ms), resetting DLTS

It may be due the OpenSSL upgrade.

[ibc]

Confirmed that it does not happen with the previous OpenSSL.

• Working version: OpenSSL 1.1.0h 27 Mar 2018
• Failing version: OpenSSL 1.1.0j 20 Nov 2018

[artushin]

Are you going to downgrade openssl or should we downgrade mediasoup?

[ibc]

mediasoup 2.6.3 has been released right now with previous OpenSSL 1.1.0h 27 Mar 2018.

[ibc]

I just reproduce the issue in Consumers, this is, when Chrome connects a WebRTC transport to receive media. In that case, it seems that DTLSv1_get_timeout() returns 1 the first time (as usual) but then it never returns 0, so the timer delay is increased until it reaches the limit.

This is important because this means that it just fails when OpenSSL behaves as DTLS server.

[ibc]

So IMPORTANT: It just fails when mediasoup acts as DTLS server. Much better logs here (with extra logs).

RTC::WebRtcTransport::MayRunDtlsTransport() | transition from DTLS local role 'auto' to 'server' and running DTLS transport +40s
RTC::WebRtcTransport::OnDtlsConnecting() | DTLS connecting +0ms
RTC::DtlsTransport::Run() | running [role:server] +1ms
RTC::DtlsTransport::OnSslInfo() | DTLS handshake start +0ms
RTC::DtlsTransport::OnSslInfo() | [role:server, action:'before SSL initialization'] +0ms
RTC::DtlsTransport::OnSslInfo() | role: server, waiting:'before SSL initialization'] +0ms
RTC::DtlsTransport::OnSslInfo() | [role:server, action:'before SSL initialization'] +0ms
RTC::DtlsTransport::OnSslInfo() | [role:server, action:'SSLv3/TLS read client hello'] +0ms
RTC::DtlsTransport::OnSslInfo() | [role:server, action:'SSLv3/TLS write server hello'] +0ms
RTC::DtlsTransport::OnSslInfo() | [role:server, action:'SSLv3/TLS write certificate'] +0ms
RTC::DtlsTransport::OnSslInfo() | [role:server, action:'SSLv3/TLS write key exchange'] +2ms
RTC::DtlsTransport::OnSslInfo() | [role:server, action:'SSLv3/TLS write certificate request'] +0ms
RTC::DtlsTransport::OnSslInfo() | [role:server, action:'SSLv3/TLS write server done'] +0ms
RTC::DtlsTransport::OnSslInfo() | role: server, waiting:'SSLv3/TLS write server done'] +0ms
RTC::DtlsTransport::SendPendingOutgoingDtlsData() | --- SendPendingOutgoingDTLSData() +40s
RTC::DtlsTransport::SendPendingOutgoingDtlsData() | 885 bytes of DTLS data ready to sent to the peer +0ms
RTC::DtlsTransport::SetTimeout() | --- SetTimeout() +1ms
RTC::DtlsTransport::SetTimeout() | --- DTLSv1_get_timeout() returns 1 +0ms
RTC::DtlsTransport::SetTimeout() | --- DTLSv1_get_timeout() sets dtlsTimeout to 999ms +0ms
RTC::DtlsTransport::OnSslInfo() | [role:server, action:'SSLv3/TLS write server done'] +4ms
RTC::DtlsTransport::OnSslInfo() | [role:server, action:'SSLv3/TLS read client certificate'] +0ms
RTC::DtlsTransport::OnSslInfo() | [role:server, action:'SSLv3/TLS read client key exchange'] +0ms
RTC::DtlsTransport::OnSslInfo() | [role:server, action:'SSLv3/TLS read certificate verify'] +3ms
RTC::DtlsTransport::OnSslInfo() | [role:server, action:'SSLv3/TLS read change cipher spec'] +0ms
RTC::DtlsTransport::OnSslInfo() | [role:server, action:'SSLv3/TLS read finished'] +1ms
RTC::DtlsTransport::OnSslInfo() | [role:server, action:'SSLv3/TLS write change cipher spec'] +0ms
RTC::DtlsTransport::OnSslInfo() | [role:server, action:'SSLv3/TLS write finished'] +0ms
RTC::DtlsTransport::OnSslInfo() | DTLS handshake done +0ms
RTC::DtlsTransport::SendPendingOutgoingDtlsData() | --- SendPendingOutgoingDTLSData() +7ms
RTC::DtlsTransport::SendPendingOutgoingDtlsData() | 67 bytes of DTLS data ready to sent to the peer +0ms
RTC::DtlsTransport::SetTimeout() | --- SetTimeout() +0ms
RTC::DtlsTransport::SetTimeout() | --- DTLSv1_get_timeout() returns 1 +1ms
RTC::DtlsTransport::SetTimeout() | --- DTLSv1_get_timeout() sets dtlsTimeout to 999ms +0ms
RTC::DtlsTransport::SetRemoteFingerprint() | handshake already done, processing it right now +2ms
RTC::DtlsTransport::CheckRemoteFingerprint() | valid remote fingerprint +0ms
RTC::DtlsTransport::GetNegotiatedSrtpProfile() | chosen SRTP profile: SRTP_AES128_CM_SHA1_80 +1ms
RTC::WebRtcTransport::OnDtlsConnected() | DTLS connected +0ms

// So DTLS has been connected!!!
// However, when the DTLS timer expires it seems that OpenSSL has pending data to be sent
// to the browser. But clearly, it receives nothing back so here the problem.

RTC::DtlsTransport::OnTimer() | --- OnTimer() +993ms
RTC::DtlsTransport::SendPendingOutgoingDtlsData() | --- SendPendingOutgoingDTLSData() +0ms
RTC::DtlsTransport::SendPendingOutgoingDtlsData() | 67 bytes of DTLS data ready to sent to the peer +1ms
RTC::DtlsTransport::SetTimeout() | --- SetTimeout() +1ms
RTC::DtlsTransport::SetTimeout() | --- DTLSv1_get_timeout() returns 1 +0ms
RTC::DtlsTransport::SetTimeout() | --- DTLSv1_get_timeout() sets dtlsTimeout to 1999ms +0ms
RTC::DtlsTransport::OnTimer() | --- OnTimer() +2s
RTC::DtlsTransport::SendPendingOutgoingDtlsData() | --- SendPendingOutgoingDTLSData() +0ms
RTC::DtlsTransport::SendPendingOutgoingDtlsData() | 67 bytes of DTLS data ready to sent to the peer +0ms
RTC::DtlsTransport::SetTimeout() | --- SetTimeout() +0ms
RTC::DtlsTransport::SetTimeout() | --- DTLSv1_get_timeout() returns 1 +0ms
RTC::DtlsTransport::SetTimeout() | --- DTLSv1_get_timeout() sets dtlsTimeout to 3999ms +0ms
RTC::DtlsTransport::OnTimer() | --- OnTimer() +4s
RTC::DtlsTransport::SendPendingOutgoingDtlsData() | --- SendPendingOutgoingDTLSData() +1ms
RTC::DtlsTransport::SendPendingOutgoingDtlsData() | 67 bytes of DTLS data ready to sent to the peer +0ms
RTC::DtlsTransport::SetTimeout() | --- SetTimeout() +0ms
RTC::DtlsTransport::SetTimeout() | --- DTLSv1_get_timeout() returns 1 +0ms
RTC::DtlsTransport::SetTimeout() | --- DTLSv1_get_timeout() sets dtlsTimeout to 7999ms +0ms
RTC::DtlsTransport::OnTimer() | --- OnTimer() +8s
RTC::DtlsTransport::SendPendingOutgoingDtlsData() | --- SendPendingOutgoingDTLSData() +0ms
RTC::DtlsTransport::SendPendingOutgoingDtlsData() | 67 bytes of DTLS data ready to sent to the peer +0ms
RTC::DtlsTransport::SetTimeout() | --- SetTimeout() +1ms
RTC::DtlsTransport::SetTimeout() | --- DTLSv1_get_timeout() returns 1 +0ms
RTC::DtlsTransport::SetTimeout() | --- DTLSv1_get_timeout() sets dtlsTimeout to 15999ms +0ms
RTC::DtlsTransport::OnTimer() | --- OnTimer() +16s
RTC::DtlsTransport::SendPendingOutgoingDtlsData() | --- SendPendingOutgoingDTLSData() +0ms
RTC::DtlsTransport::SendPendingOutgoingDtlsData() | 67 bytes of DTLS data ready to sent to the peer +0ms
RTC::DtlsTransport::SetTimeout() | --- SetTimeout() +1ms
RTC::DtlsTransport::SetTimeout() | --- DTLSv1_get_timeout() returns 1 +0ms
RTC::DtlsTransport::SetTimeout() | --- DTLSv1_get_timeout() sets dtlsTimeout to 31999ms +0ms
RTC::DtlsTransport::SetTimeout() | DTLS timeout too high (31999ms), resetting DLTS +0ms
RTC::DtlsTransport::Reset() | resetting DTLS transport +0ms
RTC::DtlsTransport::OnSslInfo() | sending DTLS warning alert: close notify +31s
RTC::WebRtcTransport::OnDtlsFailed() | DTLS fails

[ibc]

Issue reported in OpenSSL project: openssl/openssl#7998

[ibc]

2.6.4 released with latest version of OpenSSL 1.1.0j 20 Nov 2018 plus commit 0b885cf that avoids the issue reported here.

We'll keep this issue open until we have a definitive explanation or solution.

[ibc]

OK, let's close it since the solution done in 0b885cf seems to work and may even make sense.

[ibc]

Confirmed that this is due to a regression in OpenSSL. Let's track it:

openssl/openssl#7998 (comment)