mqtts backup fails with MD5 mismatch

[mflamm]

Describe the bug

Hi there,
I'm trying to backup my tasmota configuration, running on a NOUS A1T

To Reproduce

Steps to reproduce the behavior:

1. Program parameter:

decode-config.py -s mqtts://<mqtt_user>:<mqtt_pw>@<xyz>.s1.eu.hivemq.cloud:8883 --fulltopic tele/my_topic --backup-file MyBackup.json

Note: User, password and the actual hostname of the mqtt broker are obscured...

2. Result:

INFO: Load data by mqtt using 'mqtts://mqtt_user:mqtt_pw@<xyz>.s1.eu.hivemq.cloud'
/root/decode-config/./decode-config.py:4389: DeprecationWarning: Callback API version 1 is deprecated, update to latest version
  client = mqtt.Client()
ERROR 10 (@4448): Error during MQTT data processing: MD5 mismatch
Premature exit - #10 Download error

Expected behavior

I'm expecting a file called MyBackup.json to be created in my current directory

Version Information

>>> decode-config.py v14.1.0.3 [50d9a81] by Norbert Richter nr@prsolution.eu

Script:   decode-config.py
Version:  14.1.0.3 [50d9a81]
Python:   3.11.2
Platform: Linux-6.6.31+rpt-rpi-v6-armv6l-with-glibc2.36 - armv6l
OS:       Linux 6.6.31+rpt-rpi-v6 #1 Raspbian 1:6.6.31-1+rpt1 (2024-05-29)
Time:     2024-07-18 15:04:42 <<<

System' information of your Tasmota data

{
    "bootcount": 25,
    "bootcount_reset_time": 1718539168,
    "cfg_crc": "0x81c1",
    "cfg_crc32": "0xd8ab6f66",
    "cfg_holder": 4617,
    "cfg_size": 4096,
    "cfg_timestamp": 1721253600,
    "header": {
        "data": {
            "crc": "0x27ad",
            "crc32": "0xd8ab6f66",
            "hardware": "ESP82",
            "size": 4096,
            "version": {
                "id": "0xe010000",
                "name": "14.1.0"
            }
        },
        "env": {
            "platform": "Linux-5.15.153.1-microsoft-standard-WSL2-x86_64-with-glibc2.31",
            "python": "3.11.5",
            "script": "decode-config.py v14.1.0.0 [dcd18e5]",
            "system": "Linux x86_64 5.15.153.1-microsoft-standard-WSL2 #1 SMP Fri Mar 29 23:14:13 UTC 2024"
        },
        "template": {
            "crc": "0x81c1",
            "crc32": "0xd8ab6f66",
            "size": 4096,
            "version": {
                "id": "0xe010000",
                "name": "14.1.0"
            }
        },
        "timestamp": "2024-07-17 22:00:00"
    },
    "version": "0xe010000"
}

Additional context

[curzon01]

what's your installed paho-mqtt version

python -m pip show paho-mqtt ?

[mflamm]

Thanks for the quick reply...

Name: paho-mqtt
Version: 2.1.0
Summary: MQTT version 5.0/3.1.1 client class
Home-page:
Author:
Author-email: Roger Light <roger@atchoo.org>
License: EPL-2.0 OR BSD-3-Clause
Location: /root/decode-config/.venv/lib/python3.11/site-packages
Requires:
Required-by:

[curzon01]

MQTT interactions are somewhat time-critical.
Pls test the latest version. If the error still occurs, increase MQTT_DELAY in line 198 by 0.05 steps. If that fixes it, I'll have to think of something else.

[curzon01]

Should now work without delays, give it a try...

[mflamm]

Thank you for your help.
I tried the latest decode-config including your changes. Unfortunately I'm getting the same error message

INFO: Load data by mqtt using 'mqtts://mqtt_user:mqtt_pw@<xyz>.s1.eu.hivemq.cloud:8883'
/root/decode-config/./decode-config.py:4389: DeprecationWarning: Callback API version 1 is deprecated, update to latest version
  client = mqtt.Client()
ERROR 10 (@4448): Error during MQTT data processing: MD5 mismatch
Premature exit - #10 Download error

[curzon01]

