tedge mqtt cli commands do not disconnect cleanly from MQTT broker

reubenmiller commented 3 weeks ago

Describe the bug

When the local mosquitto MQTT broker instance is configured to use certificates, then publishing an MQTT message via tedge mqtt pub, an OpenSSL log error is visible in the mosquitto logs (related to the publishing of the message), below shows an example of this error:

Jun 05 14:56:19 fe9669c87b15 mosquitto[382]: 1717599379: OpenSSL Error[0]: error:0A000126:SSL routines::unexpected eof while reading

Publishing the same message with mosquitto_sub does not result in an OpenSSL error (see the "additional context" section for an example).

The logs related to the entire MQTT publish call is shown below (including the OpenSSL error).

tedge mqtt pub foo bar

Jun 05 14:56:19 fe9669c87b15 mosquitto[382]: 1717599379: New connection from 127.0.0.1:45954 on port 8883.
Jun 05 14:56:19 fe9669c87b15 mosquitto[382]: 1717599379: New client connected from 127.0.0.1:45954 as tedge-pub-1335 (p2, c1, k60).
Jun 05 14:56:19 fe9669c87b15 mosquitto[382]: 1717599379: No will message specified.
Jun 05 14:56:19 fe9669c87b15 mosquitto[382]: 1717599379: Sending CONNACK to tedge-pub-1335 (0, 0)
Jun 05 14:56:19 fe9669c87b15 mosquitto[382]: 1717599379: Received PUBLISH from tedge-pub-1335 (d0, q0, r0, m0, 'foo', ... (3 bytes))
Jun 05 14:56:19 fe9669c87b15 mosquitto[382]: 1717599379: Sending PUBLISH to auto-3AC5450B-1A23-EAFA-561A-34EBB76A5A49 (d0, q0, r0, m0, 'foo', ... (3 bytes))
Jun 05 14:56:19 fe9669c87b15 mosquitto[382]: 1717599379: OpenSSL Error[0]: error:0A000126:SSL routines::unexpected eof while reading
Jun 05 14:56:19 fe9669c87b15 mosquitto[382]: 1717599379: Client tedge-pub-1335 closed its connection.

Most likely the MQTT connection is not being correctly stopped, and instead just being abruptly terminated without sending an MQTT disconnect message.

The main motivation to addressing this issue is to reduce the "noise" in the logs, otherwise the user thinks there is something wrong, and it can mask other issues.

To Reproduce

This assumes that you have configured mosquitto to write its logs to journald, however you can of course use You can also use the file based logging option for mosquitto,

Configure the mosquitto instance to use certificates

For example if you have set everything up correctly, then your tedge config list should look something like this (exact paths might be different though, depending on how you set it up)

# tedge config list | grep mqtt.client
mqtt.client.host=localhost
mqtt.client.port=8883
mqtt.client.auth.ca_file=/etc/mosquitto/ca_certificates/ca.crt
mqtt.client.auth.cert_file=/setup/client.crt
mqtt.client.auth.key_file=/setup/client.key

Publish any message
```
tedge mqtt pub foo bar
```
Inspect the mosquitto logs

If you've configured mosquitto to log to syslog/journald, then check the output
```
journalctl -fu mosquitto -n 100
```

Expected behavior

The tedge mqtt broker should cleanly disconnect from the local MQTT broker by sending a DISCONNECT message.

For example the following commands should send

tedge mqtt pub - a DISCONNECT message should be sent after publishing the message
tedge mqtt sub - a DISCONNECT message should be sent when the process is exiting (e.g. a signal handler will have to be used to gracefully disconnect on SIGINT, SIGQUIT, SIGTERM etc.)

Screenshots

Environment (please complete the following information):

Property	Value
OS [incl. version]	`Debian GNU/Linux 12 (bookworm)`
Hardware [incl. revision]	`unknown`
System-Architecture	`Linux fe9669c87b15 6.5.0-35-generic #35-Ubuntu SMP PREEMPT_DYNAMIC Sat Apr 27 00:18:38 UTC 2024 aarch64 GNU/Linux`
thin-edge.io version	`tedge 1.1.2~65+g81eb5d0`

Additional context

mosquitto_pub example

Publishing the same MQTT message using mosquitto_sub does not result in any OpenSSL error.

mosquitto_pub \
    -h "$(tedge config get mqtt.client.host)" \
    -p "$(tedge config get mqtt.client.port)" \
    --cafile "$(tedge config get mqtt.client.auth.ca_file)" \
    --key "$(tedge config get mqtt.client.auth.key_file)" \
    --cert "$(tedge config get mqtt.client.auth.cert_file)" \
    -t foo \
    -m bar

Jun 05 14:55:38 fe9669c87b15 mosquitto[382]: 1717599338: New connection from 127.0.0.1:42596 on port 8883.
Jun 05 14:55:38 fe9669c87b15 mosquitto[382]: 1717599338: New client connected from 127.0.0.1:42596 as auto-CBDEDA9D-0FD8-2810-4173-76A9746040C6 (p2, c1, k60).
Jun 05 14:55:38 fe9669c87b15 mosquitto[382]: 1717599338: No will message specified.
Jun 05 14:55:38 fe9669c87b15 mosquitto[382]: 1717599338: Sending CONNACK to auto-CBDEDA9D-0FD8-2810-4173-76A9746040C6 (0, 0)
Jun 05 14:55:38 fe9669c87b15 mosquitto[382]: 1717599338: Received PUBLISH from auto-CBDEDA9D-0FD8-2810-4173-76A9746040C6 (d0, q0, r0, m0, 'foo', ... (3 bytes))
Jun 05 14:55:38 fe9669c87b15 mosquitto[382]: 1717599338: Sending PUBLISH to auto-3AC5450B-1A23-EAFA-561A-34EBB76A5A49 (d0, q0, r0, m0, 'foo', ... (3 bytes))
Jun 05 14:55:38 fe9669c87b15 mosquitto[382]: 1717599338: Received DISCONNECT from auto-CBDEDA9D-0FD8-2810-4173-76A9746040C6
Jun 05 14:55:38 fe9669c87b15 mosquitto[382]: 1717599338: Client auto-CBDEDA9D-0FD8-2810-4173-76A9746040C6 disconnected.

reubenmiller commented 3 weeks ago

Looking at the core/tedge/src/cli/mqtt/publish.rs, it looks like disconnect is being called, however the message is not actually sent (possibly because the event loop is not running as the .iter() has already finished).

gligorisaev commented 1 week ago

Tested with:

1.1.1-113-g82732a9e21

bug is not reproducable.

Created test in the PR: https://github.com/thin-edge/thin-edge.io/pull/2944

thin-edge / thin-edge.io

tedge mqtt cli commands do not disconnect cleanly from MQTT broker #2922