mqtt_as: PUBACKs of messages sent with qos=1 not handled and stacking up, resulting in 1) resends, then 2) no further messages being sent and 3) eventually resulting in mem exhaustion

[mirko]

I noticed when sending out messages via mqtt_as's publish() with qos=1 that at some point messages get resent to the broker. Adding debug output to "mqtt_as" shows that at some point PUBACKs are not received/handled in time anymore, resulting in messages being resent.

At some even further point, no messages make it through to the broker at all anymore.

With below test case I send out 10 messages (in 2 sets of 5) every 15 seconds (triggered by ESP32's timer). After each sets uasyncio.sleep(4) is called. Besides those 2x4 seconds there's also the mainloop calling uasyncio.sleep(10), so there should be plenty of scheduling time for mqtt_as to handle the PUBACKs (right?).

Something seems to stack up, though, as eventually the Guru starts to medidate with an MemoryError or it results in a crash caused by an assert() dropping:

assertion "mp_obj_is_small_int(args[2])" failed: file "../../extmod/moduasyncio.c", line 103, function: task_queue_push_sorted
abort() was called at PC 0x4016b75f on core 0

What is happening, what am I doing wrong? I was fearing it might be intrpt() being implicitly called via mp_sched_schedule() internally, but I'm kind of lost here.

The problem does not seem to occur with qos=0.

Micropython firmware version is v1.14 for ESP32 (SDK IDF v4, no psRAM).

Test code:

from machine import Pin, Timer
import network
import uasyncio
import utime
from mqtt_as.mqtt_as import MQTTClient, config

mqtt = None
i = 0

async def asyncfun():
    print("|| Scheduling 1st set of 5 messages..", utime.time())
    uasyncio.create_task(mqtt_pub())
    uasyncio.create_task(mqtt_pub())
    uasyncio.create_task(mqtt_pub())
    uasyncio.create_task(mqtt_pub())
    uasyncio.create_task(mqtt_pub())
    await uasyncio.sleep(4)
    print("|| Expected PUBACKs for 1st set of 5 messages to be handled by now", utime.time())
    print("|| Scheduling 2nd set of 5 messages..", utime.time())
    uasyncio.create_task(mqtt_pub())
    uasyncio.create_task(mqtt_pub())
    uasyncio.create_task(mqtt_pub())
    uasyncio.create_task(mqtt_pub())
    uasyncio.create_task(mqtt_pub())
    await uasyncio.sleep(4)
    print("|| Expected PUBACKs for 2nd set of 5 messages to be handled by now", utime.time())
    #print("asyncfun: done")

def intrpt(_=None):
    print("+++ TMR INT TRIGGERED", utime.time())
    print("|| Starting asyncfun()", utime.time())
    uasyncio.run(asyncfun())
    print("|| Finished asyncfun()", utime.time())

async def main_loop():
    while True:
        print("-- MAIN LOOP", utime.time())
        await uasyncio.sleep(10)

async def mqtt_pub():
    global mqtt
    global i
    i += 1
    print("-> PUBLISH", utime.time())
    await mqtt.publish("foo/bar", "Round {}".format(i), qos=1)
    print("-> /PUBLISH", utime.time())

async def mqtt_conn_cb(clnt):
    print("++ MQTT CONN CALLBACK", utime.time())
    print("Starting timer causing interrupts every 15secs..")
    Timer(0).init(mode=Timer.PERIODIC, period=15000, callback=intrpt)

async def mqtt_subs_cb(tpc, msg, rtnd):
    print("MQTT SUB CALLBACK!")

async def mqtt_connect():
    global mqtt
    config['ssid'] = 'foobar'
    config['wifi_pw'] = 'foobarfoobar'
    config['server'] = 'test.mosquitto.org'
    config['port'] = 1883
    config['client_id'] = 'fnord'
    config['clean'] = True
    config['response_time'] = 10
    config['subs_cb'] = mqtt_subs_cb
    config['connect_coro'] = mqtt_conn_cb

    print("++ CONNECTING TO WIFI/MQTT", utime.time())
    mqtt = MQTTClient(config)
    await mqtt.connect()

uasyncio.run(mqtt_connect())

uasyncio.run(main_loop())

Diff I applied to mqtt_as.py for debugging purposes:

diff --git a/mqtt_as/mqtt_as.py b/mqtt_as/mqtt_as.py
index ddf8d17..cf4abee 100644
--- a/mqtt_as/mqtt_as.py
+++ b/mqtt_as/mqtt_as.py
@@ -14,7 +14,7 @@ from ubinascii import hexlify
 import uasyncio as asyncio

 gc.collect()
-from utime import ticks_ms, ticks_diff
+from utime import ticks_ms, ticks_diff, time
 from uerrno import EINPROGRESS, ETIMEDOUT

 gc.collect()
@@ -341,14 +341,18 @@ class MQTT_base:
         count = 0
         while 1:  # Await PUBACK, republish on timeout
             if await self._await_pid(pid):
+                print(">#>#>#> RECEIVED PUBACK FOR PID {} (tpc: {} | msg: {})".format(pid, topic, msg), time())
                 return
+            print(">#>#>#> NO PUBACK IN TIME FOR PID {} (tpc: {} | msg: {})".format(pid, topic, msg), time())
             # No match
             if count >= self._max_repubs or not self.isconnected():
                 raise OSError(-1)  # Subclass to re-publish with new PID
+            print(">#>#>#> GOING TO *RE*PUBLISH PID {} (tpc: {} | msg: {})".format(pid, topic, msg), time())
             async with self.lock:
                 await self._publish(topic, msg, retain, qos, dup=1, pid=pid)  # Add pid
             count += 1
             self.REPUB_COUNT += 1
+            print(">#>#>#> *RE*PUBLISHED PID {} (ATTEMPT: {} (TOTAL: {})) (tpc: {} | msg: {})".format(pid, count, self.REPUB_COUNT, topic, msg), time())

     async def _publish(self, topic, msg, retain, qos, dup, pid):
         pkt = bytearray(b"\x30\0\0\0")

Log of example run:

>>> MicroPython v1.14 on 2021-02-02; ESP32 module with ESP32
Type "help()" for more information.
>>> 
>>> import test
++ CONNECTING TO WIFI/MQTT 3
++ MQTT CONN CALLBACK 12
Starting timer causing interrupts every 15secs..
-- MAIN LOOP 12
-- MAIN LOOP 22
+++ TMR INT TRIGGERED 27
|| Starting asyncfun() 27
|| Scheduling 1st set of 5 messages.. 27
-> PUBLISH 27
-> PUBLISH 27
-> PUBLISH 27
-> PUBLISH 27
-> PUBLISH 27
>#>#>#> RECEIVED PUBACK FOR PID 1 (tpc: foo/bar | msg: Round 1) 28
-> /PUBLISH 28
>#>#>#> RECEIVED PUBACK FOR PID 2 (tpc: foo/bar | msg: Round 2) 28
-> /PUBLISH 28
>#>#>#> RECEIVED PUBACK FOR PID 3 (tpc: foo/bar | msg: Round 3) 29
-> /PUBLISH 29
>#>#>#> RECEIVED PUBACK FOR PID 4 (tpc: foo/bar | msg: Round 4) 29
-> /PUBLISH 29
>#>#>#> RECEIVED PUBACK FOR PID 5 (tpc: foo/bar | msg: Round 5) 29
-> /PUBLISH 29
|| Expected PUBACKs for 1st set of 5 messages to be handled by now 31
|| Scheduling 2nd set of 5 messages.. 31
-> PUBLISH 31
-> PUBLISH 31
-> PUBLISH 31
-> PUBLISH 31
-> PUBLISH 31
>#>#>#> RECEIVED PUBACK FOR PID 6 (tpc: foo/bar | msg: Round 6) 31
-> /PUBLISH 31
>#>#>#> RECEIVED PUBACK FOR PID 7 (tpc: foo/bar | msg: Round 7) 31
-> /PUBLISH 31
-- MAIN LOOP 32
>#>#>#> RECEIVED PUBACK FOR PID 8 (tpc: foo/bar | msg: Round 8) 32
-> /PUBLISH 32
>#>#>#> RECEIVED PUBACK FOR PID 9 (tpc: foo/bar | msg: Round 9) 32
-> /PUBLISH 32
>#>#>#> RECEIVED PUBACK FOR PID 10 (tpc: foo/bar | msg: Round 10) 32
-> /PUBLISH 32
|| Expected PUBACKs for 2nd set of 5 messages to be handled by now 35
|| Finished asyncfun() 35
+++ TMR INT TRIGGERED 42
|| Starting asyncfun() 42
|| Scheduling 1st set of 5 messages.. 42
-> PUBLISH 42
-> PUBLISH 42
-> PUBLISH 42
-> PUBLISH 42
-> PUBLISH 42
-- MAIN LOOP 42
>#>#>#> RECEIVED PUBACK FOR PID 11 (tpc: foo/bar | msg: Round 11) 42
-> /PUBLISH 42
>#>#>#> RECEIVED PUBACK FOR PID 12 (tpc: foo/bar | msg: Round 12) 42
-> /PUBLISH 42
>#>#>#> RECEIVED PUBACK FOR PID 13 (tpc: foo/bar | msg: Round 13) 42
-> /PUBLISH 42
>#>#>#> RECEIVED PUBACK FOR PID 14 (tpc: foo/bar | msg: Round 14) 43
-> /PUBLISH 43
>#>#>#> RECEIVED PUBACK FOR PID 15 (tpc: foo/bar | msg: Round 15) 43
-> /PUBLISH 43
|| Expected PUBACKs for 1st set of 5 messages to be handled by now 46
|| Scheduling 2nd set of 5 messages.. 46
-> PUBLISH 46
-> PUBLISH 46
-> PUBLISH 46
-> PUBLISH 46
-> PUBLISH 46
>#>#>#> RECEIVED PUBACK FOR PID 16 (tpc: foo/bar | msg: Round 16) 46
-> /PUBLISH 46
>#>#>#> RECEIVED PUBACK FOR PID 17 (tpc: foo/bar | msg: Round 17) 46
-> /PUBLISH 46
>#>#>#> RECEIVED PUBACK FOR PID 18 (tpc: foo/bar | msg: Round 18) 46
-> /PUBLISH 46
>#>#>#> RECEIVED PUBACK FOR PID 19 (tpc: foo/bar | msg: Round 19) 47
-> /PUBLISH 47
>#>#>#> RECEIVED PUBACK FOR PID 20 (tpc: foo/bar | msg: Round 20) 47
-> /PUBLISH 47
|| Expected PUBACKs for 2nd set of 5 messages to be handled by now 50
|| Finished asyncfun() 50
-- MAIN LOOP 52
+++ TMR INT TRIGGERED 57
|| Starting asyncfun() 57
|| Scheduling 1st set of 5 messages.. 57
-> PUBLISH 57
-> PUBLISH 57
-> PUBLISH 57
-> PUBLISH 57
-> PUBLISH 57
>#>#>#> RECEIVED PUBACK FOR PID 21 (tpc: foo/bar | msg: Round 21) 57
-> /PUBLISH 57
>#>#>#> RECEIVED PUBACK FOR PID 22 (tpc: foo/bar | msg: Round 22) 57
-> /PUBLISH 57
>#>#>#> RECEIVED PUBACK FOR PID 23 (tpc: foo/bar | msg: Round 23) 57
-> /PUBLISH 57
>#>#>#> RECEIVED PUBACK FOR PID 24 (tpc: foo/bar | msg: Round 24) 57
-> /PUBLISH 57
>#>#>#> RECEIVED PUBACK FOR PID 25 (tpc: foo/bar | msg: Round 25) 58
-> /PUBLISH 58
|| Expected PUBACKs for 1st set of 5 messages to be handled by now 61
|| Scheduling 2nd set of 5 messages.. 61
-> PUBLISH 61
-> PUBLISH 61
-> PUBLISH 61
-> PUBLISH 61
-> PUBLISH 61
-- MAIN LOOP 62
>#>#>#> RECEIVED PUBACK FOR PID 26 (tpc: foo/bar | msg: Round 26) 62
-> /PUBLISH 62
>#>#>#> RECEIVED PUBACK FOR PID 27 (tpc: foo/bar | msg: Round 27) 62
-> /PUBLISH 62
>#>#>#> RECEIVED PUBACK FOR PID 28 (tpc: foo/bar | msg: Round 28) 62
-> /PUBLISH 62
>#>#>#> RECEIVED PUBACK FOR PID 29 (tpc: foo/bar | msg: Round 29) 62
-> /PUBLISH 62
>#>#>#> RECEIVED PUBACK FOR PID 30 (tpc: foo/bar | msg: Round 30) 62
-> /PUBLISH 62
|| Expected PUBACKs for 2nd set of 5 messages to be handled by now 65
|| Finished asyncfun() 65
+++ TMR INT TRIGGERED 72
|| Starting asyncfun() 72
|| Scheduling 1st set of 5 messages.. 72
-> PUBLISH 72
-> PUBLISH 72
-> PUBLISH 72
-> PUBLISH 72
-> PUBLISH 72
-- MAIN LOOP 72
|| Expected PUBACKs for 1st set of 5 messages to be handled by now 76
|| Scheduling 2nd set of 5 messages.. 76
-> PUBLISH 76
-> PUBLISH 76
-> PUBLISH 76
-> PUBLISH 76
-> PUBLISH 76
|| Expected PUBACKs for 2nd set of 5 messages to be handled by now 80
|| Finished asyncfun() 80
-- MAIN LOOP 82
+++ TMR INT TRIGGERED 87
|| Starting asyncfun() 87
|| Scheduling 1st set of 5 messages.. 87
-> PUBLISH 87
-> PUBLISH 87
-> PUBLISH 87
-> PUBLISH 87
-> PUBLISH 87
>#>#>#> NO PUBACK IN TIME FOR PID 31 (tpc: foo/bar | msg: Round 31) 90
>#>#>#> GOING TO *RE*PUBLISH PID 31 (tpc: foo/bar | msg: Round 31) 90
>#>#>#> *RE*PUBLISHED PID 31 (ATTEMPT: 1 (TOTAL: 1)) (tpc: foo/bar | msg: Round 31) 90
>#>#>#> NO PUBACK IN TIME FOR PID 32 (tpc: foo/bar | msg: Round 32) 90
>#>#>#> GOING TO *RE*PUBLISH PID 32 (tpc: foo/bar | msg: Round 32) 90
>#>#>#> NO PUBACK IN TIME FOR PID 33 (tpc: foo/bar | msg: Round 33) 90
>#>#>#> GOING TO *RE*PUBLISH PID 33 (tpc: foo/bar | msg: Round 33) 90
>#>#>#> *RE*PUBLISHED PID 32 (ATTEMPT: 1 (TOTAL: 2)) (tpc: foo/bar | msg: Round 32) 90
>#>#>#> NO PUBACK IN TIME FOR PID 34 (tpc: foo/bar | msg: Round 34) 90
>#>#>#> GOING TO *RE*PUBLISH PID 34 (tpc: foo/bar | msg: Round 34) 90
>#>#>#> NO PUBACK IN TIME FOR PID 37 (tpc: foo/bar | msg: Round 37) 90
>#>#>#> GOING TO *RE*PUBLISH PID 37 (tpc: foo/bar | msg: Round 37) 90
>#>#>#> *RE*PUBLISHED PID 33 (ATTEMPT: 1 (TOTAL: 3)) (tpc: foo/bar | msg: Round 33) 90
>#>#>#> NO PUBACK IN TIME FOR PID 35 (tpc: foo/bar | msg: Round 35) 90
>#>#>#> GOING TO *RE*PUBLISH PID 35 (tpc: foo/bar | msg: Round 35) 90
>#>#>#> NO PUBACK IN TIME FOR PID 38 (tpc: foo/bar | msg: Round 38) 90
>#>#>#> GOING TO *RE*PUBLISH PID 38 (tpc: foo/bar | msg: Round 38) 90
>#>#>#> NO PUBACK IN TIME FOR PID 36 (tpc: foo/bar | msg: Round 36) 90
>#>#>#> GOING TO *RE*PUBLISH PID 36 (tpc: foo/bar | msg: Round 36) 90
>#>#>#> NO PUBACK IN TIME FOR PID 39 (tpc: foo/bar | msg: Round 39) 90
>#>#>#> GOING TO *RE*PUBLISH PID 39 (tpc: foo/bar | msg: Round 39) 90
>#>#>#> *RE*PUBLISHED PID 34 (ATTEMPT: 1 (TOTAL: 4)) (tpc: foo/bar | msg: Round 34) 90
>#>#>#> NO PUBACK IN TIME FOR PID 40 (tpc: foo/bar | msg: Round 40) 90
>#>#>#> GOING TO *RE*PUBLISH PID 40 (tpc: foo/bar | msg: Round 40) 90
>#>#>#> *RE*PUBLISHED PID 37 (ATTEMPT: 1 (TOTAL: 5)) (tpc: foo/bar | msg: Round 37) 90
>#>#>#> *RE*PUBLISHED PID 35 (ATTEMPT: 1 (TOTAL: 6)) (tpc: foo/bar | msg: Round 35) 90
>#>#>#> *RE*PUBLISHED PID 38 (ATTEMPT: 1 (TOTAL: 7)) (tpc: foo/bar | msg: Round 38) 90
>#>#>#> *RE*PUBLISHED PID 36 (ATTEMPT: 1 (TOTAL: 8)) (tpc: foo/bar | msg: Round 36) 90
>#>#>#> *RE*PUBLISHED PID 39 (ATTEMPT: 1 (TOTAL: 9)) (tpc: foo/bar | msg: Round 39) 90
>#>#>#> *RE*PUBLISHED PID 40 (ATTEMPT: 1 (TOTAL: 10)) (tpc: foo/bar | msg: Round 40) 90
|| Expected PUBACKs for 1st set of 5 messages to be handled by now 91
|| Scheduling 2nd set of 5 messages.. 91
-> PUBLISH 91
-> PUBLISH 91
-> PUBLISH 91
-> PUBLISH 91
-> PUBLISH 91
-- MAIN LOOP 92
|| Expected PUBACKs for 2nd set of 5 messages to be handled by now 95
|| Finished asyncfun() 95
>#>#>#> NO PUBACK IN TIME FOR PID 41 (tpc: foo/bar | msg: Round 41) 97
>#>#>#> GOING TO *RE*PUBLISH PID 41 (tpc: foo/bar | msg: Round 41) 97
>#>#>#> *RE*PUBLISHED PID 41 (ATTEMPT: 1 (TOTAL: 11)) (tpc: foo/bar | msg: Round 41) 97
>#>#>#> NO PUBACK IN TIME FOR PID 43 (tpc: foo/bar | msg: Round 43) 97
>#>#>#> GOING TO *RE*PUBLISH PID 43 (tpc: foo/bar | msg: Round 43) 97
>#>#>#> NO PUBACK IN TIME FOR PID 44 (tpc: foo/bar | msg: Round 44) 97
>#>#>#> GOING TO *RE*PUBLISH PID 44 (tpc: foo/bar | msg: Round 44) 97
>#>#>#> NO PUBACK IN TIME FOR PID 42 (tpc: foo/bar | msg: Round 42) 97
>#>#>#> GOING TO *RE*PUBLISH PID 42 (tpc: foo/bar | msg: Round 42) 97
>#>#>#> NO PUBACK IN TIME FOR PID 45 (tpc: foo/bar | msg: Round 45) 97
>#>#>#> GOING TO *RE*PUBLISH PID 45 (tpc: foo/bar | msg: Round 45) 97
>#>#>#> *RE*PUBLISHED PID 43 (ATTEMPT: 1 (TOTAL: 12)) (tpc: foo/bar | msg: Round 43) 97
>#>#>#> *RE*PUBLISHED PID 44 (ATTEMPT: 1 (TOTAL: 13)) (tpc: foo/bar | msg: Round 44) 97
>#>#>#> *RE*PUBLISHED PID 42 (ATTEMPT: 1 (TOTAL: 14)) (tpc: foo/bar | msg: Round 42) 97
>#>#>#> *RE*PUBLISHED PID 45 (ATTEMPT: 1 (TOTAL: 15)) (tpc: foo/bar | msg: Round 45) 97
>#>#>#> NO PUBACK IN TIME FOR PID 31 (tpc: foo/bar | msg: Round 31) 100
>#>#>#> GOING TO *RE*PUBLISH PID 31 (tpc: foo/bar | msg: Round 31) 100
>#>#>#> *RE*PUBLISHED PID 31 (ATTEMPT: 2 (TOTAL: 16)) (tpc: foo/bar | msg: Round 31) 100
>#>#>#> NO PUBACK IN TIME FOR PID 32 (tpc: foo/bar | msg: Round 32) 100
>#>#>#> GOING TO *RE*PUBLISH PID 32 (tpc: foo/bar | msg: Round 32) 100
>#>#>#> *RE*PUBLISHED PID 32 (ATTEMPT: 2 (TOTAL: 17)) (tpc: foo/bar | msg: Round 32) 100
>#>#>#> NO PUBACK IN TIME FOR PID 33 (tpc: foo/bar | msg: Round 33) 100
>#>#>#> GOING TO *RE*PUBLISH PID 33 (tpc: foo/bar | msg: Round 33) 100
>#>#>#> *RE*PUBLISHED PID 33 (ATTEMPT: 2 (TOTAL: 18)) (tpc: foo/bar | msg: Round 33) 100
>#>#>#> NO PUBACK IN TIME FOR PID 34 (tpc: foo/bar | msg: Round 34) 100
>#>#>#> GOING TO *RE*PUBLISH PID 34 (tpc: foo/bar | msg: Round 34) 100
>#>#>#> *RE*PUBLISHED PID 34 (ATTEMPT: 2 (TOTAL: 19)) (tpc: foo/bar | msg: Round 34) 100
>#>#>#> NO PUBACK IN TIME FOR PID 37 (tpc: foo/bar | msg: Round 37) 100
>#>#>#> GOING TO *RE*PUBLISH PID 37 (tpc: foo/bar | msg: Round 37) 100
>#>#>#> NO PUBACK IN TIME FOR PID 35 (tpc: foo/bar | msg: Round 35) 100
>#>#>#> GOING TO *RE*PUBLISH PID 35 (tpc: foo/bar | msg: Round 35) 100
>#>#>#> *RE*PUBLISHED PID 37 (ATTEMPT: 2 (TOTAL: 20)) (tpc: foo/bar | msg: Round 37) 100
>#>#>#> NO PUBACK IN TIME FOR PID 38 (tpc: foo/bar | msg: Round 38) 100
>#>#>#> GOING TO *RE*PUBLISH PID 38 (tpc: foo/bar | msg: Round 38) 100
>#>#>#> *RE*PUBLISHED PID 35 (ATTEMPT: 2 (TOTAL: 21)) (tpc: foo/bar | msg: Round 35) 100
>#>#>#> NO PUBACK IN TIME FOR PID 36 (tpc: foo/bar | msg: Round 36) 100
>#>#>#> GOING TO *RE*PUBLISH PID 36 (tpc: foo/bar | msg: Round 36) 100
>#>#>#> *RE*PUBLISHED PID 38 (ATTEMPT: 2 (TOTAL: 22)) (tpc: foo/bar | msg: Round 38) 100
>#>#>#> NO PUBACK IN TIME FOR PID 39 (tpc: foo/bar | msg: Round 39) 100
>#>#>#> GOING TO *RE*PUBLISH PID 39 (tpc: foo/bar | msg: Round 39) 100
>#>#>#> *RE*PUBLISHED PID 36 (ATTEMPT: 2 (TOTAL: 23)) (tpc: foo/bar | msg: Round 36) 101
>#>#>#> NO PUBACK IN TIME FOR PID 40 (tpc: foo/bar | msg: Round 40) 101
>#>#>#> GOING TO *RE*PUBLISH PID 40 (tpc: foo/bar | msg: Round 40) 101
>#>#>#> *RE*PUBLISHED PID 39 (ATTEMPT: 2 (TOTAL: 24)) (tpc: foo/bar | msg: Round 39) 101
>#>#>#> *RE*PUBLISHED PID 40 (ATTEMPT: 2 (TOTAL: 25)) (tpc: foo/bar | msg: Round 40) 101
>#>#>#> NO PUBACK IN TIME FOR PID 46 (tpc: foo/bar | msg: Round 46) 101
>#>#>#> GOING TO *RE*PUBLISH PID 46 (tpc: foo/bar | msg: Round 46) 101
>#>#>#> *RE*PUBLISHED PID 46 (ATTEMPT: 1 (TOTAL: 26)) (tpc: foo/bar | msg: Round 46) 101
>#>#>#> NO PUBACK IN TIME FOR PID 49 (tpc: foo/bar | msg: Round 49) 101
>#>#>#> GOING TO *RE*PUBLISH PID 49 (tpc: foo/bar | msg: Round 49) 101
>#>#>#> NO PUBACK IN TIME FOR PID 47 (tpc: foo/bar | msg: Round 47) 101
>#>#>#> GOING TO *RE*PUBLISH PID 47 (tpc: foo/bar | msg: Round 47) 101
>#>#>#> NO PUBACK IN TIME FOR PID 50 (tpc: foo/bar | msg: Round 50) 101
>#>#>#> GOING TO *RE*PUBLISH PID 50 (tpc: foo/bar | msg: Round 50) 101
>#>#>#> NO PUBACK IN TIME FOR PID 48 (tpc: foo/bar | msg: Round 48) 101
>#>#>#> GOING TO *RE*PUBLISH PID 48 (tpc: foo/bar | msg: Round 48) 101
>#>#>#> *RE*PUBLISHED PID 49 (ATTEMPT: 1 (TOTAL: 27)) (tpc: foo/bar | msg: Round 49) 101
>#>#>#> *RE*PUBLISHED PID 47 (ATTEMPT: 1 (TOTAL: 28)) (tpc: foo/bar | msg: Round 47) 101
>#>#>#> *RE*PUBLISHED PID 50 (ATTEMPT: 1 (TOTAL: 29)) (tpc: foo/bar | msg: Round 50) 101
>#>#>#> *RE*PUBLISHED PID 48 (ATTEMPT: 1 (TOTAL: 30)) (tpc: foo/bar | msg: Round 48) 101
+++ TMR INT TRIGGERED 102
|| Starting asyncfun() 102
|| Scheduling 1st set of 5 messages.. 102
-> PUBLISH 102
-> PUBLISH 102
-> PUBLISH 102
-> PUBLISH 102
-> PUBLISH 102
-- MAIN LOOP 102
|| Expected PUBACKs for 1st set of 5 messages to be handled by now 106
|| Scheduling 2nd set of 5 messages.. 106
-> PUBLISH 106
-> PUBLISH 106
-> PUBLISH 106
-> PUBLISH 106
-> PUBLISH 106
>#>#>#> NO PUBACK IN TIME FOR PID 41 (tpc: foo/bar | msg: Round 41) 107
>#>#>#> GOING TO *RE*PUBLISH PID 41 (tpc: foo/bar | msg: Round 41) 107
>#>#>#> *RE*PUBLISHED PID 41 (ATTEMPT: 2 (TOTAL: 31)) (tpc: foo/bar | msg: Round 41) 107
>#>#>#> NO PUBACK IN TIME FOR PID 43 (tpc: foo/bar | msg: Round 43) 107
>#>#>#> GOING TO *RE*PUBLISH PID 43 (tpc: foo/bar | msg: Round 43) 107
>#>#>#> *RE*PUBLISHED PID 43 (ATTEMPT: 2 (TOTAL: 32)) (tpc: foo/bar | msg: Round 43) 107
>#>#>#> NO PUBACK IN TIME FOR PID 44 (tpc: foo/bar | msg: Round 44) 107
>#>#>#> GOING TO *RE*PUBLISH PID 44 (tpc: foo/bar | msg: Round 44) 107
>#>#>#> NO PUBACK IN TIME FOR PID 42 (tpc: foo/bar | msg: Round 42) 107
>#>#>#> GOING TO *RE*PUBLISH PID 42 (tpc: foo/bar | msg: Round 42) 107
>#>#>#> *RE*PUBLISHED PID 44 (ATTEMPT: 2 (TOTAL: 33)) (tpc: foo/bar | msg: Round 44) 107
>#>#>#> NO PUBACK IN TIME FOR PID 45 (tpc: foo/bar | msg: Round 45) 107
>#>#>#> GOING TO *RE*PUBLISH PID 45 (tpc: foo/bar | msg: Round 45) 107
>#>#>#> *RE*PUBLISHED PID 42 (ATTEMPT: 2 (TOTAL: 34)) (tpc: foo/bar | msg: Round 42) 107
>#>#>#> *RE*PUBLISHED PID 45 (ATTEMPT: 2 (TOTAL: 35)) (tpc: foo/bar | msg: Round 45) 107
|| Expected PUBACKs for 2nd set of 5 messages to be handled by now 110
|| Finished asyncfun() 110
>#>#>#> NO PUBACK IN TIME FOR PID 31 (tpc: foo/bar | msg: Round 31) 110
>#>#>#> GOING TO *RE*PUBLISH PID 31 (tpc: foo/bar | msg: Round 31) 110
>#>#>#> *RE*PUBLISHED PID 31 (ATTEMPT: 3 (TOTAL: 36)) (tpc: foo/bar | msg: Round 31) 110
>#>#>#> NO PUBACK IN TIME FOR PID 32 (tpc: foo/bar | msg: Round 32) 110
>#>#>#> GOING TO *RE*PUBLISH PID 32 (tpc: foo/bar | msg: Round 32) 110
>#>#>#> NO PUBACK IN TIME FOR PID 33 (tpc: foo/bar | msg: Round 33) 110
>#>#>#> GOING TO *RE*PUBLISH PID 33 (tpc: foo/bar | msg: Round 33) 110
>#>#>#> *RE*PUBLISHED PID 32 (ATTEMPT: 3 (TOTAL: 37)) (tpc: foo/bar | msg: Round 32) 110
>#>#>#> *RE*PUBLISHED PID 33 (ATTEMPT: 3 (TOTAL: 38)) (tpc: foo/bar | msg: Round 33) 110
>#>#>#> NO PUBACK IN TIME FOR PID 34 (tpc: foo/bar | msg: Round 34) 110
>#>#>#> GOING TO *RE*PUBLISH PID 34 (tpc: foo/bar | msg: Round 34) 110
>#>#>#> *RE*PUBLISHED PID 34 (ATTEMPT: 3 (TOTAL: 39)) (tpc: foo/bar | msg: Round 34) 110
>#>#>#> NO PUBACK IN TIME FOR PID 37 (tpc: foo/bar | msg: Round 37) 110
>#>#>#> GOING TO *RE*PUBLISH PID 37 (tpc: foo/bar | msg: Round 37) 110
>#>#>#> NO PUBACK IN TIME FOR PID 35 (tpc: foo/bar | msg: Round 35) 110
>#>#>#> GOING TO *RE*PUBLISH PID 35 (tpc: foo/bar | msg: Round 35) 110
>#>#>#> *RE*PUBLISHED PID 37 (ATTEMPT: 3 (TOTAL: 40)) (tpc: foo/bar | msg: Round 37) 111
>#>#>#> NO PUBACK IN TIME FOR PID 38 (tpc: foo/bar | msg: Round 38) 111
>#>#>#> GOING TO *RE*PUBLISH PID 38 (tpc: foo/bar | msg: Round 38) 111
>#>#>#> *RE*PUBLISHED PID 35 (ATTEMPT: 3 (TOTAL: 41)) (tpc: foo/bar | msg: Round 35) 111
>#>#>#> NO PUBACK IN TIME FOR PID 36 (tpc: foo/bar | msg: Round 36) 111
>#>#>#> GOING TO *RE*PUBLISH PID 36 (tpc: foo/bar | msg: Round 36) 111
>#>#>#> *RE*PUBLISHED PID 38 (ATTEMPT: 3 (TOTAL: 42)) (tpc: foo/bar | msg: Round 38) 111
>#>#>#> NO PUBACK IN TIME FOR PID 39 (tpc: foo/bar | msg: Round 39) 111
>#>#>#> GOING TO *RE*PUBLISH PID 39 (tpc: foo/bar | msg: Round 39) 111
>#>#>#> NO PUBACK IN TIME FOR PID 40 (tpc: foo/bar | msg: Round 40) 111
>#>#>#> GOING TO *RE*PUBLISH PID 40 (tpc: foo/bar | msg: Round 40) 111
>#>#>#> *RE*PUBLISHED PID 36 (ATTEMPT: 3 (TOTAL: 43)) (tpc: foo/bar | msg: Round 36) 111
>#>#>#> *RE*PUBLISHED PID 39 (ATTEMPT: 3 (TOTAL: 44)) (tpc: foo/bar | msg: Round 39) 111
>#>#>#> *RE*PUBLISHED PID 40 (ATTEMPT: 3 (TOTAL: 45)) (tpc: foo/bar | msg: Round 40) 111
>#>#>#> NO PUBACK IN TIME FOR PID 46 (tpc: foo/bar | msg: Round 46) 111
>#>#>#> GOING TO *RE*PUBLISH PID 46 (tpc: foo/bar | msg: Round 46) 111
>#>#>#> *RE*PUBLISHED PID 46 (ATTEMPT: 2 (TOTAL: 46)) (tpc: foo/bar | msg: Round 46) 111
>#>#>#> NO PUBACK IN TIME FOR PID 49 (tpc: foo/bar | msg: Round 49) 111
>#>#>#> GOING TO *RE*PUBLISH PID 49 (tpc: foo/bar | msg: Round 49) 111
>#>#>#> NO PUBACK IN TIME FOR PID 47 (tpc: foo/bar | msg: Round 47) 111
>#>#>#> GOING TO *RE*PUBLISH PID 47 (tpc: foo/bar | msg: Round 47) 111
>#>#>#> *RE*PUBLISHED PID 49 (ATTEMPT: 2 (TOTAL: 47)) (tpc: foo/bar | msg: Round 49) 111
>#>#>#> NO PUBACK IN TIME FOR PID 50 (tpc: foo/bar | msg: Round 50) 111
>#>#>#> GOING TO *RE*PUBLISH PID 50 (tpc: foo/bar | msg: Round 50) 111
>#>#>#> *RE*PUBLISHED PID 47 (ATTEMPT: 2 (TOTAL: 48)) (tpc: foo/bar | msg: Round 47) 111
>#>#>#> NO PUBACK IN TIME FOR PID 48 (tpc: foo/bar | msg: Round 48) 111
>#>#>#> GOING TO *RE*PUBLISH PID 48 (tpc: foo/bar | msg: Round 48) 111
>#>#>#> *RE*PUBLISHED PID 50 (ATTEMPT: 2 (TOTAL: 49)) (tpc: foo/bar | msg: Round 50) 111
>#>#>#> *RE*PUBLISHED PID 48 (ATTEMPT: 2 (TOTAL: 50)) (tpc: foo/bar | msg: Round 48) 111
-- MAIN LOOP 112
>#>#>#> NO PUBACK IN TIME FOR PID 51 (tpc: foo/bar | msg: Round 51) 112
>#>#>#> GOING TO *RE*PUBLISH PID 51 (tpc: foo/bar | msg: Round 51) 112
>#>#>#> NO PUBACK IN TIME FOR PID 52 (tpc: foo/bar | msg: Round 52) 112
>#>#>#> GOING TO *RE*PUBLISH PID 52 (tpc: foo/bar | msg: Round 52) 112
>#>#>#> *RE*PUBLISHED PID 51 (ATTEMPT: 1 (TOTAL: 51)) (tpc: foo/bar | msg: Round 51) 112
>#>#>#> NO PUBACK IN TIME FOR PID 53 (tpc: foo/bar | msg: Round 53) 112
>#>#>#> GOING TO *RE*PUBLISH PID 53 (tpc: foo/bar | msg: Round 53) 112
>#>#>#> *RE*PUBLISHED PID 52 (ATTEMPT: 1 (TOTAL: 52)) (tpc: foo/bar | msg: Round 52) 112
>#>#>#> NO PUBACK IN TIME FOR PID 54 (tpc: foo/bar | msg: Round 54) 112
>#>#>#> GOING TO *RE*PUBLISH PID 54 (tpc: foo/bar | msg: Round 54) 112
>#>#>#> NO PUBACK IN TIME FOR PID 55 (tpc: foo/bar | msg: Round 55) 112
>#>#>#> GOING TO *RE*PUBLISH PID 55 (tpc: foo/bar | msg: Round 55) 112
>#>#>#> *RE*PUBLISHED PID 53 (ATTEMPT: 1 (TOTAL: 53)) (tpc: foo/bar | msg: Round 53) 112
>#>#>#> *RE*PUBLISHED PID 54 (ATTEMPT: 1 (TOTAL: 54)) (tpc: foo/bar | msg: Round 54) 112
>#>#>#> *RE*PUBLISHED PID 55 (ATTEMPT: 1 (TOTAL: 55)) (tpc: foo/bar | msg: Round 55) 112
>#>#>#> NO PUBACK IN TIME FOR PID 56 (tpc: foo/bar | msg: Round 56) 116
>#>#>#> GOING TO *RE*PUBLISH PID 56 (tpc: foo/bar | msg: Round 56) 116
>#>#>#> NO PUBACK IN TIME FOR PID 57 (tpc: foo/bar | msg: Round 57) 116
>#>#>#> GOING TO *RE*PUBLISH PID 57 (tpc: foo/bar | msg: Round 57) 116
>#>#>#> NO PUBACK IN TIME FOR PID 58 (tpc: foo/bar | msg: Round 58) 116
>#>#>#> GOING TO *RE*PUBLISH PID 58 (tpc: foo/bar | msg: Round 58) 116
>#>#>#> *RE*PUBLISHED PID 56 (ATTEMPT: 1 (TOTAL: 56)) (tpc: foo/bar | msg: Round 56) 116
>#>#>#> NO PUBACK IN TIME FOR PID 59 (tpc: foo/bar | msg: Round 59) 116
>#>#>#> GOING TO *RE*PUBLISH PID 59 (tpc: foo/bar | msg: Round 59) 116
>#>#>#> NO PUBACK IN TIME FOR PID 60 (tpc: foo/bar | msg: Round 60) 116
>#>#>#> GOING TO *RE*PUBLISH PID 60 (tpc: foo/bar | msg: Round 60) 116
>#>#>#> *RE*PUBLISHED PID 57 (ATTEMPT: 1 (TOTAL: 57)) (tpc: foo/bar | msg: Round 57) 116
>#>#>#> *RE*PUBLISHED PID 58 (ATTEMPT: 1 (TOTAL: 58)) (tpc: foo/bar | msg: Round 58) 116
>#>#>#> *RE*PUBLISHED PID 59 (ATTEMPT: 1 (TOTAL: 59)) (tpc: foo/bar | msg: Round 59) 116
>#>#>#> *RE*PUBLISHED PID 60 (ATTEMPT: 1 (TOTAL: 60)) (tpc: foo/bar | msg: Round 60) 116
+++ TMR INT TRIGGERED 117
|| Starting asyncfun() 117
|| Scheduling 1st set of 5 messages.. 117
-> PUBLISH 117
-> PUBLISH 117
-> PUBLISH 117
-> PUBLISH 117
-> PUBLISH 117
>#>#>#> NO PUBACK IN TIME FOR PID 41 (tpc: foo/bar | msg: Round 41) 117
>#>#>#> GOING TO *RE*PUBLISH PID 41 (tpc: foo/bar | msg: Round 41) 117
>#>#>#> *RE*PUBLISHED PID 41 (ATTEMPT: 3 (TOTAL: 61)) (tpc: foo/bar | msg: Round 41) 117
>#>#>#> NO PUBACK IN TIME FOR PID 43 (tpc: foo/bar | msg: Round 43) 117
>#>#>#> GOING TO *RE*PUBLISH PID 43 (tpc: foo/bar | msg: Round 43) 117
>#>#>#> *RE*PUBLISHED PID 43 (ATTEMPT: 3 (TOTAL: 62)) (tpc: foo/bar | msg: Round 43) 117
>#>#>#> NO PUBACK IN TIME FOR PID 44 (tpc: foo/bar | msg: Round 44) 117
>#>#>#> GOING TO *RE*PUBLISH PID 44 (tpc: foo/bar | msg: Round 44) 117
>#>#>#> NO PUBACK IN TIME FOR PID 42 (tpc: foo/bar | msg: Round 42) 117
>#>#>#> GOING TO *RE*PUBLISH PID 42 (tpc: foo/bar | msg: Round 42) 117
>#>#>#> *RE*PUBLISHED PID 44 (ATTEMPT: 3 (TOTAL: 63)) (tpc: foo/bar | msg: Round 44) 117
>#>#>#> NO PUBACK IN TIME FOR PID 45 (tpc: foo/bar | msg: Round 45) 117
>#>#>#> GOING TO *RE*PUBLISH PID 45 (tpc: foo/bar | msg: Round 45) 117
>#>#>#> *RE*PUBLISHED PID 42 (ATTEMPT: 3 (TOTAL: 64)) (tpc: foo/bar | msg: Round 42) 117
>#>#>#> *RE*PUBLISHED PID 45 (ATTEMPT: 3 (TOTAL: 65)) (tpc: foo/bar | msg: Round 45) 117
>#>#>#> NO PUBACK IN TIME FOR PID 31 (tpc: foo/bar | msg: Round 31) 120
>#>#>#> GOING TO *RE*PUBLISH PID 31 (tpc: foo/bar | msg: Round 31) 120
>#>#>#> NO PUBACK IN TIME FOR PID 32 (tpc: foo/bar | msg: Round 32) 120
>#>#>#> GOING TO *RE*PUBLISH PID 32 (tpc: foo/bar | msg: Round 32) 120
>#>#>#> *RE*PUBLISHED PID 31 (ATTEMPT: 4 (TOTAL: 66)) (tpc: foo/bar | msg: Round 31) 120
>#>#>#> NO PUBACK IN TIME FOR PID 33 (tpc: foo/bar | msg: Round 33) 120
>#>#>#> GOING TO *RE*PUBLISH PID 33 (tpc: foo/bar | msg: Round 33) 120
>#>#>#> *RE*PUBLISHED PID 32 (ATTEMPT: 4 (TOTAL: 67)) (tpc: foo/bar | msg: Round 32) 120
>#>#>#> *RE*PUBLISHED PID 33 (ATTEMPT: 4 (TOTAL: 68)) (tpc: foo/bar | msg: Round 33) 120
>#>#>#> NO PUBACK IN TIME FOR PID 34 (tpc: foo/bar | msg: Round 34) 120
>#>#>#> GOING TO *RE*PUBLISH PID 34 (tpc: foo/bar | msg: Round 34) 120
>#>#>#> *RE*PUBLISHED PID 34 (ATTEMPT: 4 (TOTAL: 69)) (tpc: foo/bar | msg: Round 34) 121
>#>#>#> NO PUBACK IN TIME FOR PID 37 (tpc: foo/bar | msg: Round 37) 121
>#>#>#> GOING TO *RE*PUBLISH PID 37 (tpc: foo/bar | msg: Round 37) 121
>#>#>#> NO PUBACK IN TIME FOR PID 35 (tpc: foo/bar | msg: Round 35) 121
>#>#>#> GOING TO *RE*PUBLISH PID 35 (tpc: foo/bar | msg: Round 35) 121
>#>#>#> *RE*PUBLISHED PID 37 (ATTEMPT: 4 (TOTAL: 70)) (tpc: foo/bar | msg: Round 37) 121
>#>#>#> NO PUBACK IN TIME FOR PID 38 (tpc: foo/bar | msg: Round 38) 121
>#>#>#> GOING TO *RE*PUBLISH PID 38 (tpc: foo/bar | msg: Round 38) 121
>#>#>#> *RE*PUBLISHED PID 35 (ATTEMPT: 4 (TOTAL: 71)) (tpc: foo/bar | msg: Round 35) 121
>#>#>#> NO PUBACK IN TIME FOR PID 36 (tpc: foo/bar | msg: Round 36) 121
>#>#>#> GOING TO *RE*PUBLISH PID 36 (tpc: foo/bar | msg: Round 36) 121
|| Expected PUBACKs for 1st set of 5 messages to be handled by now 121
|| Scheduling 2nd set of 5 messages.. 121
-> PUBLISH 121
-> PUBLISH 121
-> PUBLISH 121
-> PUBLISH 121
-> PUBLISH 121
>#>#>#> NO PUBACK IN TIME FOR PID 39 (tpc: foo/bar | msg: Round 39) 121
>#>#>#> GOING TO *RE*PUBLISH PID 39 (tpc: foo/bar | msg: Round 39) 121
>#>#>#> *RE*PUBLISHED PID 38 (ATTEMPT: 4 (TOTAL: 72)) (tpc: foo/bar | msg: Round 38) 121
>#>#>#> *RE*PUBLISHED PID 36 (ATTEMPT: 4 (TOTAL: 73)) (tpc: foo/bar | msg: Round 36) 121
>#>#>#> NO PUBACK IN TIME FOR PID 46 (tpc: foo/bar | msg: Round 46) 121
>#>#>#> GOING TO *RE*PUBLISH PID 46 (tpc: foo/bar | msg: Round 46) 121
>#>#>#> *RE*PUBLISHED PID 39 (ATTEMPT: 4 (TOTAL: 74)) (tpc: foo/bar | msg: Round 39) 121
>#>#>#> *RE*PUBLISHED PID 46 (ATTEMPT: 3 (TOTAL: 75)) (tpc: foo/bar | msg: Round 46) 121
>#>#>#> NO PUBACK IN TIME FOR PID 49 (tpc: foo/bar | msg: Round 49) 121
>#>#>#> GOING TO *RE*PUBLISH PID 49 (tpc: foo/bar | msg: Round 49) 121
>#>#>#> NO PUBACK IN TIME FOR PID 47 (tpc: foo/bar | msg: Round 47) 121
>#>#>#> GOING TO *RE*PUBLISH PID 47 (tpc: foo/bar | msg: Round 47) 121
>#>#>#> *RE*PUBLISHED PID 49 (ATTEMPT: 3 (TOTAL: 76)) (tpc: foo/bar | msg: Round 49) 121
>#>#>#> NO PUBACK IN TIME FOR PID 50 (tpc: foo/bar | msg: Round 50) 121
>#>#>#> GOING TO *RE*PUBLISH PID 50 (tpc: foo/bar | msg: Round 50) 121
>#>#>#> *RE*PUBLISHED PID 47 (ATTEMPT: 3 (TOTAL: 77)) (tpc: foo/bar | msg: Round 47) 121
>#>#>#> NO PUBACK IN TIME FOR PID 48 (tpc: foo/bar | msg: Round 48) 121
>#>#>#> GOING TO *RE*PUBLISH PID 48 (tpc: foo/bar | msg: Round 48) 121
>#>#>#> *RE*PUBLISHED PID 50 (ATTEMPT: 3 (TOTAL: 78)) (tpc: foo/bar | msg: Round 50) 121
>#>#>#> *RE*PUBLISHED PID 48 (ATTEMPT: 3 (TOTAL: 79)) (tpc: foo/bar | msg: Round 48) 122
-- MAIN LOOP 122
>#>#>#> NO PUBACK IN TIME FOR PID 51 (tpc: foo/bar | msg: Round 51) 122
>#>#>#> GOING TO *RE*PUBLISH PID 51 (tpc: foo/bar | msg: Round 51) 122
>#>#>#> *RE*PUBLISHED PID 51 (ATTEMPT: 2 (TOTAL: 80)) (tpc: foo/bar | msg: Round 51) 122
>#>#>#> NO PUBACK IN TIME FOR PID 52 (tpc: foo/bar | msg: Round 52) 122
>#>#>#> GOING TO *RE*PUBLISH PID 52 (tpc: foo/bar | msg: Round 52) 122
>#>#>#> *RE*PUBLISHED PID 52 (ATTEMPT: 2 (TOTAL: 81)) (tpc: foo/bar | msg: Round 52) 122
>#>#>#> NO PUBACK IN TIME FOR PID 53 (tpc: foo/bar | msg: Round 53) 122
>#>#>#> GOING TO *RE*PUBLISH PID 53 (tpc: foo/bar | msg: Round 53) 122
>#>#>#> NO PUBACK IN TIME FOR PID 54 (tpc: foo/bar | msg: Round 54) 122
>#>#>#> GOING TO *RE*PUBLISH PID 54 (tpc: foo/bar | msg: Round 54) 122
>#>#>#> NO PUBACK IN TIME FOR PID 55 (tpc: foo/bar | msg: Round 55) 122
>#>#>#> GOING TO *RE*PUBLISH PID 55 (tpc: foo/bar | msg: Round 55) 122
>#>#>#> *RE*PUBLISHED PID 53 (ATTEMPT: 2 (TOTAL: 82)) (tpc: foo/bar | msg: Round 53) 122
>#>#>#> NO PUBACK IN TIME FOR PID 58 (tpc: foo/bar | msg: Round 58) 122
>#>#>#> NO PUBACK IN TIME FOR PID 63 (tpc: foo/bar | msg: Round 63) 122
>#>#>#> NO PUBACK IN TIME FOR PID 42 (tpc: foo/bar | msg: Round 42) 122
>#>#>#> NO PUBACK IN TIME FOR PID 50 (tpc: foo/bar | msg: Round 50) 122
>#>#>#> NO PUBACK IN TIME FOR PID 66 (tpc: foo/bar | msg: Round 66) 122
>#>#>#> NO PUBACK IN TIME FOR PID 57 (tpc: foo/bar | msg: Round 57) 122
>#>#>#> NO PUBACK IN TIME FOR PID 61 (tpc: foo/bar | msg: Round 61) 122
>#>#>#> NO PUBACK IN TIME FOR PID 59 (tpc: foo/bar | msg: Round 59) 122
>#>#>#> NO PUBACK IN TIME FOR PID 32 (tpc: foo/bar | msg: Round 32) 122
>#>#>#> NO PUBACK IN TIME FOR PID 39 (tpc: foo/bar | msg: Round 39) 122
>#>#>#> NO PUBACK IN TIME FOR PID 64 (tpc: foo/bar | msg: Round 64) 122
>#>#>#> NO PUBACK IN TIME FOR PID 62 (tpc: foo/bar | msg: Round 62) 122
>#>#>#> NO PUBACK IN TIME FOR PID 34 (tpc: foo/bar | msg: Round 34) 122
>#>#>#> NO PUBACK IN TIME FOR PID 41 (tpc: foo/bar | msg: Round 41) 122
>#>#>#> NO PUBACK IN TIME FOR PID 37 (tpc: foo/bar | msg: Round 37) 122
>#>#>#> NO PUBACK IN TIME FOR PID 44 (tpc: foo/bar | msg: Round 44) 122
>#>#>#> NO PUBACK IN TIME FOR PID 53 (tpc: foo/bar | msg: Round 53) 122
>#>#>#> NO PUBACK IN TIME FOR PID 52 (tpc: foo/bar | msg: Round 52) 122
>#>#>#> NO PUBACK IN TIME FOR PID 43 (tpc: foo/bar | msg: Round 43) 122
>#>#>#> NO PUBACK IN TIME FOR PID 69 (tpc: foo/bar | msg: Round 69) 122
>#>#>#> NO PUBACK IN TIME FOR PID 47 (tpc: foo/bar | msg: Round 47) 122
>#>#>#> NO PUBACK IN TIME FOR PID 67 (tpc: foo/bar | msg: Round 67) 122
>#>#>#> NO PUBACK IN TIME FOR PID 36 (tpc: foo/bar | msg: Round 36) 122
>#>#>#> NO PUBACK IN TIME FOR PID 31 (tpc: foo/bar | msg: Round 31) 122
>#>#>#> NO PUBACK IN TIME FOR PID 48 (tpc: foo/bar | msg: Round 48) 122
>#>#>#> NO PUBACK IN TIME FOR PID 65 (tpc: foo/bar | msg: Round 65) 122
>#>#>#> NO PUBACK IN TIME FOR PID 56 (tpc: foo/bar | msg: Round 56) 123
>#>#>#> NO PUBACK IN TIME FOR PID 45 (tpc: foo/bar | msg: Round 45) 123
>#>#>#> NO PUBACK IN TIME FOR PID 33 (tpc: foo/bar | msg: Round 33) 123
>#>#>#> NO PUBACK IN TIME FOR PID 35 (tpc: foo/bar | msg: Round 35) 123
>#>#>#> NO PUBACK IN TIME FOR PID 70 (tpc: foo/bar | msg: Round 70) 123
>#>#>#> NO PUBACK IN TIME FOR PID 49 (tpc: foo/bar | msg: Round 49) 123
>#>#>#> NO PUBACK IN TIME FOR PID 46 (tpc: foo/bar | msg: Round 46) 123
>#>#>#> NO PUBACK IN TIME FOR PID 51 (tpc: foo/bar | msg: Round 51) 123
>#>#>#> NO PUBACK IN TIME FOR PID 38 (tpc: foo/bar | msg: Round 38) 123
>#>#>#> NO PUBACK IN TIME FOR PID 68 (tpc: foo/bar | msg: Round 68) 123
>#>#>#> NO PUBACK IN TIME FOR PID 60 (tpc: foo/bar | msg: Round 60) 123
|| Expected PUBACKs for 2nd set of 5 messages to be handled by now 125
|| Finished asyncfun() 125
>#>#>#> NO PUBACK IN TIME FOR PID 40 (tpc: foo/bar | msg: Round 40) 125
++ MQTT CONN CALLBACK 130
Starting timer causing interrupts every 15secs..
>#>#>#> RECEIVED PUBACK FOR PID 71 (tpc: foo/bar | msg: Round 53) 131
-> /PUBLISH 131
>#>#>#> RECEIVED PUBACK FOR PID 72 (tpc: foo/bar | msg: Round 52) 131
-> /PUBLISH 131
>#>#>#> RECEIVED PUBACK FOR PID 73 (tpc: foo/bar | msg: Round 43) 131
-> /PUBLISH 131
>#>#>#> RECEIVED PUBACK FOR PID 74 (tpc: foo/bar | msg: Round 69) 131
-> /PUBLISH 131
-- MAIN LOOP 132
>#>#>#> RECEIVED PUBACK FOR PID 75 (tpc: foo/bar | msg: Round 47) 132
-> /PUBLISH 132
>#>#>#> RECEIVED PUBACK FOR PID 76 (tpc: foo/bar | msg: Round 67) 132
-> /PUBLISH 132
>#>#>#> RECEIVED PUBACK FOR PID 77 (tpc: foo/bar | msg: Round 36) 132
-> /PUBLISH 132
>#>#>#> RECEIVED PUBACK FOR PID 78 (tpc: foo/bar | msg: Round 31) 132
-> /PUBLISH 132
>#>#>#> RECEIVED PUBACK FOR PID 79 (tpc: foo/bar | msg: Round 48) 132
-> /PUBLISH 132
>#>#>#> RECEIVED PUBACK FOR PID 80 (tpc: foo/bar | msg: Round 65) 132
-> /PUBLISH 132
>#>#>#> RECEIVED PUBACK FOR PID 81 (tpc: foo/bar | msg: Round 56) 133
-> /PUBLISH 133
>#>#>#> RECEIVED PUBACK FOR PID 82 (tpc: foo/bar | msg: Round 45) 133
-> /PUBLISH 133
>#>#>#> RECEIVED PUBACK FOR PID 83 (tpc: foo/bar | msg: Round 33) 133
-> /PUBLISH 133
>#>#>#> RECEIVED PUBACK FOR PID 84 (tpc: foo/bar | msg: Round 35) 133
-> /PUBLISH 133
>#>#>#> RECEIVED PUBACK FOR PID 85 (tpc: foo/bar | msg: Round 70) 133
-> /PUBLISH 133
>#>#>#> RECEIVED PUBACK FOR PID 86 (tpc: foo/bar | msg: Round 49) 133
-> /PUBLISH 133
>#>#>#> RECEIVED PUBACK FOR PID 87 (tpc: foo/bar | msg: Round 46) 133
-> /PUBLISH 133
>#>#>#> RECEIVED PUBACK FOR PID 88 (tpc: foo/bar | msg: Round 51) 133
-> /PUBLISH 133
>#>#>#> RECEIVED PUBACK FOR PID 89 (tpc: foo/bar | msg: Round 38) 133
-> /PUBLISH 133
>#>#>#> RECEIVED PUBACK FOR PID 90 (tpc: foo/bar | msg: Round 68) 133
-> /PUBLISH 133
>#>#>#> RECEIVED PUBACK FOR PID 91 (tpc: foo/bar | msg: Round 60) 133
-> /PUBLISH 133
>#>#>#> RECEIVED PUBACK FOR PID 92 (tpc: foo/bar | msg: Round 58) 133
-> /PUBLISH 133
>#>#>#> RECEIVED PUBACK FOR PID 93 (tpc: foo/bar | msg: Round 63) 133
-> /PUBLISH 133
>#>#>#> RECEIVED PUBACK FOR PID 94 (tpc: foo/bar | msg: Round 42) 133
-> /PUBLISH 133
>#>#>#> RECEIVED PUBACK FOR PID 95 (tpc: foo/bar | msg: Round 54) 133
-> /PUBLISH 133
>#>#>#> RECEIVED PUBACK FOR PID 96 (tpc: foo/bar | msg: Round 50) 133
-> /PUBLISH 133
>#>#>#> RECEIVED PUBACK FOR PID 97 (tpc: foo/bar | msg: Round 66) 133
-> /PUBLISH 133
>#>#>#> RECEIVED PUBACK FOR PID 98 (tpc: foo/bar | msg: Round 55) 133
-> /PUBLISH 133
>#>#>#> RECEIVED PUBACK FOR PID 99 (tpc: foo/bar | msg: Round 57) 133
-> /PUBLISH 133
>#>#>#> RECEIVED PUBACK FOR PID 100 (tpc: foo/bar | msg: Round 61) 133
-> /PUBLISH 133
>#>#>#> RECEIVED PUBACK FOR PID 101 (tpc: foo/bar | msg: Round 59) 133
-> /PUBLISH 133
>#>#>#> RECEIVED PUBACK FOR PID 103 (tpc: foo/bar | msg: Round 39) 133
-> /PUBLISH 133
>#>#>#> RECEIVED PUBACK FOR PID 104 (tpc: foo/bar | msg: Round 64) 133
-> /PUBLISH 133
>#>#>#> RECEIVED PUBACK FOR PID 102 (tpc: foo/bar | msg: Round 32) 133
-> /PUBLISH 133
>#>#>#> RECEIVED PUBACK FOR PID 105 (tpc: foo/bar | msg: Round 62) 134
-> /PUBLISH 134
>#>#>#> RECEIVED PUBACK FOR PID 106 (tpc: foo/bar | msg: Round 34) 134
-> /PUBLISH 134
>#>#>#> RECEIVED PUBACK FOR PID 107 (tpc: foo/bar | msg: Round 41) 134
-> /PUBLISH 134
>#>#>#> RECEIVED PUBACK FOR PID 108 (tpc: foo/bar | msg: Round 37) 134
-> /PUBLISH 134
>#>#>#> RECEIVED PUBACK FOR PID 109 (tpc: foo/bar | msg: Round 44) 134
-> /PUBLISH 134
-- MAIN LOOP 142
+++ TMR INT TRIGGERED 145
|| Starting asyncfun() 145
|| Scheduling 1st set of 5 messages.. 145
-> PUBLISH 145
-> PUBLISH 145
-> PUBLISH 145
-> PUBLISH 145
-> PUBLISH 145
>#>#>#> RECEIVED PUBACK FOR PID 110 (tpc: foo/bar | msg: Round 71) 146
-> /PUBLISH 146
>#>#>#> RECEIVED PUBACK FOR PID 111 (tpc: foo/bar | msg: Round 72) 146
-> /PUBLISH 146
>#>#>#> RECEIVED PUBACK FOR PID 112 (tpc: foo/bar | msg: Round 73) 146
-> /PUBLISH 146
>#>#>#> RECEIVED PUBACK FOR PID 113 (tpc: foo/bar | msg: Round 74) 146
-> /PUBLISH 146
>#>#>#> RECEIVED PUBACK FOR PID 114 (tpc: foo/bar | msg: Round 75) 146
-> /PUBLISH 146
|| Expected PUBACKs for 1st set of 5 messages to be handled by now 149
|| Scheduling 2nd set of 5 messages.. 149
-> PUBLISH 149
-> PUBLISH 149
-> PUBLISH 149
-> PUBLISH 149
-> PUBLISH 149
>#>#>#> RECEIVED PUBACK FOR PID 115 (tpc: foo/bar | msg: Round 76) 151
-> /PUBLISH 151
>#>#>#> RECEIVED PUBACK FOR PID 116 (tpc: foo/bar | msg: Round 77) 151
-> /PUBLISH 151
>#>#>#> RECEIVED PUBACK FOR PID 117 (tpc: foo/bar | msg: Round 78) 151
-> /PUBLISH 151
>#>#>#> RECEIVED PUBACK FOR PID 118 (tpc: foo/bar | msg: Round 79) 151
-> /PUBLISH 151
>#>#>#> RECEIVED PUBACK FOR PID 119 (tpc: foo/bar | msg: Round 80) 151
-> /PUBLISH 151
-- MAIN LOOP 152
|| Expected PUBACKs for 2nd set of 5 messages to be handled by now 153
|| Finished asyncfun() 153
+++ TMR INT TRIGGERED 160
|| Starting asyncfun() 160
|| Scheduling 1st set of 5 messages.. 160
-> PUBLISH 160
-> PUBLISH 160
-> PUBLISH 160
-> PUBLISH 160
-> PUBLISH 160
>#>#>#> RECEIVED PUBACK FOR PID 120 (tpc: foo/bar | msg: Round 81) 161
-> /PUBLISH 161
>#>#>#> RECEIVED PUBACK FOR PID 121 (tpc: foo/bar | msg: Round 82) 161
-> /PUBLISH 161
-- MAIN LOOP 162
>#>#>#> RECEIVED PUBACK FOR PID 122 (tpc: foo/bar | msg: Round 83) 162
-> /PUBLISH 162
>#>#>#> RECEIVED PUBACK FOR PID 123 (tpc: foo/bar | msg: Round 84) 162
-> /PUBLISH 162
>#>#>#> RECEIVED PUBACK FOR PID 124 (tpc: foo/bar | msg: Round 85) 162
-> /PUBLISH 162
|| Expected PUBACKs for 1st set of 5 messages to be handled by now 164
|| Scheduling 2nd set of 5 messages.. 164
-> PUBLISH 164
-> PUBLISH 164
-> PUBLISH 164
-> PUBLISH 164
-> PUBLISH 164
>#>#>#> RECEIVED PUBACK FOR PID 125 (tpc: foo/bar | msg: Round 86) 165
-> /PUBLISH 165
>#>#>#> RECEIVED PUBACK FOR PID 126 (tpc: foo/bar | msg: Round 87) 165
-> /PUBLISH 165
>#>#>#> RECEIVED PUBACK FOR PID 127 (tpc: foo/bar | msg: Round 88) 165
-> /PUBLISH 165
>#>#>#> RECEIVED PUBACK FOR PID 128 (tpc: foo/bar | msg: Round 89) 166
-> /PUBLISH 166
>#>#>#> RECEIVED PUBACK FOR PID 129 (tpc: foo/bar | msg: Round 90) 166
-> /PUBLISH 166
|| Expected PUBACKs for 2nd set of 5 messages to be handled by now 168
|| Finished asyncfun() 168
-- MAIN LOOP 172
+++ TMR INT TRIGGERED 175
|| Starting asyncfun() 175
|| Scheduling 1st set of 5 messages.. 175
-> PUBLISH 175
-> PUBLISH 175
-> PUBLISH 175
-> PUBLISH 175
-> PUBLISH 175
>#>#>#> RECEIVED PUBACK FOR PID 130 (tpc: foo/bar | msg: Round 91) 176
-> /PUBLISH 176
>#>#>#> RECEIVED PUBACK FOR PID 131 (tpc: foo/bar | msg: Round 92) 176
-> /PUBLISH 176
>#>#>#> RECEIVED PUBACK FOR PID 132 (tpc: foo/bar | msg: Round 93) 176
-> /PUBLISH 176
>#>#>#> RECEIVED PUBACK FOR PID 133 (tpc: foo/bar | msg: Round 94) 176
-> /PUBLISH 176
>#>#>#> RECEIVED PUBACK FOR PID 134 (tpc: foo/bar | msg: Round 95) 176
-> /PUBLISH 176
|| Expected PUBACKs for 1st set of 5 messages to be handled by now 179
|| Scheduling 2nd set of 5 messages.. 179
-> PUBLISH 179
-> PUBLISH 179
-> PUBLISH 179
-> PUBLISH 179
-> PUBLISH 179
>#>#>#> RECEIVED PUBACK FOR PID 135 (tpc: foo/bar | msg: Round 96) 181
-> /PUBLISH 181
>#>#>#> RECEIVED PUBACK FOR PID 136 (tpc: foo/bar | msg: Round 97) 181
-> /PUBLISH 181
>#>#>#> RECEIVED PUBACK FOR PID 137 (tpc: foo/bar | msg: Round 98) 181
-> /PUBLISH 181
>#>#>#> RECEIVED PUBACK FOR PID 138 (tpc: foo/bar | msg: Round 99) 181
-> /PUBLISH 181
>#>#>#> RECEIVED PUBACK FOR PID 139 (tpc: foo/bar | msg: Round 100) 181
-> /PUBLISH 181
-- MAIN LOOP 182
|| Expected PUBACKs for 2nd set of 5 messages to be handled by now 183
|| Finished asyncfun() 183
+++ TMR INT TRIGGERED 190
|| Starting asyncfun() 190
|| Scheduling 1st set of 5 messages.. 190
-> PUBLISH 190
-> PUBLISH 190
-> PUBLISH 190
-> PUBLISH 190
-> PUBLISH 190
>#>#>#> RECEIVED PUBACK FOR PID 140 (tpc: foo/bar | msg: Round 101) 191
-> /PUBLISH 191
>#>#>#> RECEIVED PUBACK FOR PID 141 (tpc: foo/bar | msg: Round 102) 191
-> /PUBLISH 191
>#>#>#> RECEIVED PUBACK FOR PID 142 (tpc: foo/bar | msg: Round 103) 191
-> /PUBLISH 191
>#>#>#> RECEIVED PUBACK FOR PID 143 (tpc: foo/bar | msg: Round 104) 191
-> /PUBLISH 191
>#>#>#> RECEIVED PUBACK FOR PID 144 (tpc: foo/bar | msg: Round 105) 191
-> /PUBLISH 191
-- MAIN LOOP 192
|| Expected PUBACKs for 1st set of 5 messages to be handled by now 194
|| Scheduling 2nd set of 5 messages.. 194
-> PUBLISH 194
-> PUBLISH 194
-> PUBLISH 194
-> PUBLISH 194
-> PUBLISH 194
>#>#>#> RECEIVED PUBACK FOR PID 145 (tpc: foo/bar | msg: Round 106) 196
-> /PUBLISH 196
>#>#>#> RECEIVED PUBACK FOR PID 146 (tpc: foo/bar | msg: Round 107) 196
-> /PUBLISH 196
>#>#>#> RECEIVED PUBACK FOR PID 147 (tpc: foo/bar | msg: Round 108) 196
-> /PUBLISH 196
>#>#>#> RECEIVED PUBACK FOR PID 148 (tpc: foo/bar | msg: Round 109) 196
-> /PUBLISH 196
>#>#>#> RECEIVED PUBACK FOR PID 149 (tpc: foo/bar | msg: Round 110) 196
-> /PUBLISH 196
|| Expected PUBACKs for 2nd set of 5 messages to be handled by now 198
|| Finished asyncfun() 198
-- MAIN LOOP 202
+++ TMR INT TRIGGERED 205
|| Starting asyncfun() 205
|| Scheduling 1st set of 5 messages.. 205
-> PUBLISH 205
-> PUBLISH 205
-> PUBLISH 205
-> PUBLISH 205
-> PUBLISH 205
>#>#>#> RECEIVED PUBACK FOR PID 150 (tpc: foo/bar | msg: Round 111) 206
-> /PUBLISH 206
>#>#>#> RECEIVED PUBACK FOR PID 151 (tpc: foo/bar | msg: Round 112) 206
-> /PUBLISH 206
>#>#>#> RECEIVED PUBACK FOR PID 152 (tpc: foo/bar | msg: Round 113) 206
-> /PUBLISH 206
>#>#>#> RECEIVED PUBACK FOR PID 153 (tpc: foo/bar | msg: Round 114) 206
-> /PUBLISH 206
>#>#>#> RECEIVED PUBACK FOR PID 154 (tpc: foo/bar | msg: Round 115) 206
-> /PUBLISH 206
|| Expected PUBACKs for 1st set of 5 messages to be handled by now 209
|| Scheduling 2nd set of 5 messages.. 209
-> PUBLISH 209
-> PUBLISH 209
-> PUBLISH 209
-> PUBLISH 209
-> PUBLISH 209
>#>#>#> RECEIVED PUBACK FOR PID 155 (tpc: foo/bar | msg: Round 116) 211
-> /PUBLISH 211
>#>#>#> RECEIVED PUBACK FOR PID 156 (tpc: foo/bar | msg: Round 117) 211
-> /PUBLISH 211
>#>#>#> RECEIVED PUBACK FOR PID 157 (tpc: foo/bar | msg: Round 118) 211
-> /PUBLISH 211
>#>#>#> RECEIVED PUBACK FOR PID 158 (tpc: foo/bar | msg: Round 119) 211
-> /PUBLISH 211
>#>#>#> RECEIVED PUBACK FOR PID 159 (tpc: foo/bar | msg: Round 120) 211
-> /PUBLISH 211
-- MAIN LOOP 212
|| Expected PUBACKs for 2nd set of 5 messages to be handled by now 213
|| Finished asyncfun() 213
+++ TMR INT TRIGGERED 220
|| Starting asyncfun() 220
|| Scheduling 1st set of 5 messages.. 220
-> PUBLISH 220
-> PUBLISH 220
-> PUBLISH 220
-> PUBLISH 220
-> PUBLISH 220
-- MAIN LOOP 222
|| Expected PUBACKs for 1st set of 5 messages to be handled by now 224
|| Scheduling 2nd set of 5 messages.. 224
-> PUBLISH 224
-> PUBLISH 224
-> PUBLISH 224
-> PUBLISH 224
-> PUBLISH 224
|| Expected PUBACKs for 2nd set of 5 messages to be handled by now 228
|| Finished asyncfun() 228
assertion "mp_obj_is_small_int(args[2])" failed: file "../../extmod/moduasyncio.c", line 103, function: task_queue_push_sorted
abort() was called at PC 0x4016b75f on core 0

ELF file SHA256: 0000000000000000

Backtrace: 0x4009ae74:0x3ffce180 0x4009b269:0x3ffce1a0 0x4016b75f:0x3ffce1c0 0x400ee1c6:0x3ffce1f0 0x400e388a:0x3ffce210 0x400df7ed:0x3ffce240 0x400df915:0x3ffce260 0x400ed141:0x3ffce280 0x400e3944:0x3ffce320 0x400df7ed:0x3ffce390 0x400df915:0x3ffce3b0 0x400dfa8b:0x3ffce3d0 0x400ed319:0x3ffce410 0x400e3c67:0x3ffce4b0 0x400e3cc9:0x3ffce4d0 0x400e3d38:0x3ffce500 0x400e37f5:0x3ffce520 0x400df7ed:0x3ffce540 0x400df915:0x3ffce560 0x400ed141:0x3ffce580 0x400e3944:0x3ffce620 0x400df7ed:0x3ffce650 0x400ed0b9:0x3ffce670 0x400e3944:0x3ffce710 0x400df7ed:0x3ffce780 0x400df915:0x3ffce7a0 0x400ed141:0x3ffce7c0 0x400e3944:0x3ffce860 0x400df7ed:0x3ffce8c0 0x400df816:0x3ffce8e0 0x400df88b:0x3ffce900 0x400ea521:0x3ffce990 0x400ea857:0x3ffce9c0 0x400df992:0x3ffceaa0 0x400ed3a5:0x3ffceae0 0x400e3944:0x3ffceb80 0x400df7ed:0x3ffcebe0 0x400df816:0x3ffcec00 0x40104c52:0x3ffcec20 0x40104f74:0x3ffcecb0 0x400f60dc:0x3ffcecf0 0x4009b831:0x3ffced20

Rebooting...
MicroPython v1.14 on 2021-02-02; ESP32 module with ESP32
Type "help()" for more information.

[peterhinch]

Your use of uasyncio is (in my opinion) highly unorthodox, in particular scheduling a coroutine from an interrupt. I have never tried this and I suspect it's a bad idea. In the discussions on uasyncio I don't think this was ever considered as a possible design pattern. Bear in mind that CPython does not support interrupts and uasyncio seeks to be a micro version of asyncio.

In my designs a uasyncio application has only one instance of uasyncio.run(): this starts the whole application and, in typical firmware applications, never actually returns. I would definitely remove the timer: uasyncio has its own means of scheduling coroutines - that is its purpose.

The other thing to bear in mind with public brokers is latency, which depends on the quality of your internet connection. While mqtt_as allows concurrent publications, if communications are slow it is safer to await qos==1 publications: concurrent publications risk spawning multiple coroutines all waiting on PUBACK packets. However I would fix the other issues first, as I think the timer code is the most likely to be the source of the problem.

[mirko]

Thanks for your very helpful answer and clarification. Re public broker and delay: I'm also experiencing this issue with a mosquitto setup in the same LAN, public broker only used for being able to have a minimal test which can be just run. Also the timer is solely used for this test to be able to just run, work and reproduce the issue I experience in a slightly different scenario. My real use case: the ISR (intrpt()) is not triggered by a timer, but by an GPIO (Pin(23, Pin.IN).irq(handler=intrpt, trigger=Pin.IRQ_FALLING)). Internally, at least on ESP32, both ISRs are executed/scheduled the same way, via mp_sched_schedule() (that's why I substituted the GPIO with the Timer while still experiencing the issue). When you say now, the timer is the issue, then migh high-level question would be: how do I run async code (in particular: how to I publish MQTT messages) once a GPIO got triggered (on falling edge)?

