Rabbitmq-server: TLS errors can prevent a connection from being cleaned up

[dimas]

Thread RabbitMQ Mailing List: https://groups.google.com/forum/#!topic/rabbitmq-users/aY_K2jEnAZ0

Short version: sometimes when TLS error happens, RabbitMQ broker kills the connection so it disappears from the OS (tested with netstat) but still rabbitmqctl list_connections keep showing it forever. This is despite the fact that 10 second heartbeat was configured on the client and RabbitMQ should have closed these "dead" connection for inactivity even if it missed the original closure event from runtime.

Long version

• RabbitMQ version - 3.6.14
• Erlang version - 20.1.7
• OS - Ubuntu 16.04 and 14.04

Clean RabbitMQ installation on a clean Amazon EC2 machine running Ubuntu 16.04.
The https://github.com/dimas/rabbitmq-broker-tls-issue-1474 repository contains test client as well as step-by-step instruction how rabbit was set up. (There is nothing fancy but ability to just copy&paste commands makes it easier to reproduce).

Initial state:

$ netstat -nat | grep :5671
tcp6       0      0 :::5671                 :::*                    LISTEN     
$ sudo rabbitmqctl list_connections pid peer_host peer_port state channels protocol auth_mechanism timeout frame_max channel_max recv_oct recv_cnt send_oct send_cnt send_pend connected_at

Freshly started broker, no connections.
Run the test

$ java -jar target/rabbitmq-broker-tls-issue-1474-0.1-shaded.jar
connection = amqp://[email protected]:5671/
Sleeping for 5 sec
...

the test connects, pauses for 5 seconds and then it will kill TLS connection by injecting garbage into TLS raw byte stream. During that 5 seconds delay from another terminal session:

$ netstat -nat | grep :5671
tcp6       0      0 :::5671                 :::*                    LISTEN     
tcp6       0      0 127.0.0.1:59998         127.0.0.1:5671          ESTABLISHED
tcp6       0      0 127.0.0.1:5671          127.0.0.1:59998         ESTABLISHED

$ sudo rabbitmqctl list_connections pid peer_host peer_port state channels protocol auth_mechanism timeout frame_max channel_max recv_oct recv_cnt send_oct send_cnt send_pend connected_at
Listing connections
<[email protected]>    127.0.0.1   59998   running 0   {0,9,1} PLAIN   10  131072  0   1159    8   2079    5   0   1515716359917

So netstat sees that connection as well as rabbitmqctl.
After 5 seconds test client prints exception and quits

$ netstat -nat | grep :5671
tcp6       0      0 :::5671                 :::*                    LISTEN     

$ sudo rabbitmqctl list_connections pid peer_host peer_port state channels protocol auth_mechanism timeout frame_max channel_max recv_oct recv_cnt send_oct send_cnt send_pend connected_at
Listing connections
<[email protected]>    127.0.0.1   59998   running 0   {0,9,1} PLAIN   10  131072  0   0   0   0   0   0   1515716359917

The connection has gone from OS view (netstat) but still reported by the broker although all stats were zeroed out. Note the 10 value there - it is the timeout. It matches the heartbeat requested by the client so I assume it is the heartbeat.

Expected behaviour - the connection should disappear from the broker at the same time it disappears from netstat.

The https://github.com/dimas/rabbitmq-broker-tls-issue-1474 repository has a buildable Maven project but for the record below is the Java source of the client used:

import com.rabbitmq.client.Connection;
import com.rabbitmq.client.ConnectionFactory;
import com.rabbitmq.client.DefaultSaslConfig;
import com.rabbitmq.client.impl.SocketFrameHandler;
import sun.security.ssl.SSLSocketImpl;

import javax.net.ssl.*;
import java.io.IOException;
import java.io.OutputStream;
import java.lang.reflect.Field;
import java.security.*;
import java.security.cert.CertificateException;
import java.security.cert.X509Certificate;

public class Test {

    private static Object getField(final Object target, final String name) {
        try {
            final Field field = target.getClass().getDeclaredField(name);
            field.setAccessible(true);
            return field.get(target);
        } catch (Exception e) {
            throw new RuntimeException("Failed to get field '" + name + "' on " + target);
        }
    }

