2

I'm trying to establish a TLS connection to a MQTT broker behind a HAProxy instance. At the end of the handshake (TLS 1.2 application data was sent), the server unexpectedly closes the connection.

I'm using self-signed certificates in form of a Keystore and a Truststore. Keystore and Truststore are tested against the server, for example with MQTTFx and with a MQTT3 Paho client.

As I have to use shared subscriptions, I decided to switch to the HiveMQ MQTT5 async client.

The following code illustrates building the client and connecting to the server.

The variable connectionProperties contains information about the broker and the keystores used.

public class MqttConnector {

    Logger logger = LoggerFactory.getLogger(MqttConnector.class);

    private ConnectionListener connectionListener;
    private Properties connectionProperties;

    private Mqtt5AsyncClient client;

    public MqttConnector() throws SSLException {
        this.connectionListener = new ConnectionListener();
        this.connectionProperties = ConnectionProperties.get();
        this.client = this.buildMqtt5AsyncClient(this.connectionProperties, this.connectionListener);
    }

    public MqttConnector(ConnectionListener connectionListener, Properties connectionProperties) throws SSLException {
        this.connectionListener = connectionListener;
        this.connectionProperties = connectionProperties;
        this.client = this.buildMqtt5AsyncClient(this.connectionProperties, this.connectionListener);
    }

    private Mqtt5AsyncClient buildMqtt5AsyncClient(
            Properties connectionProperties, 
            ConnectionListener connectionListener) throws SSLException {

        return MqttClient.builder()
                .identifier(connectionProperties.getProperty("clientId"))
                .serverHost(connectionProperties.getProperty("host"))
                .serverPort(Integer.valueOf(connectionProperties.getProperty("port")))
                .addConnectedListener(connectionListener)
                .addDisconnectedListener(connectionListener)
                .sslConfig()
                .keyManagerFactory(KeystoreUtil.keyManagerFromKeystore(
                        new File(connectionProperties.getProperty("keystore_file")), 
                        connectionProperties.getProperty("keystore_pass"), 
                        connectionProperties.getProperty("keystore_pass")))
                .trustManagerFactory(KeystoreUtil.trustManagerFromKeystore(
                        new File(connectionProperties.getProperty("truststore_file")), 
                        connectionProperties.getProperty("truststore_pass")))
                .applySslConfig()
                .automaticReconnectWithDefaultConfig()
                .useMqttVersion5()
                .buildAsync();
    }

    public void connect() {
        this.client.connect().whenComplete((connack, throwable) -> {
            if (throwable != null) {
                logger.error("connection exception", throwable);
            } else {
                logger.info(connack.toString());
            }
        });

    }

