peterhinch / micropython-mqtt

A 'resilient' asynchronous MQTT driver. Recovers from WiFi and broker outages.
MIT License
549 stars 116 forks source link

° sign breaks MQTT publishing & causes weird behaviour #115

Closed Deishelon closed 12 months ago

Deishelon commented 12 months ago

Hi,

I found pretty odd bug while developing a temperature sensor for home use using Pico W and this library (mqqt_as.py)

Encoding ° sign in the JSON payload - the receiving side (of this mqtt topic) will get malformed json (tried mosquitto_sub and mqtt explorer, however if I print the json that PICO is sending - it looks sane. Moreover, when encoding ° sign, after 2nd transition to MQTT, mqtt_as will trigger some kinda wifi integrity check ? (will circle back to this point in the logs below).

I've tried this on PicoW running micropython running the latest firmware, as well as a bit older one (v1.19). FW version: rp2-pico-w-20230426-v1.20.0.uf2

Also, note, I've tried with multiple variations of ° sign encoding. \u00b0 , \u2103 , °C, °, °F - Any of these combinations will cause the issue.

Minimal reproducible code snippet:

from mqtt_as import MQTTClient, config
import uasyncio as asyncio

import wifi_config
import mqtt_config
import json

# Local configuration
config['ssid'] = wifi_config.HOME_WIFI_SSID
config['wifi_pw'] = wifi_config.HOME_WIFI_PWD
config['server'] = mqtt_config.MQTT_SERVER_HOST_NAME

async def messages(client):  # Respond to incoming messages
    async for topic, msg, retained in client.queue:
        print((topic, msg, retained))

async def up(client):  # Respond to connectivity being (re)established
    while True:
        await client.up.wait()  # Wait on an Event
        client.up.clear()
        await client.subscribe('foo_topic', 1)  # renew subscriptions

async def main(client):
    await client.connect()
    for coroutine in (up, messages):
        asyncio.create_task(coroutine(client))
    n = 0
    while True:
        await asyncio.sleep(5)
        json_text_to_send = json.dumps({
            "unit_of_meas": "\u00b0"
        })
        print('publish', json_text_to_send)
        await client.publish("bug_showcase",json_text_to_send, qos = 1)
        n += 1

config["queue_len"] = 1  # Use event interface with default queue size
MQTTClient.DEBUG = True  # Optional: print diagnostic messages
client = MQTTClient(config)
try:
    asyncio.run(main(client))
finally:
    client.close()  # Prevent LmacRxBlk:1 errors

Logs

Without ° in payload (sanity check)

Logs from PicoW

MPY: soft reboot
Checking WiFi integrity.
Got reliable connection
Connecting to broker.
Connected to broker.
publish {"obj_id": "id_1", "stat_t": "test/bug", "exp_aft": 100, "dev_cla": "temperature", "uniq_id": "id_1", "state_class": "measurement"}
publish {"obj_id": "id_1", "stat_t": "test/bug", "exp_aft": 100, "dev_cla": "temperature", "uniq_id": "id_1", "state_class": "measurement"}
publish {"obj_id": "id_1", "stat_t": "test/bug", "exp_aft": 100, "dev_cla": "temperature", "uniq_id": "id_1", "state_class": "measurement"}
RAM free 168032 alloc 24736
publish {"obj_id": "id_1", "stat_t": "test/bug", "exp_aft": 100, "dev_cla": "temperature", "uniq_id": "id_1", "state_class": "measurement"}
Traceback (most recent call last):
  File "main.py", line 47, in <module>
  File "uasyncio/core.py", line 1, in run
  File "uasyncio/core.py", line 1, in run_until_complete
  File "uasyncio/core.py", line 1, in wait_io_event
KeyboardInterrupt:
MicroPython v1.20.0 on 2023-04-26; Raspberry Pi Pico W with RP2040
Type "help()" for more information.
>>>

Logs from PC:

deishelon@deishelon-server:~$ mosquitto_sub -h mqtt.home -t "bug_showcase"
{"obj_id": "id_1", "stat_t": "test/bug", "exp_aft": 100, "dev_cla": "temperature", "uniq_id": "id_1", "state_class": "measurement"}
{"obj_id": "id_1", "stat_t": "test/bug", "exp_aft": 100, "dev_cla": "temperature", "uniq_id": "id_1", "state_class": "measurement"}
{"obj_id": "id_1", "stat_t": "test/bug", "exp_aft": 100, "dev_cla": "temperature", "uniq_id": "id_1", "state_class": "measurement"}
{"obj_id": "id_1", "stat_t": "test/bug", "exp_aft": 100, "dev_cla": "temperature", "uniq_id": "id_1", "state_class": "measurement"}

(Notice how picow sent 4 payloads - no 'wifi integrity checks')

With ° in payload (Bug)

Logs from pico:

Checking WiFi integrity.
Got reliable connection
Connecting to broker.
Connected to broker.
publish {"unit_of_meas": "°F", "dev_cla": "temperature", "state_class": "measurement", "uniq_id": "id_1", "stat_t": "test/bug", "exp_aft": 100, "obj_id": "id_1"}
publish {"unit_of_meas": "°F", "dev_cla": "temperature", "state_class": "measurement", "uniq_id": "id_1", "stat_t": "test/bug", "exp_aft": 100, "obj_id": "id_1"}
Checking WiFi integrity.
Got reliable connection
Connecting to broker.
Connected to broker.
Reconnect OK!
publish {"unit_of_meas": "°F", "dev_cla": "temperature", "state_class": "measurement", "uniq_id": "id_1", "stat_t": "test/bug", "exp_aft": 100, "obj_id": "id_1"}
Checking WiFi integrity.
Got reliable connection
Connecting to broker.
Connected to broker.
Reconnect OK!
publish {"unit_of_meas": "°F", "dev_cla": "temperature", "state_class": "measurement", "uniq_id": "id_1", "stat_t": "test/bug", "exp_aft": 100, "obj_id": "id_1"}
Checking WiFi integrity.
Got reliable connection
Connecting to broker.
Connected to broker.
Reconnect OK!
Traceback (most recent call last):
  File "main.py", line 47, in <module>
  File "uasyncio/core.py", line 1, in run
  File "uasyncio/core.py", line 1, in run_until_complete
  File "uasyncio/core.py", line 1, in wait_io_event
KeyboardInterrupt:
MicroPython v1.20.0 on 2023-04-26; Raspberry Pi Pico W with RP2040
Type "help()" for more information.
>>>

PC Logs:

^Cdeishelon@deishelon-server:~$ mosquitto_sub -h mqtt.home -t "bug_showcase"
{"unit_of_meas": "°F", "dev_cla": "temperature", "state_class": "measurement", "uniq_id": "id_1", "stat_t": "test/bug", "exp_aft": 100, "obj_id": "id_1"
{"unit_of_meas": "°F", "dev_cla": "temperature", "state_class": "measurement", "uniq_id": "id_1", "stat_t": "test/bug", "exp_aft": 100, "obj_id": "id_1"
{"unit_of_meas": "°F", "dev_cla": "temperature", "state_class": "measurement", "uniq_id": "id_1", "stat_t": "test/bug", "exp_aft": 100, "obj_id": "id_1"
{"unit_of_meas": "°F", "dev_cla": "temperature", "state_class": "measurement", "uniq_id": "id_1", "stat_t": "test/bug", "exp_aft": 100, "obj_id": "id_1"

Notice how Checking WiFi integrity. is popping up? Also see the logs from PC - malformed json, yet PICO logs show correct json.

Lastly, had a quick look into mqtt_as and I thought maybe I should print what bytes we send to the socket when malformed json happens. I've added this line to mqtt_as print(f"D_D _as_write about to sock.write, {bytes(bytes_wr)}") in _as_write function, like this:

try:
                print(f"D_D _as_write about to sock.write, {bytes(bytes_wr)}")
                n = sock.write(bytes_wr)

Pico logs:

MPY: soft reboot
Checking WiFi integrity.
Got reliable connection
Connecting to broker.
D_D _as_write about to sock.write, b'\x10\x1c\x00'
D_D _as_write about to sock.write, b'\x04MQTT\x04\x02\x00<'
D_D _as_write about to sock.write, b'\x00\x10'
D_D _as_write about to sock.write, b'e66141040367a836'
Connected to broker.
D_D _as_write about to sock.write, b'\x82\x0e\x00\x01'
D_D _as_write about to sock.write, b'\x00\t'
D_D _as_write about to sock.write, b'foo_topic'
D_D _as_write about to sock.write, b'\x01'
publish {"unit_of_meas": "°"}
D_D _as_write about to sock.write, b'2%'
D_D _as_write about to sock.write, b'\x00\x0c'
D_D _as_write about to sock.write, b'bug_showcase'
D_D _as_write about to sock.write, b'\x00\x02'
D_D _as_write about to sock.write, b'{"unit_of_meas": "\xc2\xb0"}'
publish {"unit_of_meas": "°"}
D_D _as_write about to sock.write, b'2%'
D_D _as_write about to sock.write, b'\x00\x0c'
D_D _as_write about to sock.write, b'bug_showcase'
D_D _as_write about to sock.write, b'\x00\x03'
D_D _as_write about to sock.write, b'{"unit_of_meas": "\xc2\xb0"}'
D_D _as_write about to sock.write, b'\xc0\x00'
RAM free 167872 alloc 24896
D_D _as_write about to sock.write, b':%'
D_D _as_write about to sock.write, b'\x00\x0c'
D_D _as_write about to sock.write, b'bug_showcase'
D_D _as_write about to sock.write, b'\x00\x03'
D_D _as_write about to sock.write, b'{"unit_of_meas": "\xc2\xb0"}'
D_D _as_write about to sock.write, b'\xc0\x00'
D_D _as_write about to sock.write, b':%'
D_D _as_write about to sock.write, b'\x00\x0c'
D_D _as_write about to sock.write, b'bug_showcase'
D_D _as_write about to sock.write, b'\x00\x03'
D_D _as_write about to sock.write, b'{"unit_of_meas": "\xc2\xb0"}'
RAM free 167872 alloc 24896
D_D _as_write about to sock.write, b':%'
D_D _as_write about to sock.write, b'\x00\x0c'
Traceback (most recent call last):
  File "main.py", line 47, in <module>
  File "uasyncio/core.py", line 1, in run
  File "uasyncio/core.py", line 1, in run_until_complete
  File "uasyncio/core.py", line 1, in wait_io_event
KeyboardInterrupt: 
MicroPython v1.20.0 on 2023-04-26; Raspberry Pi Pico W with RP2040
Type "help()" for more information.
>>> 

Any idea what is happening? Any workarounds? I also wonder if this is even mqtt_as bug, could it be micropython bug?

Deishelon commented 12 months ago

hm, after playing around with code a bit more, I made it work with: str(json_to_send).encode() where json_to_send is the output from json.dumps

peterhinch commented 12 months ago

See the docs.