    public static class TrustEverythingTrustManager implements X509TrustManager {
        @Override
        public java.security.cert.X509Certificate[] getAcceptedIssuers() {
            return new X509Certificate[0];
        }

        @Override
        public void checkClientTrusted(final java.security.cert.X509Certificate[] certs, final String authType) {
        }

        @Override
        public void checkServerTrusted(final java.security.cert.X509Certificate[] certs, final String authType) {
        }
    }

    static SSLContext createSslContext()
            throws UnrecoverableKeyException, NoSuchAlgorithmException,
            KeyStoreException, IOException, CertificateException, KeyManagementException, NoSuchProviderException {

        final KeyStore keystore = KeyStore.getInstance(KeyStore.getDefaultType());
        keystore.load(null, null);

        final KeyManagerFactory keyManagerFactory = KeyManagerFactory.getInstance(
                KeyManagerFactory.getDefaultAlgorithm());
        keyManagerFactory.init(keystore, "".toCharArray());

        final SSLContext sslContext = SSLContext.getInstance("TLS");

        final String defaultAlgorithm = TrustManagerFactory.getDefaultAlgorithm();
        final TrustManagerFactory trustManagerFactory = TrustManagerFactory.getInstance(defaultAlgorithm);
        trustManagerFactory.init(keystore);

        sslContext.init(keyManagerFactory.getKeyManagers(),
                new TrustManager[]{new TrustEverythingTrustManager()},
                null);

        return sslContext;
    }

    public static void main(String[] args) {

        try {
            final ConnectionFactory factory = new ConnectionFactory();
            factory.setHost(args[0]);
            factory.useSslProtocol(createSslContext());
            factory.setSaslConfig(DefaultSaslConfig.PLAIN);
            factory.setRequestedHeartbeat(10);
            factory.setAutomaticRecoveryEnabled(false);

            final Connection connection = factory.newConnection();

            System.out.println("connection = " + connection);

            // Get actual TCP socket raw output stream
            final SocketFrameHandler _frameHandler = (SocketFrameHandler) getField(connection, "_frameHandler");
            final SSLSocketImpl _socket = (SSLSocketImpl) getField(_frameHandler, "_socket");
            final OutputStream sockOutput = (OutputStream) getField(_socket, "sockOutput");

            System.out.println("Sleeping for 5 sec");
            Thread.sleep(5000);

            sockOutput.flush();
            // record type = 0x17 - APPLICATION_DATA
            // version = 0x303 - TLS 1.2
            // length = 0x0002
            // then two zero bytes of "payload"
            sockOutput.write(new byte[] {0x17, 0x03, 0x03, 0x00, 0x02, 0x00, 0x00});
            sockOutput.flush();

            System.out.println("Rubbish sent");

            System.out.println("Finished");

        } catch (Exception e) {
            e.printStackTrace();
        }
    }
}

[dimas]

One thing worth mentioning is that in my previous tests I used to see errors like

2018-01-04 00:12:11.694 [error] <0.905.2530> SSL: {connection,{alert,2,20,{"ssl_cipher.erl",276},decryption_failed}}: ssl_connection.erl:861:Fatal error: unexpected message

(RabbitMQ 3.6.12, Erlang 19.6.3)
or

2018-01-04 00:00:33.118 [info] <0.545.537> TLS server: In state {connection,
                         {alert,2,20,
                             {"ssl_cipher.erl",276},
                             undefined,decryption_failed}} at ssl_connection.erl:848 generated SERVER ALERT: Fatal - Unexpected Message

(RabbitMQ 3.6.14, Erlang 20.1.7)
in rabbit logs. I do not get these in my test described in this ticket.

My assumption is that it is because I did not configure lager as it is configured on the live servers. If it is important, I can update rabbitmq.config for that.

[dumbbell]

Hi @dimas!

First, thank you for providing the Java test client, it greatly helped to reproduce the problem.

When the SSL error happens, the Erlang ssl library returns the error handshake_timeout to RabbitMQ. Normally, this causes RabbitMQ to terminate the connection at its level, except after the connection.open AMQP frame was received, where the error is ignored:
https://github.com/rabbitmq/rabbitmq-server/blob/master/src/rabbit_reader.erl#L574-L576