[amotl]

Dear Mirko and Peter,

thanks a stack for this discussion. I believe it is very much on the spot.

So, while I also second Peter that it is probably not a good idea to publish MQTT messages directly from within an interrupt handler, I would very much appreciate to see a respective full working example program which resonates with Mirko's use case.

Thoughts

On vanilla CPython, I would use queue.Queue in a threading scenario and asyncio.Queue in an asyncio scenario in order to connect both worlds. In other words, the interrupt handler would put messages into the queue which would be drained by an MQTT publishing/communication loop living within the main thread.

Something along the lines of:

queue = asyncio.Queue()

def interrupt_handler():
    message = "Hello world"
    queue.put_nowait(message)

async def communication_loop():
    while True:
        message = await queue.get()
        await mqtt.publish("foo/bar", message, qos=1)

Searching for uasyncio.Queue

However, I don't know whether MicroPython's uasyncio implementation actually provides a Queue class [1]. While @peterhinch's micropython-async implementation has something at [2], I haven't been able to find back a pendant with @dpgeorge's uasyncio v3 implementation quickly , but didn't investigate further.

Patches and respective discussions at https://github.com/micropython/micropython/pull/6125 and https://github.com/micropython/micropython/pull/6515 as well as [4] might be related.

Maybe you can just use @peterhinch's primitives.queue.Queue class [5] based on @pfalcon's original uasyncio.queues.Queue implementation [6] and add it to your userspace code?