    public void disconnect() {
        if (this.client != null && this.client.getState().isConnected()) {
            this.client.disconnect();
        }
    }

This is part of the debug log (debugged with additional -Djavax.net.debug=all to see the SSL output). I removed most of the raw data and the certificate information.

At the end of the handshake the connection is closed by the server.I have no idea why this is happening with tried and tested certificates.

javax.net.ssl|DEBUG|01|main|2019-10-15 15:40:50.356 CEST|X509TrustManagerImpl.java:79|adding as trusted certificates (
  "certificate" : {
    "version"            : "v3",
    "serial number"      : "02 41 2E 94 57 70 85 FC DF CB 6E F1 24 79 E0 C3 53 2C 41 7A",
    "signature algorithm": "SHA256withRSA",
    "issuer"             : "CN=ca.dev-broker.your-server.de",
    "not before"         : "2019-07-31 16:05:54.000 CEST",
    "not  after"         : "2029-07-28 16:05:54.000 CEST",
    "subject"            : "CN=dev-broker.your-server.de",
    "subject public key" : "RSA",
    "extensions"         : [
      {
        ObjectId: 2.5.29.19 Criticality=false
        BasicConstraints:[
          CA:false
          PathLen: undefined
        ]
      },
      {
        ObjectId: 2.5.29.15 Criticality=false
        KeyUsage [
          DigitalSignature
          Non_repudiation
          Key_Encipherment
        ]
      },
      {
        ObjectId: 2.5.29.17 Criticality=false
        SubjectAlternativeName [
          DNSName: dev-broker.your-server.de
          DNSName: *.dev-broker.your-server.de
        ]
      }
    ]}
)

15:44:31.015 [main] DEBUG io.netty.util.internal.logging.InternalLoggerFactory - Using SLF4J as the default logging framework
15:44:32.601 [main] DEBUG io.netty.util.internal.PlatformDependent0 - -Dio.netty.noUnsafe: false
15:44:32.603 [main] DEBUG io.netty.util.internal.PlatformDependent0 - Java version: 11
15:44:32.651 [main] DEBUG io.netty.util.internal.PlatformDependent0 - sun.misc.Unsafe.theUnsafe: available
15:44:32.669 [main] DEBUG io.netty.util.internal.PlatformDependent0 - sun.misc.Unsafe.copyMemory: available
15:44:32.687 [main] DEBUG io.netty.util.internal.PlatformDependent0 - java.nio.Buffer.address: available
15:44:32.708 [main] DEBUG io.netty.util.internal.PlatformDependent0 - direct buffer constructor: unavailable
15:44:33.245 [main] DEBUG io.netty.util.internal.PlatformDependent0 - java.nio.Bits.unaligned: available, true
15:44:33.272 [main] DEBUG io.netty.util.internal.PlatformDependent0 - jdk.internal.misc.Unsafe.allocateUninitializedArray(int): unavailable

5:44:50.873 [epollEventLoopGroup-2-1] DEBUG io.netty.handler.ssl.JdkSslContext - Default protocols (JDK): [TLSv1.2, TLSv1.1, TLSv1] 
15:44:50.876 [epollEventLoopGroup-2-1] DEBUG io.netty.handler.ssl.JdkSslContext - Default cipher suites (JDK): [TLS_ECDHE_ECDSA_WITH_AES_256_GCM_SHA384, TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256, TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256, TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA, TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA, TLS_RSA_WITH_AES_128_GCM_SHA256, TLS_RSA_WITH_AES_128_CBC_SHA, TLS_RSA_WITH_AES_256_CBC_SHA, TLS_AES_128_GCM_SHA256, TLS_AES_256_GCM_SHA384]
javax.net.ssl|ALL|19|epollEventLoopGroup-2-1|2019-10-15 15:44:50.877 CEST|SSLContextImpl.java:115|trigger seeding of SecureRandom
javax.net.ssl|ALL|19|epollEventLoopGroup-2-1|2019-10-15 15:44:50.877 CEST|SSLContextImpl.java:119|done seeding of SecureRandom
javax.net.ssl|DEBUG|19|epollEventLoopGroup-2-1|2019-10-15 15:44:50.962 CEST|HandshakeContext.java:290|Ignore unsupported cipher suite: TLS_ECDHE_ECDSA_WITH_AES_256_GCM_SHA384 for TLS11
javax.net.ssl|DEBUG|19|epollEventLoopGroup-2-1|2019-10-15 15:44:50.963 CEST|HandshakeContext.java:290|Ignore unsupported cipher suite: TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256 for TLS11
javax.net.ssl|DEBUG|19|epollEventLoopGroup-2-1|2019-10-15 15:44:50.964 CEST|HandshakeContext.java:290|Ignore unsupported cipher suite: TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256 for TLS11
javax.net.ssl|DEBUG|19|epollEventLoopGroup-2-1|2019-10-15 15:44:50.964 CEST|HandshakeContext.java:290|Ignore unsupported cipher suite: TLS_ECDHE_ECDSA_WITH_AES_256_GCM_SHA384 for TLS10
javax.net.ssl|DEBUG|19|epollEventLoopGroup-2-1|2019-10-15 15:44:50.967 CEST|HandshakeContext.java:290|Ignore unsupported cipher suite: TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256 for TLS10
javax.net.ssl|DEBUG|19|epollEventLoopGroup-2-1|2019-10-15 15:44:50.968 CEST|HandshakeContext.java:290|Ignore unsupported cipher suite: TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256 for TLS10
javax.net.ssl|WARNING|19|epollEventLoopGroup-2-1|2019-10-15 15:44:51.002 CEST|ServerNameExtension.java:255|Unable to indicate server name
javax.net.ssl|DEBUG|19|epollEventLoopGroup-2-1|2019-10-15 15:44:51.003 CEST|SSLExtensions.java:256|Ignore, context unavailable extension: server_name
javax.net.ssl|DEBUG|19|epollEventLoopGroup-2-1|2019-10-15 15:44:51.009 CEST|SupportedGroupsExtension.java:841|Ignore inactive or disabled named group: ffdhe2048
javax.net.ssl|DEBUG|19|epollEventLoopGroup-2-1|2019-10-15 15:44:51.012 CEST|SupportedGroupsExtension.java:841|Ignore inactive or disabled named group: ffdhe3072
javax.net.ssl|DEBUG|19|epollEventLoopGroup-2-1|2019-10-15 15:44:51.013 CEST|SupportedGroupsExtension.java:841|Ignore inactive or disabled named group: ffdhe4096
javax.net.ssl|DEBUG|19|epollEventLoopGroup-2-1|2019-10-15 15:44:51.014 CEST|SupportedGroupsExtension.java:841|Ignore inactive or disabled named group: ffdhe6144
javax.net.ssl|DEBUG|19|epollEventLoopGroup-2-1|2019-10-15 15:44:51.014 CEST|SupportedGroupsExtension.java:841|Ignore inactive or disabled named group: ffdhe8192
javax.net.ssl|WARNING|19|epollEventLoopGroup-2-1|2019-10-15 15:44:51.026 CEST|SignatureScheme.java:282|Signature algorithm, ed25519, is not supported by the underlying providers
javax.net.ssl|WARNING|19|epollEventLoopGroup-2-1|2019-10-15 15:44:51.027 CEST|SignatureScheme.java:282|Signature algorithm, ed448, is not supported by the underlying providers
javax.net.ssl|ALL|19|epollEventLoopGroup-2-1|2019-10-15 15:44:51.043 CEST|SignatureScheme.java:358|Ignore disabled signature sheme: rsa_md5
javax.net.ssl|INFO|19|epollEventLoopGroup-2-1|2019-10-15 15:44:51.046 CEST|AlpnExtension.java:161|No available application protocols
javax.net.ssl|DEBUG|19|epollEventLoopGroup-2-1|2019-10-15 15:44:51.047 CEST|SSLExtensions.java:256|Ignore, context unavailable extension: application_layer_protocol_negotiation
javax.net.ssl|DEBUG|19|epollEventLoopGroup-2-1|2019-10-15 15:44:51.053 CEST|ClientHello.java:651|Produced ClientHello handshake message (
"ClientHello": {
  "client version"      : "TLSv1.2",
  "random"              : "4D 37 59 83 17 36 AD CD 4E D5 4F DB EF 60 88 66 23 B2 ED FA DC 13 81 EF 5D 19 9E DC 9E FA 41 57",
  "session id"          : "",
  "cipher suites"       : "[TLS_ECDHE_ECDSA_WITH_AES_256_GCM_SHA384(0xC02C), TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256(0xC02B), TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256(0xC02F), TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA(0xC013), TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA(0xC014), TLS_RSA_WITH_AES_128_GCM_SHA256(0x009C), TLS_RSA_WITH_AES_128_CBC_SHA(0x002F), TLS_RSA_WITH_AES_256_CBC_SHA(0x0035)]",
  "compression methods" : "00",
  "extensions"          : [

  ]
}
)
15:44:51.076 [epollEventLoopGroup-2-1] DEBUG io.netty.util.Recycler - -Dio.netty.recycler.maxCapacityPerThread: 4096
15:44:51.077 [epollEventLoopGroup-2-1] DEBUG io.netty.util.Recycler - -Dio.netty.recycler.maxSharedCapacityFactor: 2
15:44:51.078 [epollEventLoopGroup-2-1] DEBUG io.netty.util.Recycler - -Dio.netty.recycler.linkCapacity: 16
15:44:51.078 [epollEventLoopGroup-2-1] DEBUG io.netty.util.Recycler - -Dio.netty.recycler.ratio: 8
javax.net.ssl|DEBUG|19|epollEventLoopGroup-2-1|2019-10-15 15:44:51.135 CEST|SSLEngineOutputRecord.java:507|WRITE: TLS12 handshake, length = 223
javax.net.ssl|DEBUG|19|epollEventLoopGroup-2-1|2019-10-15 15:44:51.136 CEST|SSLEngineOutputRecord.java:525|Raw write (...)

javax.net.ssl|DEBUG|19|epollEventLoopGroup-2-1|2019-10-15 15:44:51.176 CEST|SSLEngineInputRecord.java:177|Raw read (...)

javax.net.ssl|DEBUG|19|epollEventLoopGroup-2-1|2019-10-15 15:44:51.177 CEST|SSLEngineInputRecord.java:214|READ: TLSv1.2 handshake, length = 93
javax.net.ssl|DEBUG|19|epollEventLoopGroup-2-1|2019-10-15 15:44:51.184 CEST|ServerHello.java:866|Consuming ServerHello handshake message (
"ServerHello": {
  "server version"      : "TLSv1.2",
  "random"              : "EC 44 2C 42 7F C7 DD 1F C5 F8 C2 E1 13 4B C1 94 71 41 AF EF 96 E1 8D F3 E8 B4 7B 11 D7 74 A1 3F",
  "session id"          : "37 23 36 B1 49 8B A1 97 C5 2C F0 3A BC 25 D4 BF 13 3D 25 35 A9 31 C0 3E AB DA CE 81 E2 39 4D FF",
  "cipher suite"        : "TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256(0xC02F)",
  "compression methods" : "00",
  "extensions"          : [
    "renegotiation_info (65,281)": {
      "renegotiated connection": [<no renegotiated connection>]
    },
    "ec_point_formats (11)": {
      "formats": [uncompressed, ansiX962_compressed_prime, ansiX962_compressed_char2]
    },
    "extended_master_secret (23)": {
      <empty>
    }
  ]
}
)
javax.net.ssl|DEBUG|19|epollEventLoopGroup-2-1|2019-10-15 15:44:51.185 CEST|SSLExtensions.java:169|Ignore unavailable extension: supported_versions
javax.net.ssl|DEBUG|19|epollEventLoopGroup-2-1|2019-10-15 15:44:51.186 CEST|ServerHello.java:962|Negotiated protocol version: TLSv1.2
javax.net.ssl|DEBUG|19|epollEventLoopGroup-2-1|2019-10-15 15:44:51.187 CEST|SSLExtensions.java:188|Consumed extension: renegotiation_info
javax.net.ssl|DEBUG|19|epollEventLoopGroup-2-1|2019-10-15 15:44:51.188 CEST|SSLExtensions.java:169|Ignore unavailable extension: server_name
javax.net.ssl|DEBUG|19|epollEventLoopGroup-2-1|2019-10-15 15:44:51.189 CEST|SSLExtensions.java:169|Ignore unavailable extension: max_fragment_length
javax.net.ssl|DEBUG|19|epollEventLoopGroup-2-1|2019-10-15 15:44:51.189 CEST|SSLExtensions.java:169|Ignore unavailable extension: status_request
javax.net.ssl|DEBUG|19|epollEventLoopGroup-2-1|2019-10-15 15:44:51.191 CEST|SSLExtensions.java:188|Consumed extension: ec_point_formats
javax.net.ssl|DEBUG|19|epollEventLoopGroup-2-1|2019-10-15 15:44:51.194 CEST|SSLExtensions.java:169|Ignore unavailable extension: status_request_v2
javax.net.ssl|DEBUG|19|epollEventLoopGroup-2-1|2019-10-15 15:44:51.194 CEST|SSLExtensions.java:188|Consumed extension: extended_master_secret
javax.net.ssl|DEBUG|19|epollEventLoopGroup-2-1|2019-10-15 15:44:51.195 CEST|SSLExtensions.java:188|Consumed extension: renegotiation_info
javax.net.ssl|ALL|19|epollEventLoopGroup-2-1|2019-10-15 15:44:51.195 CEST|SSLSessionImpl.java:209|Session initialized:  Session(1571147091195|TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256)
javax.net.ssl|DEBUG|19|epollEventLoopGroup-2-1|2019-10-15 15:44:51.196 CEST|SSLExtensions.java:203|Ignore unavailable extension: server_name
javax.net.ssl|DEBUG|19|epollEventLoopGroup-2-1|2019-10-15 15:44:51.196 CEST|SSLExtensions.java:203|Ignore unavailable extension: max_fragment_length
javax.net.ssl|DEBUG|19|epollEventLoopGroup-2-1|2019-10-15 15:44:51.196 CEST|SSLExtensions.java:203|Ignore unavailable extension: status_request
javax.net.ssl|WARNING|19|epollEventLoopGroup-2-1|2019-10-15 15:44:51.197 CEST|SSLExtensions.java:211|Ignore impact of unsupported extension: ec_point_formats
javax.net.ssl|DEBUG|19|epollEventLoopGroup-2-1|2019-10-15 15:44:51.197 CEST|SSLExtensions.java:203|Ignore unavailable extension: application_layer_protocol_negotiation
javax.net.ssl|DEBUG|19|epollEventLoopGroup-2-1|2019-10-15 15:44:51.197 CEST|SSLExtensions.java:203|Ignore unavailable extension: status_request_v2
javax.net.ssl|WARNING|19|epollEventLoopGroup-2-1|2019-10-15 15:44:51.197 CEST|SSLExtensions.java:211|Ignore impact of unsupported extension: extended_master_secret
javax.net.ssl|WARNING|19|epollEventLoopGroup-2-1|2019-10-15 15:44:51.198 CEST|SSLExtensions.java:211|Ignore impact of unsupported extension: renegotiation_info
javax.net.ssl|DEBUG|19|epollEventLoopGroup-2-1|2019-10-15 15:44:51.209 CEST|SSLEngineInputRecord.java:177|Raw read (...)

javax.net.ssl|DEBUG|19|epollEventLoopGroup-2-1|2019-10-15 15:44:51.215 CEST|SSLEngineInputRecord.java:214|READ: TLSv1.2 handshake, length = 2517
javax.net.ssl|DEBUG|19|epollEventLoopGroup-2-1|2019-10-15 15:44:51.240 CEST|CertificateMessage.java:358|Consuming server Certificate handshake message (
"Certificates": [...]

javax.net.ssl|DEBUG|19|epollEventLoopGroup-2-1|2019-10-15 15:44:51.760 CEST|X509TrustManagerImpl.java:300|Found trusted certificate (
  "certificate" : {...}
)
javax.net.ssl|DEBUG|19|epollEventLoopGroup-2-1|2019-10-15 15:44:51.766 CEST|SSLEngineInputRecord.java:177|Raw read (...)

javax.net.ssl|DEBUG|19|epollEventLoopGroup-2-1|2019-10-15 15:44:51.767 CEST|SSLEngineInputRecord.java:214|READ: TLSv1.2 handshake, length = 333
javax.net.ssl|DEBUG|19|epollEventLoopGroup-2-1|2019-10-15 15:44:51.778 CEST|ECDHServerKeyExchange.java:538|Consuming ECDH ServerKeyExchange handshake message (
"ECDH ServerKeyExchange": {
  "parameters": {
    "named group": "secp256r1"
    "ecdh public": {...},
  },
  "digital signature":  {
    "signature algorithm": "rsa_pss_rsae_sha256"
    "signature": {...},
  }
}
)
javax.net.ssl|DEBUG|19|epollEventLoopGroup-2-1|2019-10-15 15:44:51.780 CEST|SSLEngineInputRecord.java:177|Raw read (...)

javax.net.ssl|DEBUG|19|epollEventLoopGroup-2-1|2019-10-15 15:44:51.782 CEST|SSLEngineInputRecord.java:214|READ: TLSv1.2 handshake, length = 131
javax.net.ssl|DEBUG|19|epollEventLoopGroup-2-1|2019-10-15 15:44:51.788 CEST|CertificateRequest.java:651|Consuming CertificateRequest handshake message (
"CertificateRequest": {
  "certificate types": [rsa_sign, dss_sign, ecdsa_sign]
  "supported signature algorithms": [ecdsa_secp256r1_sha256, ecdsa_secp384r1_sha384, ecdsa_secp512r1_sha512, ed25519, ed448, rsa_pss_pss_sha256, rsa_pss_pss_sha384, rsa_pss_pss_sha512, rsa_pss_rsae_sha256, rsa_pss_rsae_sha384, rsa_pss_rsae_sha512, rsa_pkcs1_sha256, rsa_pkcs1_sha384, rsa_pkcs1_sha512, ecdsa_sha224, ecdsa_sha1, rsa_sha224, rsa_pkcs1_sha1, dsa_sha224, dsa_sha1, dsa_sha256, dsa_sha384, dsa_sha512]
  "certificate authorities": [CN=ca.your-server.de, CN=ca.dev-broker.your-server.de]
}
)
javax.net.ssl|DEBUG|19|epollEventLoopGroup-2-1|2019-10-15 15:44:51.812 CEST|X509KeyManagerImpl.java:389|KeyMgr: choosing key: 1 (verified: OK)
javax.net.ssl|DEBUG|19|epollEventLoopGroup-2-1|2019-10-15 15:44:52.131 CEST|SSLEngineInputRecord.java:177|Raw read (
  0000: 16 03 03 00 04 0E 00 00   00                       .........
)
javax.net.ssl|DEBUG|19|epollEventLoopGroup-2-1|2019-10-15 15:44:52.131 CEST|SSLEngineInputRecord.java:214|READ: TLSv1.2 handshake, length = 4
javax.net.ssl|DEBUG|19|epollEventLoopGroup-2-1|2019-10-15 15:44:52.132 CEST|ServerHelloDone.java:142|Consuming ServerHelloDone handshake message (
<empty>
)
javax.net.ssl|DEBUG|19|epollEventLoopGroup-2-1|2019-10-15 15:44:52.141 CEST|CertificateMessage.java:322|Produced client Certificate handshake message (
"Certificates": [
  "certificate" : {...}
]
)
javax.net.ssl|DEBUG|19|epollEventLoopGroup-2-1|2019-10-15 15:44:52.150 CEST|ECDHClientKeyExchange.java:401|Produced ECDHE ClientKeyExchange handshake message (
"ECDH ClientKeyExchange": {
  "ecdh public": {...},
}
)
javax.net.ssl|DEBUG|19|epollEventLoopGroup-2-1|2019-10-15 15:44:52.387 CEST|CertificateVerify.java:743|Produced CertificateVerify handshake message (
"CertificateVerify": {
  "signature algorithm": rsa_pss_rsae_sha256
  "signature": {...}
}
)
javax.net.ssl|DEBUG|19|epollEventLoopGroup-2-1|2019-10-15 15:44:52.418 CEST|ChangeCipherSpec.java:109|Produced ChangeCipherSpec message
javax.net.ssl|DEBUG|19|epollEventLoopGroup-2-1|2019-10-15 15:44:52.419 CEST|Finished.java:395|Produced client Finished handshake message (
"Finished": {
  "verify data": {
    ...
  }'}
)

avax.net.ssl|DEBUG|19|epollEventLoopGroup-2-1|2019-10-15 15:44:52.422 CEST|SSLEngineOutputRecord.java:507|WRITE: TLS12 handshake, length = 2855
javax.net.ssl|DEBUG|19|epollEventLoopGroup-2-1|2019-10-15 15:44:52.427 CEST|SSLEngineOutputRecord.java:525|Raw write (...)

javax.net.ssl|DEBUG|19|epollEventLoopGroup-2-1|2019-10-15 15:44:52.430 CEST|SSLEngineOutputRecord.java:507|WRITE: TLS12 change_cipher_spec, length = 1
javax.net.ssl|DEBUG|19|epollEventLoopGroup-2-1|2019-10-15 15:44:52.431 CEST|SSLEngineOutputRecord.java:525|Raw write (
  0000: 14 03 03 00 01 01                                  ......
)
javax.net.ssl|DEBUG|19|epollEventLoopGroup-2-1|2019-10-15 15:44:52.432 CEST|SSLEngineOutputRecord.java:507|WRITE: TLS12 handshake, length = 16
javax.net.ssl|DEBUG|19|epollEventLoopGroup-2-1|2019-10-15 15:44:52.483 CEST|SSLCipher.java:1727|Plaintext before ENCRYPTION (
  0000: 14 00 00 0C 91 F1 79 2C   A0 3C A8 61 58 45 99 AF  ......y,.<.aXE..
)
javax.net.ssl|DEBUG|19|epollEventLoopGroup-2-1|2019-10-15 15:44:52.487 CEST|SSLEngineOutputRecord.java:525|Raw write (
  0000: 16 03 03 00 28 00 00 00   00 00 00 00 00 09 AE 57  ....(..........W
  0010: EC 20 A9 DD 8F 44 DE 34   3D BE F8 44 F8 D9 7D F0  . ...D.4=..D....
  0020: 3F C1 62 92 97 40 2C BD   44 38 E0 8A 7E           ?.b..@,.D8...
)
javax.net.ssl|DEBUG|19|epollEventLoopGroup-2-1|2019-10-15 15:44:52.504 CEST|SSLEngineInputRecord.java:177|Raw read (
  0000: 14 03 03 00 01 01                                  ......
)
javax.net.ssl|DEBUG|19|epollEventLoopGroup-2-1|2019-10-15 15:44:52.505 CEST|SSLEngineInputRecord.java:214|READ: TLSv1.2 change_cipher_spec, length = 1
javax.net.ssl|DEBUG|19|epollEventLoopGroup-2-1|2019-10-15 15:44:52.505 CEST|ChangeCipherSpec.java:143|Consuming ChangeCipherSpec message
javax.net.ssl|DEBUG|19|epollEventLoopGroup-2-1|2019-10-15 15:44:52.509 CEST|SSLEngineInputRecord.java:177|Raw read (
  0000: 16 03 03 00 28 FF 2B 4B   EC 5F F7 5C BA 8C 2F 34  ....(.+K._.\../4
  0010: 2A C1 FE 1C 6F 92 22 BC   B2 B4 E8 93 3C F2 20 48  *...o.".....<. H
  0020: 8E FE E2 60 93 7A 3D EA   B3 FA 66 05 F2           ...`.z=...f..
)
javax.net.ssl|DEBUG|19|epollEventLoopGroup-2-1|2019-10-15 15:44:52.510 CEST|SSLEngineInputRecord.java:214|READ: TLSv1.2 handshake, length = 40
javax.net.ssl|DEBUG|19|epollEventLoopGroup-2-1|2019-10-15 15:44:52.514 CEST|SSLCipher.java:1629|Plaintext after DECRYPTION (
  0000: 14 00 00 0C AB A5 7E 92   19 0D F5 96 FA E2 D5 A4  ................
)
javax.net.ssl|DEBUG|19|epollEventLoopGroup-2-1|2019-10-15 15:44:52.547 CEST|Finished.java:532|Consuming server Finished handshake message (
"Finished": {
  "verify data": {
    0000: AB A5 7E 92 19 0D F5 96   FA E2 D5 A4 
  }'}
)
15:44:52.586 [epollEventLoopGroup-2-1] DEBUG io.netty.handler.ssl.SslHandler - [id: 0xf55e3747, L:/10.156.123.175:40054 - R:dev-broker.your-server.de/185.201.147.157:8883] HANDSHAKEN: TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256
javax.net.ssl|DEBUG|19|epollEventLoopGroup-2-1|2019-10-15 15:44:52.591 CEST|SSLEngineOutputRecord.java:267|WRITE: TLS12 application_data, length = 30
javax.net.ssl|DEBUG|19|epollEventLoopGroup-2-1|2019-10-15 15:44:52.592 CEST|SSLCipher.java:1727|Plaintext before ENCRYPTION (
  0000: 10 1C 00 04 4D 51 54 54   05 02 00 3C 00 00 0F 63  ....MQTT...<...c
  0010: 6F 6E 6E 65 63 74 69 6F   6E 2D 74 65 73 74        onnection-test
)
javax.net.ssl|DEBUG|19|epollEventLoopGroup-2-1|2019-10-15 15:44:52.595 CEST|SSLEngineOutputRecord.java:283|Raw write (
  0000: 17 03 03 00 36 00 00 00   00 00 00 00 01 F8 AA 69  ....6..........i
  0010: 92 64 CE 34 D2 5D 5A D1   4F 4D D3 34 D8 05 5A F2  .d.4.]Z.OM.4..Z.
  0020: C0 8E 63 8B 5A 51 E6 4A   4A A5 B0 E7 61 62 E5 69  ..c.ZQ.JJ...ab.i
  0030: 67 84 31 16 09 59 C5 6A   76 4C E1                 g.1..Y.jvL.
)
javax.net.ssl|DEBUG|19|epollEventLoopGroup-2-1|2019-10-15 15:44:52.596 CEST|SSLEngineInputRecord.java:177|Raw read (
  0000: 15 03 03 00 1A FF 2B 4B   EC 5F F7 5C BB 9D 2E 7B  ......+K._.\....
  0010: FC DB 74 D3 A3 62 BF 86   66 8B 9C 03 04 55 93     ..t..b..f....U.
)
javax.net.ssl|DEBUG|19|epollEventLoopGroup-2-1|2019-10-15 15:44:52.596 CEST|SSLEngineInputRecord.java:214|READ: TLSv1.2 alert, length = 26
javax.net.ssl|DEBUG|19|epollEventLoopGroup-2-1|2019-10-15 15:44:52.598 CEST|SSLCipher.java:1629|Plaintext after DECRYPTION (
  0000: 01 00                                              ..
)
javax.net.ssl|DEBUG|19|epollEventLoopGroup-2-1|2019-10-15 15:44:52.600 CEST|Alert.java:232|Received alert message (
"Alert": {
  "level"      : "warning",
  "description": "close_notify"
}
)
javax.net.ssl|WARNING|19|epollEventLoopGroup-2-1|2019-10-15 15:44:52.602 CEST|SSLEngineOutputRecord.java:168|outbound has closed, ignore outbound application data
javax.net.ssl|DEBUG|19|epollEventLoopGroup-2-1|2019-10-15 15:44:52.603 CEST|SSLEngineOutputRecord.java:507|WRITE: TLS12 alert, length = 2
javax.net.ssl|DEBUG|19|epollEventLoopGroup-2-1|2019-10-15 15:44:52.604 CEST|SSLCipher.java:1727|Plaintext before ENCRYPTION (
  0000: 01 00                                              ..
)
javax.net.ssl|DEBUG|19|epollEventLoopGroup-2-1|2019-10-15 15:44:52.609 CEST|SSLEngineOutputRecord.java:525|Raw write (
  0000: 15 03 03 00 1A 00 00 00   00 00 00 00 02 30 1D 82  .............0..
  0010: 69 FE 1A 9E BE 35 47 37   9E 67 DF 85 5A F4 E5     i....5G7.g..Z..
)
15:44:52.631 [epollEventLoopGroup-2-1] INFO  com.you.mqtt.ConnectionListener - Disconnected from MQTT broker.
15:44:52.641 [epollEventLoopGroup-2-1] ERROR com.you.mqtt.ConnectionListener - Server closed connection without DISCONNECT. Will try to reconnect.
15:44:52.666 [RxComputationThreadPool-1] ERROR com.you.mqtt.MqttConnector - connection exception
com.hivemq.client.mqtt.exceptions.ConnectionClosedException: Server closed connection without DISCONNECT.

I'm using Java 11 with the HiveMQ MQTT client version 1.1.2 (latest in maven repo).

The server is a HAProxy, the port is 8883.

I would be really thankful, if someone has a hint or a clue about what is happening here and why the client does not connect to the the MQTT broker behind the HAProxy.

HAProxy Config

The following snippet is the part of the haproxy configuration concerned with TCP connection. The configuration follows recommendations for the VerneMQ broker.

global
        daemon
        user haproxy
        group haproxy
        chroot /var/empty
        maxconn 20000
        #log gi18hd.stackhero-network.com:514 local1 debug
        log /dev/log local0 debug
        #ssl
        tune.ssl.default-dh-param 2048
        #ssl-default-bind-options no-sslv3 no-tls-tickets force-tlsv12
        #ssl-default-bind-ciphers EECDH+AESGCM:EDH+AESGCM:AES256+EECDH:AES256+EDH

defaults
        log global
        #option httplog
        option tcplog
        timeout connect 5s
        timeout client 30s
        timeout client-fin 30s
        timeout server 300s
        timeout tunnel 1h

frontend front_tcp
        mode tcp
        option clitcpka # For TCP keep-alive

        log global
        option tcplog

        bind *:8883 ssl crt-list /etc/haproxy/server-dev-test-crt-list.txt

        use_backend sub_dev-broker if { ssl_fc_sni -i dev-broker.your-server.de }

backend sub_dev-broker
        mode tcp
        option redispatch
        balance leastconn
        server manager1 10.1.2.51:1883 check fall 1
        server manager2 10.1.2.52:1883 check fall 1
        server manager3 10.1.2.53:1883 check fall 1

VerneMQ Config

Our broker is a clustered(!) VerneMQ MQTT broker (https://vernemq.com/) in a Docker Swarm. The MQTT 5 protocol is enabled via the env variable DOCKER_VERNEMQ_LISTENER__TCP__ALLOWED_PROTOCOL_VERSIONS=3,4,5. We use an internal listener on port 18883, which is mapped outside the container to 1883. Again: this setup is working with tools like MQTTFx and other Paho-based MQTT3 clients.

The corresponding docker-compose configuration is:

version: '3.7'

services:
  mqttbroker0:
    image: erlio/docker-vernemq
    networks:
      - your-backend
    environment:
      - DOCKER_VERNEMQ_SWARM=1
      - DOCKER_VERNEMQ_ALLOW_ANONYMOUS=on
      - DOCKER_VERNEMQ_LOG__CONSOLE__LEVEL=debug

  mqttbroker:
    image: erlio/docker-vernemq
    depends_on:
      - mqttbroker0
    networks:
      - your-backend
    environment:
      - DOCKER_VERNEMQ_SWARM=1
      - DOCKER_VERNEMQ_DISCOVERY_NODE=mqttbroker0
      - DOCKER_VERNEMQ_ALLOW_ANONYMOUS=on
      - DOCKER_NET_INTERFACE=eth1
      - DOCKER_VERNEMQ_LOG__CONSOLE__LEVEL=debug
      - DOCKER_VERNEMQ_LISTENER__TCP__SERVER = 0.0.0.0:18883
      - DOCKER_VERNEMQ_LISTENER__TCP__ALLOWED_PROTOCOL_VERSIONS=3,4,5
    ports:
      - "1883:18883"
    deploy:
      replicas: 2

networks:
  your-backend:
    external: true

Update: TLS handshake is ok, haproxy can't find the server

The connection is closed after the handshake between client and server. HAProxy logs 

front_tcp~ front_tcp/<NOSRV> -1/-1/965 0 SC 2/1/0/0/0 0/0

We have a condition in our haproxy configuration: use_backend sub_dev-broker if { ssl_fc_sni -i dev-broker.your-server.de }. This enables us to use only one haproxy instance and to switch between different endpoints (DEV and TEST servers in our case).

The request coming from the client after the handshake can not be routed to a backend server. HAProxy reacts with NOSRV. It seems that the request does not contain the hostname of the server, so the if-condition fails.

Update: HiveMQ Client 1.1.2 does not use SNI

The HiveMQ Client 1.1.2 does not use the Server Name Indication TLS extension, Milestone 1.1.3 does. We use the SNI information for the switch in our HAProxy configuration. As I see no workaround at the moment and this functionality is not critical in the MQTT subscriber, I will wait for the next release of the HiveMQ client.

Thank you to all participants for thoughts and hints!

MacPatric
  • 21
  • 4
  • Edit the question to include you full haproxy configuration – hardillb Oct 15 '19 at 17:14
  • Thanks for the reply. You're right; without the proxy config, nothing can be said about potential TLS problems. I added the relevant parts of the configuration to my question. – MacPatric Oct 16 '19 at 09:23
  • Also does this work if you connect directly to the broker without the proxy in the way? – hardillb Oct 16 '19 at 09:26
  • Yes, it does. The application I'm writing is a MQTT subscriber running in our backend (Docker Swarm). The subscriber will be directly talking to the broker via port 1883 without any authentication. This part of the subscriber already works. It is possible that in the future the subscriber must get MQTT messages from brokers behind a HAProxy so I want my implementation to be ready for that. – MacPatric Oct 16 '19 at 09:30
  • That's not really what I meant, but as you are doing the SSL termination in the proxy you can't properly compare the setup. Turn off the SSL termination and test if it will work if it is just load balancing/proxying – hardillb Oct 16 '19 at 09:32
  • I see. But it is actually not possible to disable auth via certificates even for a small test. I can not open a part of our backend to the public, even if it is just the DEV part on a certain port. :-) What I can do is write a test case with an MQTT 3 client to make sure the connection to the broker works in principle. I did that in the past with the Eclipse Paho lib (successfully); now I will do the same with the HiveMQ client lib. – MacPatric Oct 16 '19 at 09:47

1 Answers1

2

As I understand the provided log, there seems to be nothing wrong with the TLS handshake.

After the handshake is finished the client sends a MQTT CONNECT packet. As you are using the HiveMQ client with MQTT 5 as protocol version, this will contain a flag that MQTT 5 is expected. Now if the used broker can't handle that, it will close the connection (protocol error).

This would also explain, why you were successful in connecting

with MQTTFx and with a MQTT3 Paho.

Alternatively you could change the MQTT client creation to:

return MqttClient.builder()
            ...
            .useMqttVersion3()
            .buildAsync();

But as your original goal was to use the shared subscriptions a broker change/upgrade would still be necessary.

Could you perhaps provide more information about the used broker?

sauroter
  • 148
  • 7
  • Thank you for your reply. We are using VerneMQ as our MQTT broker. I added information regarding our configuration (MQTT5 enabled). But I will write a test with a MQTT3 client just to see if I can get a successful connection. – MacPatric Oct 16 '19 at 09:22