I don't know the background of this special case, therefore I'm digging into the history of this file, as well as our legacy internal Bugzilla. I'll keep you posted.

[dumbbell]

Hmm, in fact no, ignore my comment above: the handshake_timeout message is an internal one, not something from ssl. It just happened that this internal message is sent after 5 seconds as well.

[dumbbell]

Different versions of Erlang don't behave the same:

• With Erlang 17.5.6.9, the ssl library logs an error and returns {error,{tls_alert,"bad record mac"}} to RabbitMQ:

  =ERROR REPORT==== 6-Feb-2018::11:19:09 ===
  SSL: connection: ssl_cipher.erl:216:Fatal error: bad record mac
  
  =ERROR REPORT==== 6-Feb-2018::11:19:09 ===
  mainloop -> Recv = {error,{tls_alert,"bad record mac"}}
  
  =ERROR REPORT==== 6-Feb-2018::11:19:09 ===
  closing AMQP connection <0.318.0> (127.0.0.1:44760 -> 127.0.0.1:5671):
  {inet_error,{tls_alert,"bad record mac"}}
  

• With Erlang 18.3.4.7, the behavior is the same:

  =ERROR REPORT==== 6-Feb-2018::11:20:40 ===
  SSL: connection: ssl_cipher.erl:301:Fatal error: bad record mac
  
  =ERROR REPORT==== 6-Feb-2018::11:20:40 ===
  mainloop -> Recv = {error,{tls_alert,"bad record mac"}}
  
  =ERROR REPORT==== 6-Feb-2018::11:20:40 ===
  closing AMQP connection <0.327.0> (127.0.0.1:44796 -> 127.0.0.1:5671):
  {inet_error,{tls_alert,"bad record mac"}}
  

• With Erlang 19.3.6.5, ssl logs an error but doesn't return anything to RabbitMQ which sits indefinitely, waiting for something from the ssl library:

  =ERROR REPORT==== 6-Feb-2018::11:21:12 ===
  mainloop -> rabbit_net:recv...
  
  =ERROR REPORT==== 6-Feb-2018::11:21:12 ===
  SSL: {connection,{alert,2,20,{"ssl_cipher.erl",304},decryption_failed}}: ssl_connection.erl:861:Fatal error: unexpected message
  

• With Erlang 20.2.2, ssl doesn't log anything and never returns to RabbitMQ:

  =ERROR REPORT==== 6-Feb-2018::11:22:12 ===
  mainloop -> rabbit_net:recv...
  

This looks like a regression in Erlang's ssl library. I will continue to investigate.

[dumbbell]

I reported the issue upstream: https://bugs.erlang.org/browse/ERL-562

I also prepared a patch: erlang/otp#1709

[dimas]

That is just great you managed to find out what is going on. Thanks very much, @dumbbell !

[michaelklishin]

@dimas thank you for providing a reliable way to reproduce.

[dimas]

By the way, if Erlang does not pass RabbitMQ some alert, does it also explains why RabbitMQ was not destroying that connection for the lack of heartbeats? (The connection was configured with 30 sec heartbeat but was listed by rabbitmqctl list_connections forever even after SSL error).
Cheers

[michaelklishin]

We don't know but if the runtime doesn't notify RabbitMQ connections of socket events, it breaks the connection state machine.

[dumbbell]

The patch was merged \o/ The ticket says "Resolved in 20.3". I will ask if they plan to backport it to previous releases.

[michaelklishin]

Closing because https://bugs.erlang.org/browse/ERL-562 is now resolved. We'll add more details about any possible backports here.

[florianajir]

I have this error message when I try to connect my client to server with ssl; below the command I run (from the doc):
openssl s_client -connect rabbitmq.domain.com:5671 -ssl3

Log:
TLS server: In state hello at tls_handshake.erl:213 generated SERVER ALERT: Fatal - Protocol Version

erlang v21.0
RabbitMQ v3.7.7

[michaelklishin]

@florianajir this is not a support forum.

The message means that the client (s_client) and the node cannot agree on a TLS protocol version and it makes sense: you passed -ssl3 and SSLv3 connections are refused by default because of known vulnerabilities.

Enabling SSLv3 is highly discouraged.