Keep up the spirit and with kind regards, Andreas.

[1] Unfortunately, I haven't been able to play with the recent excellent releases of vanilla MicroPython yet, because the last time we worked with it, we've been stuck with Pycom MicroPython 1.11 as this is very much behind mainline development, which I consider a very unfortunate situation. But, well, C'est la vie. [2] https://github.com/peterhinch/micropython-async/blob/master/v3/docs/TUTORIAL.md#35-queue [3] https://docs.micropython.org/en/latest/library/uasyncio.html [4] Something like Threading/Queue in MicroPython?: https://forum.micropython.org/viewtopic.php?t=6084 [5] https://github.com/peterhinch/micropython-async/blob/master/v3/primitives/queue.py [6] https://github.com/micropython/micropython-lib/blob/master/uasyncio.queues/uasyncio/queues.py

[mirko]

Maybe you can just use @peterhinch's primitives.Queue class [5] based on @pfalcon's original uasyncio.queues.Queue implementation [6] and add it to your userspace code?

That sounds quite promising, however clearly I'm struggling with how to use asyncio and its concepts, as my first test code again does not what I'd have expected:

import uasyncio as asyncio
from primitives import queue

q = queue.Queue()

async def main_loop():
    global q
    while True:
        print("-- MAIN LOOP")
        res = await q.get()
        print(res)
        await asyncio.sleep(1)
        print("End of round in in main loop.")

