-
Notifications
You must be signed in to change notification settings - Fork 141
Description
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.