Error logged when server closes connection on disconnect

[jorispz]

We are using the HiveMQ client with the VerneMQ broker, using MQTT5.

Expected behavior

When disconnecting the client by calling client.disconnect(), the client disconnects without error.

Actual behavior

When disconnecting the client by calling client.disconnect(), the following error is always logged:

2020-02-20 16:43:02.548 [com.hivemq.client.mqtt-1-9] ERROR c.h.c.i.m.h.d.MqttDisconnectHandler - Exception while disconnecting.
java.io.IOException: An existing connection was forcibly closed by the remote host
	at sun.nio.ch.SocketDispatcher.read0(Native Method)
	at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:43)
	at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:223)
	at sun.nio.ch.IOUtil.read(IOUtil.java:192)
	at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:380)
	at io.netty.buffer.PooledByteBuf.setBytes(PooledByteBuf.java:253)
	at io.netty.buffer.AbstractByteBuf.writeBytes(AbstractByteBuf.java:1133)
	at io.netty.channel.socket.nio.NioSocketChannel.doReadBytes(NioSocketChannel.java:350)
	at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:148)
	at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:714)
	at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:650)
	at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:576)
	at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:493)
	at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989)
	at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
	at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
	at java.lang.Thread.run(Thread.java:748)

My uneducated guess is that the broker closes the TCP session immediately upon receiving the DISCONNECT message (as it should according to the spec), which leads to the IOException on the client. The code that logs the error is this (MQTTDisconnectHandler line 112:

    @Override
    public void exceptionCaught(final @NotNull ChannelHandlerContext ctx, final @NotNull Throwable cause) {
        if (state == null) {
            state = State.CLOSED;
            fireDisconnectEvent(ctx.channel(), new ConnectionClosedException(cause), MqttDisconnectSource.CLIENT);
        } else {
            LOGGER.error("Exception while disconnecting.", cause);
        }
    }

However, the state after the call to disconnect() is CLOSED, which isn't checked for, but in which case this IOException is probably to be expected and shouldn't be logged? (Especially not on ERROR level).

To Reproduce

Connect with a VerneMQ broker over MQTT5, then call disconnect on the client

Details

• Affected HiveMQ MQTT Client version(s): 1.1.3
• Used JVM version: 1.8

[SgtSilvio]

Hi @jorispz
We have not seen this log when disconnecting normally (we did not test with VerneMQ, just HiveMQ and mosquitto).
HiveMQ closes the TCP socket upon receiving the DISCONNECT message gracefully by sending a TCP packet with the FIN/ACK flags. It seems that your server sent a RST flag as the log message states was forcibly closed.
It would be very helpful, if you could provide a Wireshark trace that shows the packet exchange when disconnecting the client.
You are definitely right about the log level, should at most be a warning.

[jorispz]

I think you are right about the RST, I made a Wireshark trace of the client connecting and immediately disconnecting, which lead to the following trace:

      1 0.000000       192.168.0.1     10.0.0.1        TCP      66     11310 → 1883 [SYN] Seq=0 Win=64240 Len=0 MSS=1460 WS=256 SACK_PERM=1
      2 0.038508       10.0.0.1        192.168.0.1     TCP      66     1883 → 11310 [SYN, ACK] Seq=0 Ack=1 Win=26883 Len=0 MSS=1420 SACK_PERM=1 WS=128
      3 0.038739       192.168.0.1     10.0.0.1        TCP      54     11310 → 1883 [ACK] Seq=1 Ack=1 Win=131840 Len=0
      4 0.068941       192.168.0.1     10.0.0.1        MQTT     74     Connect Command
      5 0.105332       10.0.0.1        192.168.0.1     TCP      60     1883 → 11310 [ACK] Seq=1 Ack=21 Win=27008 Len=0
      6 0.105332       10.0.0.1        192.168.0.1     MQTT     60     Connect Ack
      7 0.152824       192.168.0.1     10.0.0.1        TCP      54     11310 → 1883 [ACK] Seq=21 Ack=6 Win=131840 Len=0
      8 0.206235       192.168.0.1     10.0.0.1        MQTT     56     Disconnect Req
      9 0.208518       192.168.0.1     10.0.0.1        TCP      54     11310 → 1883 [FIN, ACK] Seq=23 Ack=6 Win=131840 Len=0
     10 0.240008       10.0.0.1        192.168.0.1     TCP      60     1883 → 11310 [RST, ACK] Seq=6 Ack=23 Win=27008 Len=0
     11 0.246503       10.0.0.1        192.168.0.1     TCP      60     1883 → 11310 [RST] Seq=6 Win=0 Len=0

Would you say this is (apart from the log level) a mistake on the VerneMQ side?

[jorispz]

I am a bit confused about the FIN ACK on line 9, shouldn't that be a plain FIN?

Edit: ah, wait, that ACK is (re-)acknowledging the earlier Connect Ack from line 6, never mind

[SgtSilvio]

The RST flag is normally not used when "closing" the connection but only when data is sent on half-open TCP connections, so you should report this to VerneMQ.
On the client side we should probably either ignore the IOException in this case or deliver it to the caller of disconnect.

[jorispz]

OK, as discussed with the VerneMQ maintainers in the issue linked above, forcefully closing the connection with a RST packet is indeed the default behaviour of VerneMQ by design, although it can be changed by configuration.

Personally, I would suggest that the HiveMQ client would, in this specific scenario, swallow the exception and log it on DEBUG if at all, as it is I think not an issue in practice.

[SgtSilvio]

What we will change on the client side: we will ignore all IOExceptions in the MqttDisconnectHandler and change the log level to warn for other types of exceptions (which should never occur).