asyncio.run(main_loop())
print("Dropped out of main loop - why?")

drops out of the main loop after its first round:

>>> import test
-- MAIN LOOP
Dropped out of main loop - why?
>>>

Happy for any pointers on how to make myself familiar in a way that I'm not puzzled by such behaviour anymore.

[amotl]

Hi Mirko,

while I am not having any MCU at hand, I tried your example slightly modified for vanilla CPython and it also bailed out like

RuntimeError: Task <Task pending name='Task-1' coro=<main_loop() running at testme.py:9> cb=[_run_until_complete_cb() at /Users/amo/.pyenv/versions/3.8.6/lib/python3.8/asyncio/base_events.py:184]>
got Future <Future pending> attached to a different loop

Stack Overflow to the rescue, I have been able to find [1]:

Your queues must be created inside the loop. You created them outside the loop created for asyncio.run(), so they use events.get_event_loop(). asyncio.run() creates a new loop, and futures created for the queue in one loop can't then be used in the other.

So, with this modification, the example would work on CPython - at least it will neither croak nor drop out of the main loop. Maybe it also does work on MicroPython?

import asyncio

q = None

async def main_loop():
    global q
    q = asyncio.Queue()
    while True:
        print("-- MAIN LOOP")
        res = await q.get()
        print(res)
        await asyncio.sleep(1)
        print("End of round in in main loop.")