damn, I had this error once in the past too. I have a suspicion, but I can't reproduce the issue at the moment.

Want to ask you: Can you pls test the previous commit 9ed8dff and increase MQTT_DELAY as described above if necessary? That would help to better understand the error.

[mflamm]

I tested the MQTT_DELAY in 0.05 steps till 0.7 without any success :(

(.venv) root@raspberrypi:~/decode-config# git status
HEAD losgelöst bei 9ed8dff
Änderungen, die nicht zum Commit vorgemerkt sind:
  (benutzen Sie "git add <Datei>...", um die Änderungen zum Commit vorzumerken)
  (benutzen Sie "git restore <Datei>...", um die Änderungen im Arbeitsverzeichnis zu verwerfen)
        geändert:       decode-config.py

keine Änderungen zum Commit vorgemerkt (benutzen Sie "git add" und/oder "git commit -a")
(.venv) root@raspberrypi:~/decode-config# ./decode-config.py -s mqtts://mqtt_user:mqtt_pw@<xyz>.eu.hivemq.cloud --fulltopic tele/mytopic --backup-file Config.json
INFO: Load data by mqtt using 'mqtts://mqtt_user:mqtt_pw@<xyz>.s1.eu.hivemq.cloud'
/root/decode-config/./decode-config.py:4390: DeprecationWarning: Callback API version 1 is deprecated, update to latest version
  client = mqtt.Client()
ERROR 10 (@4449): Error during MQTT data processing: MD5 mismatch
Premature exit - #10 Download error

[curzon01]

ok, will try to reproduce the issue using a hivemq account... (could take a couple of days, pls be patient)

[curzon01]

Sorry for delayed response.
Was not able to reproduce the issue with hivemq so I add some debug output.

pls could you test commit 3aac04f with additonal --debug parm:

./decode-config.py -s mqtts://mqtt_user:mqtt_pw@<xyz>.eu.hivemq.cloud --fulltopic tele/mytopic --backup-file Config.json --debug

[mflamm]

Hello,
interestingly enough, I only got the error once (unfortunately without debug enabled), and it worked the at least 10 times that I tried it again in order to reproduce it and to produce debug logs for you.

This is the output with a few seconds in between the executions using commit 3aac04f:

(.venv) root@raspberrypi:~/decode-config# ./decode-config.py -s mqtts://mqtt_user:mqtt_pw@<xyz>.s1.eu.hivemq.cloud --fulltopic tele/b4e8c22a-b
9d9-4a9c-9b0b-bab54686747c --backup-file Config.json.json
INFO: Load data by mqtt using 'mqtts://mqtt_user:mqtt_pw@<xyz>.s1.eu.hivemq.cloud'
/root/decode-config/./decode-config.py:4373: DeprecationWarning: Callback API version 1 is deprecated, update to latest version
  client = mqtt.Client()
ERROR 10 (@4432): Error during MQTT data processing: MD5 mismatch
Premature exit - #10 Download error
(.venv) root@raspberrypi:~/decode-config# ./decode-config.py -s mqtts://mqtt_user:mqtt_pw@<xyz>.s1.eu.hivemq.cloud --fulltopic tele/mytopic --backup-file Config.json.json
INFO: Load data by mqtt using 'mqtts://mqtt_user:mqtt_pw@<xyz>.s1.eu.hivemq.cloud'
/root/decode-config/./decode-config.py:4373: DeprecationWarning: Callback API version 1 is deprecated, update to latest version
  client = mqtt.Client()
INFO: Backup successful to './Config.json.json' (JSON format)

I would expect to see a documented fix here: https://www.hivemq.com/changelog/whats-new-in-hivemq-4-31/. However, nothing mentioned fits the problem I believe.

Status:
I can not reproduce the issue anymore. Even with your current master state (without mqtt delays) everything works as expected.
Anyway your debug feature seems to be useful for other problems in the future, maybe that's worth merging.

Thank you.

[curzon01]

I expected something like this.

The cause of the issue is probably a timing problem. In this case the MQTT messages do not arrive in the order Theo intended and I wanted to make it easy for myself with the debug output 😁 - now I have to have a look at the logic using my brain 😢

But the suggestion is good, I'll merge that