tve/mqboard

mqboard put needs to use flow-control

Opened this issue · 4 comments

Any idea what might be happening here. Running /blinky/sync
(venv) fredrick@fredrick-Studio-XPS-435MT:~/Development/micropython/mqboard/blinky$ ./sync.sh --server mqtt.xxxxxxx.com --port 8883 --tls --prefix aiotcomqtt
Target directory /lib
ok sntp.py
ok sysinfo.py
ok logging.py
ok board.py
ok mqtt.py
ok mqrepl.py
ok watchdog.py
put shadiff ../mqtt_async/mqtt_async.py -> /lib/mqtt_async.py
MQRepl protocol error put: message missing: 22 vs. 21
Aborted!

tve commented

The error states that message 21 got lost (it received message 22 when it expected 21). I have to admit I haven't seen that error triggered... mqboard doesn't use flow-control for put (only for ota), I wonder whether your MQTT server is configured to only buffer up to 20 messages per client or per topic... Is there a way you can check that? If that's the case, try to double the BUFLEN https://github.com/tve/mqboard/blob/master/mqboard/engine.py#L9, that will cut the number of messages in half...

Changed BUFLEN to 2400. Below is the output...

(venv) fredrick@fredrick-Studio-XPS-435MT:~/Development/micropython/mqboard/blinky$ ./sync --server mqtt.xxxxxx.com --port 8883 --tls --prefix aiotcomqtt --verbose --timeout 120
Target directory /lib
Connecting to mqtt.xxxxxx.com:8883
Subscribing to aiotcomqtt/mqb/reply/out/syyIGwzl and aiotcomqtt/mqb/reply/err/syyIGwzl
Pub aiotcomqtt/mqb/cmd/eval/syyIGwzl #0 last=True len=499
Received reply on topic 'aiotcomqtt/mqb/reply/out/syyIGwzl' with QoS 1
0.928kB in 1.427s -> 0.650kB/s
ok sntp.py
ok sysinfo.py
ok logging.py
ok board.py
ok mqtt.py
ok mqrepl.py
ok watchdog.py
put shadiff ./../mqtt_async/mqtt_async.py -> /lib/mqtt_async.py
Subscribing to aiotcomqtt/mqb/reply/out/tEXJWKHS and aiotcomqtt/mqb/reply/err/tEXJWKHS
Pub aiotcomqtt/mqb/cmd/put/tEXJWKHS//lib/mqtt_async.py #0 last=False len=2802
Pub aiotcomqtt/mqb/cmd/put/tEXJWKHS//lib/mqtt_async.py #1 last=False len=2802
Pub aiotcomqtt/mqb/cmd/put/tEXJWKHS//lib/mqtt_async.py #2 last=False len=2802
Pub aiotcomqtt/mqb/cmd/put/tEXJWKHS//lib/mqtt_async.py #3 last=False len=2802
Pub aiotcomqtt/mqb/cmd/put/tEXJWKHS//lib/mqtt_async.py #4 last=False len=2802
Pub aiotcomqtt/mqb/cmd/put/tEXJWKHS//lib/mqtt_async.py #5 last=False len=2802
Pub aiotcomqtt/mqb/cmd/put/tEXJWKHS//lib/mqtt_async.py #6 last=False len=2802
Pub aiotcomqtt/mqb/cmd/put/tEXJWKHS//lib/mqtt_async.py #7 last=False len=2802
Pub aiotcomqtt/mqb/cmd/put/tEXJWKHS//lib/mqtt_async.py #8 last=False len=2802
Pub aiotcomqtt/mqb/cmd/put/tEXJWKHS//lib/mqtt_async.py #9 last=False len=2802
Pub aiotcomqtt/mqb/cmd/put/tEXJWKHS//lib/mqtt_async.py #10 last=False len=2802
Pub aiotcomqtt/mqb/cmd/put/tEXJWKHS//lib/mqtt_async.py #11 last=False len=2802
Pub aiotcomqtt/mqb/cmd/put/tEXJWKHS//lib/mqtt_async.py #12 last=True len=2040
Received reply on topic 'aiotcomqtt/mqb/reply/out/tEXJWKHS' with QoS 1
34.830kB in 4.652s -> 7.487kB/s
Target directory /src
Subscribing to aiotcomqtt/mqb/reply/out/onaw5ZgQ and aiotcomqtt/mqb/reply/err/onaw5ZgQ
Pub aiotcomqtt/mqb/cmd/eval/onaw5ZgQ #0 last=True len=499
Traceback (most recent call last):
File "/safemode/mqrepl.py", line 313, in _msg_cb
File "/safemode/mqrepl.py", line 192, in _do_eval
File "", line 18, in
File "", line 17, in _ls
File "", line 14, in _ls_dir
OSError: [Errno 2] ENOENT
mkdir /src
Subscribing to aiotcomqtt/mqb/reply/out/MngltQmr and aiotcomqtt/mqb/reply/err/MngltQmr
Pub aiotcomqtt/mqb/cmd/eval/MngltQmr #0 last=True len=135
Received reply on topic 'aiotcomqtt/mqb/reply/out/MngltQmr' with QoS 1
0.132kB in 0.611s -> 0.216kB/s
put missing ./blinky.py -> /src/blinky.py
Subscribing to aiotcomqtt/mqb/reply/out/zCZ8r7gV and aiotcomqtt/mqb/reply/err/zCZ8r7gV
Pub aiotcomqtt/mqb/cmd/put/zCZ8r7gV//src/blinky.py #0 last=True len=1692
Received reply on topic 'aiotcomqtt/mqb/reply/out/zCZ8r7gV' with QoS 1
1.654kB in 0.613s -> 2.698kB/s
Target directory /
Subscribing to aiotcomqtt/mqb/reply/out/KWc2q5u8 and aiotcomqtt/mqb/reply/err/KWc2q5u8
Pub aiotcomqtt/mqb/cmd/eval/KWc2q5u8 #0 last=True len=496
Received reply on topic 'aiotcomqtt/mqb/reply/out/KWc2q5u8' with QoS 1
0.537kB in 0.614s -> 0.875kB/s
put missing ../board/main.py -> /main.py
Subscribing to aiotcomqtt/mqb/reply/out/HPG0-ImY and aiotcomqtt/mqb/reply/err/HPG0-ImY
Pub aiotcomqtt/mqb/cmd/put/HPG0-ImY//main.py #0 last=False len=2802
Pub aiotcomqtt/mqb/cmd/put/HPG0-ImY//main.py #1 last=True len=846
Received reply on topic 'aiotcomqtt/mqb/reply/out/HPG0-ImY' with QoS 1
3.564kB in 0.434s -> 8.207kB/s
put missing ./board_config.py -> /board_config.py
Subscribing to aiotcomqtt/mqb/reply/out/gjR3kdNb and aiotcomqtt/mqb/reply/err/gjR3kdNb
Pub aiotcomqtt/mqb/cmd/put/gjR3kdNb//board_config.py #0 last=True len=2702
Received reply on topic 'aiotcomqtt/mqb/reply/out/gjR3kdNb' with QoS 1
2.641kB in 0.799s -> 3.304kB/s
ok boot.py

Uggg, just now finding out that my ESP32-DevKitC WROOM-32D does not have a user LED only a 5v LED

tve commented

Looks good! So the amount of buffering at the broker level most likely was the issue. This means I need to implement flow-control, just like I do for OTA (which is a bit on the hacky end). Grrr...