asyncio.run(main_loop())
print("Dropped out of main loop - why?")

With kind regards, Andreas.

[1] https://stackoverflow.com/questions/53724665/using-queues-results-in-asyncio-exception-got-future-future-pending-attached/53724990#53724990

[kevinkk525]

This is a special case in micropython uasyncio not being interrupt aware. The moment you call "res=await q.get()" the uasyncio task will get paused until an item is available in the queue. To do that, the task is being removed from the main loop and parked at the queue object. But now the main uasyncio loop is empty and uasyncio will exit (there would be no way to fill that queue. At least not without interrupts but uasyncio is not aware of those - yet). It will work if you have a simple other task running like:

async def do_nothing():
    while True:
        await asyncio.sleep(1)

This behaviour might puzzle you during testing but in a real program you'd actually never have a single task waiting for a queue. That would make uasyncio completely useless and you could program without uasyncio. But for testing this is indeed a case where it surprises you.

[mirko]

EDIT: This comment was written before @kevinkk525's answer (https://github.com/peterhinch/micropython-mqtt/issues/54#issuecomment-778646752) and as a reply to @amotl (https://github.com/peterhinch/micropython-mqtt/issues/54#issuecomment-778645857)

Your queues must be created inside the loop. You created them outside the loop created for asyncio.run(), so they use events.get_event_loop(). asyncio.run() creates a new loop, and futures created for the queue in one loop can't then be used in the other.

With the following code it still drops out unfortunately:

import uasyncio as asyncio
from primitives import queue

q = None

async def main_loop():
    global q
    q = queue.Queue()
    while True:
        print("-- MAIN LOOP")
        res = await q.get()
        print(res)
        await asyncio.sleep(1)
        print("End of round in in main loop.")

asyncio.run(main_loop())
print("Dropped out of main loop - why?")

[peterhinch]

The issue of interfacing uasyncio and interrupts is under discussion. One proposal is that it will be possible to trigger an Event from a soft IRQ, but this is currently unsupported. @jimmo has proposed another solution using the stream mechanism. Until an official solution emerges, the only safe way is to have the hard ISR set a flag which is polled by a coroutine. My Message primitive does this. Not very efficient, but it's currently the only safe way.

Re Queue this version is compatible with uasyncio V3: I suggest you use this until an official version is released.

Regarding the code sample, I think this may be a bug in the Event class connected with the fact that only one task is running. With a second task, everything works as expected. I will try to produce a minimal test case and raise an issue. This runs on a Pyboard:

import uasyncio as asyncio
from primitives import queue

q = queue.Queue()

async def main_loop():
    while True:
        print("-- MAIN LOOP")
        res = await q.get()
        print(res)
        await asyncio.sleep(1)
        print("End of round in in main loop.")

async def main():
    asyncio.create_task(main_loop())
    for _ in range(5):
        await asyncio.sleep(1)  # Waits here as expected
    await q.put(1)
    while True:
        await asyncio.sleep(1)

asyncio.run(main())

[kevinkk525]

@peterhinch the issue of uasyncio exiting is already open since uasyncio v3 was released: https://github.com/micropython/micropython/issues/5843

[peterhinch]

Ah, thank you. I had a feeling I'd come across this before but couldn't find the issue.