Pycom frozen MQTTClient leaks memory when publishing messages under 1.11.0.b1

[rkeiii]

I'm seeing this on a WiPy 2.0 running my own build of 1.11.0.b1. The only changes I made to the firmware was to add datetime into the frozen modules area. In the test case below I didn't even load datetime so I believe that's irrelevant. This same memory leak seems to occur in the last release of the firmware as well when the frozen MQTTClient was introduced (at least that's how it looked to me).

(sysname='WiPy', nodename='WiPy', release='1.11.0.b1', version='063e199 on 2017-12-19', machine='WiPy with ESP32')

• Exact steps to cause this issue

  1. Modify the boot.py and main.py test case below with your own MQTT broker URL, user, pass, WiFi creds, etc.
  2. Transfer the main.py and boot.py onto a WiPy 2.0 running 1.11.0.b1
  3. Reset the WiPi and let it loop sending messages until it runs out of RAM

• Here's the main.py

  
  import MQTTConst
  import micropython
  import gc

from MQTTClient import MQTTClient from machine import Timer

class HeartbeatTimer: def init(self): self._mqtt_client = MQTTClient("tester", True, MQTTConst.MQTTv3_1_1)

    self._mqtt_host = '192.168.1.66'
    self._mqtt_port = 1883
    self._mqtt_topic = 'realtime'
    self._mqtt_user = 'myusername'
    self._mqtt_pass = 'secr3t'
    self._mqtt_qos = 0

    self._iters = 0

    self._mqtt_client.configEndpoint(self._mqtt_host, self._mqtt_port)
    self._mqtt_client._user = self._mqtt_user
    self._mqtt_client._password = self._mqtt_pass
    self._mqtt_client.connect()

    self._alarm = Timer.Alarm(self._wakeup_handler, arg=self, s=0.25, periodic=True)

def _wakeup_handler(self, arg):
    self._iters += 1
    print("iteration", self._iters)
    self._mqtt_client.publish("events", "hello!!", 0, False)
    micropython.mem_info()
    gc.collect()

print("Starting up...")

software versions

print("Version Information: ", os.uname())

create our timer

hbtimer = HeartbeatTimer()

startup is complete so let's take a nap and wait for something to wake us

machine.sleep()

And here's the boot.py

boot.py -- run on boot-up

import os import machine from machine import UART from network import WLAN

???

uart = UART(0, 115200) os.dupterm(uart)

setup WLAN and assign static ip

originallu taken from: http://docs.micropython.org/en/latest/wipy/wipy/tutorial/wlan.html

wlan = WLAN()

if machine.reset_cause() != machine.SOFT_RESET: wlan.init(mode=WLAN.STA)

configuration below MUST match your home router settings!!

wlan.ifconfig(config=('192.168.1.123', '255.255.255.0', '192.168.1.1', '8.8.8.8'))

if not wlan.isconnected():

change the line below to match your network ssid, security and password

wlan.connect('WiFiSSID', auth=(WLAN.WPA2, 'V3RySECRET!'), timeout=5000)
while not wlan.isconnected():
    machine.idle() # save power while waiting

* And here's the beginning and end of a test run showing the problem

rst:0x7 (TG0WDT_SYS_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT) configsip: 0, SPIWP:0xee clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00 mode:DIO, clock div:1 load:0x3fff9028,len:8 load:0x3fff9030,len:1060 load:0x4009fa00,len:0 ho 12 tail 0 room 4 load:0x4009fa00,len:15160 entry 0x400a0644 Starting up... Version Information: (sysname='WiPy', nodename='WiPy', release='1.11.0.b1', version='063e199 on 2017-12-19', machine='WiPy with ESP32') Packet sent. (Length: 44) MicroPython 063e199 on 2017-12-19; WiPy with ESP32 Type "help()" for more information.

iteration 1 stack: 816 out of 5120 GC: total: 67008, used: 26448, free: 40560 No. of 1-blocks: 201, 2-blocks: 21, max blk sz: 512, max free sz: 2529 iteration 2 stack: 816 out of 5120 GC: total: 67008, used: 24992, free: 42016 No. of 1-blocks: 145, 2-blocks: 17, max blk sz: 512, max free sz: 2529 iteration 3 stack: 816 out of 5120 GC: total: 67008, used: 25040, free: 41968 No. of 1-blocks: 146, 2-blocks: 18, max blk sz: 512, max free sz: 2529 iteration 4 stack: 816 out of 5120 GC: total: 67008, used: 25088, free: 41920 No. of 1-blocks: 147, 2-blocks: 19, max blk sz: 512, max free sz: 2529 iteration 5 stack: 816 out of 5120 GC: total: 67008, used: 25152, free: 41856 No. of 1-blocks: 147, 2-blocks: 21, max blk sz: 512, max free sz: 2529 iteration 6 stack: 816 out of 5120 GC: total: 67008, used: 25200, free: 41808 No. of 1-blocks: 148, 2-blocks: 22, max blk sz: 512, max free sz: 2529 iteration 7 ................................................... GC: total: 67008, used: 66272, free: 736 No. of 1-blocks: 908, 2-blocks: 801, max blk sz: 512, max free sz: 38 iteration 831 stack: 816 out of 5120 GC: total: 67008, used: 66256, free: 752 No. of 1-blocks: 905, 2-blocks: 802, max blk sz: 512, max free sz: 38 iteration 832 stack: 816 out of 5120 GC: total: 67008, used: 66288, free: 720 No. of 1-blocks: 905, 2-blocks: 803, max blk sz: 512, max free sz: 38 iteration 833 stack: 816 out of 5120 GC: total: 67008, used: 66336, free: 672 No. of 1-blocks: 906, 2-blocks: 804, max blk sz: 512, max free sz: 36 iteration 834 stack: 816 out of 5120 GC: total: 67008, used: 66384, free: 624 No. of 1-blocks: 907, 2-blocks: 805, max blk sz: 512, max free sz: 33 iteration 835 stack: 816 out of 5120 GC: total: 67008, used: 66432, free: 576 No. of 1-blocks: 908, 2-blocks: 806, max blk sz: 512, max free sz: 30 iteration 836 stack: 816 out of 5120 GC: total: 67008, used: 66480, free: 528 No. of 1-blocks: 909, 2-blocks: 807, max blk sz: 512, max free sz: 27 iteration 837 stack: 816 out of 5120 GC: total: 67008, used: 66528, free: 480 No. of 1-blocks: 910, 2-blocks: 808, max blk sz: 512, max free sz: 24 Packet sent. (Length: 17) iteration 838 stack: 816 out of 5120 GC: total: 67008, used: 66736, free: 272 No. of 1-blocks: 912, 2-blocks: 810, max blk sz: 512, max free sz: 11 iteration 839 stack: 816 out of 5120 GC: total: 67008, used: 66752, free: 256 No. of 1-blocks: 913, 2-blocks: 810, max blk sz: 512, max free sz: 9 iteration 840 stack: 816 out of 5120 GC: total: 67008, used: 66784, free: 224 No. of 1-blocks: 915, 2-blocks: 810, max blk sz: 512, max free sz: 7 iteration 841 stack: 816 out of 5120 GC: total: 67008, used: 66832, free: 176 No. of 1-blocks: 916, 2-blocks: 811, max blk sz: 512, max free sz: 6 iteration 842 stack: 816 out of 5120 GC: total: 67008, used: 66880, free: 128 No. of 1-blocks: 917, 2-blocks: 812, max blk sz: 512, max free sz: 6 iteration 843 stack: 816 out of 5120 GC: total: 67008, used: 66816, free: 192 No. of 1-blocks: 911, 2-blocks: 813, max blk sz: 512, max free sz: 6 iteration 844 Unhandled exception in callback handler Traceback (most recent call last): File "main.py", line 32, in _wakeup_handler File "MQTTClient.py", line 161, in publish MemoryError: iteration 845 Unhandled exception in callback handler Traceback (most recent call last): File "main.py", line 32, in _wakeup_handler File "MQTTClient.py", line 161, in publish MemoryError: iteration 846 Unhandled exception in callback handler Traceback (most recent call last): File "main.py", line 32, in _wakeup_handler File "MQTTClient.py", line 161, in publish MemoryError: iteration 847 Unhandled exception in callback handler Traceback (most recent call last): File "main.py", line 32, in _wakeup_handler File "MQTTClient.py", line 161, in publish MemoryError: iteration 848 Unhandled exception in callback handler Traceback (most recent call last): File "main.py", line 32, in _wakeup_handler File "MQTTClient.py", line 161, in publish MemoryError: iteration 849 Unhandled exception in callback handler Traceback (most recent call last): File "main.py", line 32, in _wakeup_handler File "MQTTClient.py", line 161, in publish MemoryError: iteration 850 stack: 816 out of 5120 GC: total: 67008, used: 66800, free: 208 No. of 1-blocks: 913, 2-blocks: 815, max blk sz: 512, max free sz: 6 iteration 851 stack: 816 out of 5120 GC: total: 67008, used: 66896, free: 112 No. of 1-blocks: 917, 2-blocks: 816, max blk sz: 512, max free sz: 6 iteration 852 stack: 816 out of 5120 GC: total: 67008, used: 66832, free: 176 No. of 1-blocks: 911, 2-blocks: 817, max blk sz: 512, max free sz: 6 iteration 853 Unhandled exception in callback handler Traceback (most recent call last): File "main.py", line 32, in _wakeup_handler File "MQTTClient.py", line 161, in publish MemoryError: iteration 854 Unhandled exception in callback handler Traceback (most recent call last): File "main.py", line 32, in _wakeup_handler File "MQTTClient.py", line 161, in publish MemoryError: iteration 855 stack: 816 out of 5120 GC: total: 67008, used: 66912, free: 96 No. of 1-blocks: 914, 2-blocks: 818, max blk sz: 512, max free sz: 6 iteration 856 Unhandled exception in callback handler Traceback (most recent call last): File "main.py", line 32, in _wakeup_handler File "MQTTClient.py", line 161, in publish MemoryError: iteration 857 Unhandled exception in callback handler Traceback (most recent call last): File "main.py", line 32, in _wakeup_handler File "MQTTClient.py", line 161, in publish MemoryError: Unhandled exception in thread started by Traceback (most recent call last): File "MQTTMsgHandler.py", line 257, in _io_thread_func File "MQTTMsgHandler.py", line 232, in _verify_connection_state File "MQTTMsgHandler.py", line 210, in _send_pingreq File "MQTTMsgHandler.py", line 150, in priority_send File "MQTTMsgHandler.py", line 223, in _send_packet File "MQTTMsgHandler.py", line 220, in _send_packet MemoryError: iteration 858

[rkeiii]

Here's an even shorter main.py removing the class entirely.

import MQTTConst
import micropython
import gc

from MQTTClient import MQTTClient
from machine import Timer

mqtt_client = MQTTClient("tester", True, MQTTConst.MQTTv3_1_1)

def wakeup_handler(none):
    global mqtt_client
    mqtt_client.publish("events", "hello!!", 0, False)
    micropython.mem_info()
    gc.collect()

print("Starting up...")

# software versions
print("Version Information: ", os.uname())

mqtt_host = '192.168.1.66'
mqtt_port = 1883
mqtt_topic = 'realtime'
mqtt_user = 'user'
mqtt_pass = 'pass'
mqtt_qos = 0

mqtt_client.configEndpoint(mqtt_host, mqtt_port)
mqtt_client._user = mqtt_user
mqtt_client._password = mqtt_pass
mqtt_client.connect()

alarm = Timer.Alarm(wakeup_handler, arg=None, s=0.25, periodic=True)

# startup is complete so let's take a nap and wait for something to wake us
machine.sleep()

[rkeiii]

I replaced the Pycom provided MQTTClient with umqtt.simple from micropython-lib and the issue is gone.

Here's the test using umqtt.simple...

#import MQTTConst
import micropython
import gc
from mqtt import MQTTClient

#from MQTTClient import MQTTClient
from machine import Timer

mqtt_host = '192.168.1.66'
mqtt_port = 1883
mqtt_topic = 'realtime'
mqtt_user = 'auser'
mqtt_pass = 'apass'
mqtt_qos = 0

#mqtt_client = MQTTClient("tester", True, MQTTConst.MQTTv3_1_1)
mqtt_client = MQTTClient("umqtt_client", mqtt_host)

def wakeup_handler(none):
    global mqtt_client
    mqtt_client.publish(b"events", b"hello!!")
    micropython.mem_info()
    gc.collect()

print("Starting up...")

# software versions
print("Version Information: ", os.uname())

#mqtt_client.configEndpoint(mqtt_host, mqtt_port)
#mqtt_client._user = mqtt_user      
#mqtt_client._password = mqtt_pass
#mqtt_client.connect()

mqtt_client.user = mqtt_user
mqtt_client.pswd = mqtt_pass
mqtt_client.connect()

alarm = Timer.Alarm(wakeup_handler, arg=None, s=0.25, periodic=True)

# startup is complete so let's take a nap and wait for something to wake us
machine.sleep()

Here's the beginning of an example run...

rst:0x7 (TG0WDT_SYS_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
configsip: 0, SPIWP:0xee
clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
mode:DIO, clock div:1
load:0x3fff9028,len:8
load:0x3fff9030,len:1060
load:0x4009fa00,len:0
ho 12 tail 0 room 4
load:0x4009fa00,len:15160
entry 0x400a0644
Starting up...
Version Information:  (sysname='WiPy', nodename='WiPy', release='1.11.0.b1', version='063e199 on 2017-12-19', machine='WiPy with ESP32')
MicroPython 063e199 on 2017-12-19; WiPy with ESP32
Type "help()" for more information.
>>> stack: 688 out of 5120
GC: total: 67008, used: 17728, free: 49280
 No. of 1-blocks: 147, 2-blocks: 23, max blk sz: 384, max free sz: 2284
stack: 688 out of 5120
GC: total: 67008, used: 15552, free: 51456
 No. of 1-blocks: 75, 2-blocks: 14, max blk sz: 384, max free sz: 2284
stack: 688 out of 5120
GC: total: 67008, used: 15552, free: 51456
 No. of 1-blocks: 75, 2-blocks: 14, max blk sz: 384, max free sz: 2284
stack: 688 out of 5120
GC: total: 67008, used: 15552, free: 51456
 No. of 1-blocks: 75, 2-blocks: 14, max blk sz: 384, max free sz: 2284
stack: 688 out of 5120
GC: total: 67008, used: 15552, free: 51456
 No. of 1-blocks: 75, 2-blocks: 14, max blk sz: 384, max free sz: 2284
stack: 688 out of 5120
GC: total: 67008, used: 15552, free: 51456
 No. of 1-blocks: 75, 2-blocks: 14, max blk sz: 384, max free sz: 2284
stack: 688 out of 5120
GC: total: 67008, used: 15552, free: 51456
 No. of 1-blocks: 75, 2-blocks: 14, max blk sz: 384, max free sz: 2284
stack: 688 out of 5120
GC: total: 67008, used: 15552, free: 51456
 No. of 1-blocks: 75, 2-blocks: 14, max blk sz: 384, max free sz: 2284
stack: 688 out of 5120
GC: total: 67008, used: 15552, free: 51456
 No. of 1-blocks: 75, 2-blocks: 14, max blk sz: 384, max free sz: 2284
stack: 688 out of 5120
GC: total: 67008, used: 15552, free: 51456
 No. of 1-blocks: 75, 2-blocks: 14, max blk sz: 384, max free sz: 2284
stack: 688 out of 5120
GC: total: 67008, used: 15552, free: 51456
 No. of 1-blocks: 75, 2-blocks: 14, max blk sz: 384, max free sz: 2284
stack: 688 out of 5120
GC: total: 67008, used: 15552, free: 51456
 No. of 1-blocks: 75, 2-blocks: 14, max blk sz: 384, max free sz: 2284
stack: 688 out of 5120
GC: total: 67008, used: 15552, free: 51456
 No. of 1-blocks: 75, 2-blocks: 14, max blk sz: 384, max free sz: 2284
stack: 688 out of 5120
GC: total: 67008, used: 15552, free: 51456
 No. of 1-blocks: 75, 2-blocks: 14, max blk sz: 384, max free sz: 2284
stack: 688 out of 5120
GC: total: 67008, used: 15552, free: 51456
 No. of 1-blocks: 75, 2-blocks: 14, max blk sz: 384, max free sz: 2284
stack: 688 out of 5120
GC: total: 67008, used: 15552, free: 51456
 No. of 1-blocks: 75, 2-blocks: 14, max blk sz: 384, max free sz: 2284
stack: 688 out of 5120
GC: total: 67008, used: 15552, free: 51456
 No. of 1-blocks: 75, 2-blocks: 14, max blk sz: 384, max free sz: 2284
stack: 688 out of 5120

[oligauc]

This is not a leakage but your output queue is growing till no memory is left. In your logs i cannot see the line "Packet sent. (Length: XXXX)". Please check the connection to your broker.

The library you are using is AWS compliant and you should interface with the MQTTLib.py file. Please see this link for a usage example: [https://docs.pycom.io/chapter/tutorials/all/aws.html]

If you use the publishing example you should something like this:

Packet sent. (Length: 4) Iteration 1996 GC free 31104 Packet sent. (Length: 34) Received a new message: b'New Message 1996' from topic: b'PublishTopic'

Iteration 1997 GC free 29504 Packet sent. (Length: 4) Iteration 1998 GC free 29056 Packet sent. (Length: 2) Packet sent. (Length: 34) Packet sent. (Length: 34) Received a new message: b'New Message 1997' from topic: b'PublishTopic'

[rkeiii]

Hello @oligauc,

Thank you for pointing out that I was improperly accessing MQTTClient. I'm still learning where all the documentation is.

I've conducted further testing and amended the code to address the points you raised. I believe I'm still seeing the same issue I originally raised and I also have a design concern.

Design Concern: If you connect to a non-existent host in the first place the Pycom MQTT client doesn't seem to raise any exception at all. Am I missing something here? I would also tend to expect client software to send something like ECONNRESET (or whatever) in the event the connection disappears mid-run.

Original Issue: Client still seems to leak memory for some reason even with mqtt_client.configureOfflinePublishQueueing(0) and mqtt_client.configureDrainingFrequency(10). I would expect this to disable publish queuing or at the very least try to empty the queue every 1/10th of a second (and my code only try's to send a message every quarter of a second).

Here's my amended test case code that addresses your points. I ran it against a RabbitMQ broker in my testing.

import MQTTConst
import micropython
import gc

from MQTTLib import AWSIoTMQTTClient as MQTTClient
from machine import Timer

mqtt_client = MQTTClient("tester")

def wakeup_handler(none):
    global mqtt_client
    mqtt_client.publish("events", "hello!!", 0)
    connection_state = mqtt_client._mqttClient._msgHandler.isConnected()
    print("mqtt client connected?: %s" % connection_state)
    micropython.mem_info()
    gc.collect()

print("Starting up...")

# software versions
print("Version Information: ", os.uname())

mqtt_host = '192.168.1.66'
mqtt_port = 1883
mqtt_topic = 'cantbelieve'
mqtt_user = 'donaldtrump'
mqtt_pass = 'ispresident'
mqtt_qos = 0

mqtt_client.configureOfflinePublishQueueing(0)
mqtt_client.configureDrainingFrequency(10)
mqtt_client.configureEndpoint(mqtt_host, mqtt_port)
conn = mqtt_client._mqttClient
conn._user = mqtt_user
conn._password = mqtt_pass

if conn.connect():
    print('MQTT connection succeeded')

alarm = Timer.Alarm(wakeup_handler, arg=None, s=0.25, periodic=True)

# startup is complete so let's take a nap and wait for something to wake us
machine.sleep()

Here's the beginning and end of a sample run...

Starting up...
Version Information:  (sysname='WiPy', nodename='WiPy', release='1.11.0.b1', version='7200c89-dirty on 2017-12-25', machine='WiPy with ES)
Packet sent. (Length: 44)
MQTT connection succeeded
MicroPython 7200c89-dirty on 2017-12-25; WiPy with ESP32
Type "help()" for more information.
>>> mqtt client connected?: True
stack: 704 out of 5120
GC: total: 67008, used: 32128, free: 34880
 No. of 1-blocks: 270, 2-blocks: 37, max blk sz: 512, max free sz: 2177
mqtt client connected?: True
stack: 704 out of 5120
GC: total: 67008, used: 31792, free: 35216
 No. of 1-blocks: 255, 2-blocks: 34, max blk sz: 512, max free sz: 2177
mqtt client connected?: True
stack: 704 out of 5120
GC: total: 67008, used: 31904, free: 35104
 No. of 1-blocks: 258, 2-blocks: 36, max blk sz: 512, max free sz: 2177
mqtt client connected?: True
stack: 704 out of 5120
GC: total: 67008, used: 31872, free: 35136
 No. of 1-blocks: 258, 2-blocks: 35, max blk sz: 512, max free sz: 2177
mqtt client connected?: True
stack: 704 out of 5120
GC: total: 67008, used: 31968, free: 35040
 No. of 1-blocks: 260, 2-blocks: 37, max blk sz: 512, max free sz: 2177
mqtt client connected?: True
stack: 704 out of 5120
GC: total: 67008, used: 32064, free: 34944
 No. of 1-blocks: 262, 2-blocks: 39, max blk sz: 512, max free sz: 2177
mqtt client connected?: True
stack: 704 out of 5120
GC: total: 67008, used: 32128, free: 34880
 No. of 1-blocks: 262, 2-blocks: 41, max blk sz: 512, max free sz: 2175
mqtt client connected?: True
stack: 704 out of 5120
GC: total: 67008, used: 32128, free: 34880
 No. of 1-blocks: 260, 2-blocks: 42, max blk sz: 512, max free sz: 2173
mqtt client connected?: True
stack: 704 out of 5120
GC: total: 67008, used: 32224, free: 34784
 No. of 1-blocks: 260, 2-blocks: 43, max blk sz: 512, max free sz: 2163
mqtt client connected?: True
stack: 704 out of 5120
GC: total: 67008, used: 32224, free: 34784
 No. of 1-blocks: 260, 2-blocks: 43, max blk sz: 512, max free sz: 2163
mqtt client connected?: True
stack: 704 out of 5120
GC: total: 67008, used: 32288, free: 34720
 No. of 1-blocks: 262, 2-blocks: 44, max blk sz: 512, max free sz: 2163
mqtt client connected?: True
stack: 704 out of 5120
GC: total: 67008, used: 32256, free: 34752
 No. of 1-blocks: 265, 2-blocks: 45, max blk sz: 512, max free sz: 2163
Packet sent. (Length: 17)
mqtt client connected?: True
stack: 704 out of 5120
GC: total: 67008, used: 32496, free: 34512
 No. of 1-blocks: 269, 2-blocks: 47, max blk sz: 512, max free sz: 2154
mqtt client connected?: True
stack: 704 out of 5120
GC: total: 67008, used: 32416, free: 34592
 No. of 1-blocks: 264, 2-blocks: 47, max blk sz: 512, max free sz: 2154
mqtt client connected?: True
stack: 704 out of 5120
GC: total: 67008, used: 32512, free: 34496
 No. of 1-blocks: 266, 2-blocks: 49, max blk sz: 512, max free sz: 2154
mqtt client connected?: True
stack: 704 out of 5120
GC: total: 67008, used: 32496, free: 34512
 No. of 1-blocks: 265, 2-blocks: 49, max blk sz: 512, max free sz: 2152
mqtt client connected?: True
stack: 704 out of 5120
GC: total: 67008, used: 32560, free: 34448
 No. of 1-blocks: 265, 2-blocks: 51, max blk sz: 512, max free sz: 2150
mqtt client connected?: True
stack: 704 out of 5120
GC: total: 67008, used: 32704, free: 34304
 No. of 1-blocks: 266, 2-blocks: 53, max blk sz: 512, max free sz: 2136
mqtt client connected?: True
stack: 704 out of 5120
GC: total: 67008, used: 32720, free: 34288
 No. of 1-blocks: 267, 2-blocks: 53, max blk sz: 512, max free sz: 2136
mqtt client connected?: True
stack: 704 out of 5120
GC: total: 67008, used: 32864, free: 34144
 No. of 1-blocks: 272, 2-blocks: 55, max blk sz: 512, max free sz: 2131
mqtt client connected?: True
stack: 704 out of 5120
GC: total: 67008, used: 32912, free: 34096
 No. of 1-blocks: 273, 2-blocks: 56, max blk sz: 512, max free sz: 2129
mqtt client connected?: True
stack: 704 out of 5120
GC: total: 67008, used: 32960, free: 34048
 No. of 1-blocks: 274, 2-blocks: 57, max blk sz: 512, max free sz: 2127
mqtt client connected?: True
stack: 704 out of 5120
GC: total: 67008, used: 33040, free: 33968
 No. of 1-blocks: 275, 2-blocks: 59, max blk sz: 512, max free sz: 2119
mqtt client connected?: True
.....................................................................................................................
stack: 704 out of 5120
GC: total: 67008, used: 65744, free: 1264
 No. of 1-blocks: 840, 2-blocks: 691, max blk sz: 512, max free sz: 76
mqtt client connected?: True
stack: 704 out of 5120
GC: total: 67008, used: 65792, free: 1216
 No. of 1-blocks: 841, 2-blocks: 692, max blk sz: 512, max free sz: 74
mqtt client connected?: True
stack: 704 out of 5120
GC: total: 67008, used: 65824, free: 1184
 No. of 1-blocks: 841, 2-blocks: 693, max blk sz: 512, max free sz: 71
mqtt client connected?: True
stack: 704 out of 5120
GC: total: 67008, used: 65856, free: 1152
 No. of 1-blocks: 843, 2-blocks: 693, max blk sz: 512, max free sz: 69
mqtt client connected?: True
stack: 704 out of 5120
GC: total: 67008, used: 65920, free: 1088
 No. of 1-blocks: 845, 2-blocks: 694, max blk sz: 512, max free sz: 65
mqtt client connected?: True
stack: 704 out of 5120
GC: total: 67008, used: 65968, free: 1040
 No. of 1-blocks: 846, 2-blocks: 695, max blk sz: 512, max free sz: 62
mqtt client connected?: True
stack: 704 out of 5120
GC: total: 67008, used: 66000, free: 1008
 No. of 1-blocks: 846, 2-blocks: 696, max blk sz: 512, max free sz: 60
mqtt client connected?: True
stack: 704 out of 5120
GC: total: 67008, used: 66096, free: 912
 No. of 1-blocks: 848, 2-blocks: 698, max blk sz: 512, max free sz: 52
Packet sent. (Length: 17)
mqtt client connected?: True
stack: 704 out of 5120
GC: total: 67008, used: 66176, free: 832
 No. of 1-blocks: 851, 2-blocks: 699, max blk sz: 512, max free sz: 45
mqtt client connected?: True
stack: 704 out of 5120
GC: total: 67008, used: 66144, free: 864
 No. of 1-blocks: 849, 2-blocks: 699, max blk sz: 512, max free sz: 45
mqtt client connected?: True
stack: 704 out of 5120
GC: total: 67008, used: 66208, free: 800
 No. of 1-blocks: 851, 2-blocks: 700, max blk sz: 512, max free sz: 45
mqtt client connected?: True
stack: 704 out of 5120
GC: total: 67008, used: 66208, free: 800
 No. of 1-blocks: 849, 2-blocks: 701, max blk sz: 512, max free sz: 45
mqtt client connected?: True
stack: 704 out of 5120
GC: total: 67008, used: 66288, free: 720
 No. of 1-blocks: 852, 2-blocks: 702, max blk sz: 512, max free sz: 43
mqtt client connected?: True
stack: 704 out of 5120
GC: total: 67008, used: 66336, free: 672
 No. of 1-blocks: 853, 2-blocks: 703, max blk sz: 512, max free sz: 39
mqtt client connected?: True
stack: 704 out of 5120
GC: total: 67008, used: 66416, free: 592
 No. of 1-blocks: 854, 2-blocks: 705, max blk sz: 512, max free sz: 31
mqtt client connected?: True
stack: 704 out of 5120
GC: total: 67008, used: 66400, free: 608
 No. of 1-blocks: 853, 2-blocks: 705, max blk sz: 512, max free sz: 31
mqtt client connected?: True
stack: 704 out of 5120
GC: total: 67008, used: 66464, free: 544
 No. of 1-blocks: 855, 2-blocks: 706, max blk sz: 512, max free sz: 31
mqtt client connected?: True
stack: 704 out of 5120
GC: total: 67008, used: 66528, free: 480
 No. of 1-blocks: 857, 2-blocks: 707, max blk sz: 512, max free sz: 27
mqtt client connected?: True
stack: 704 out of 5120
GC: total: 67008, used: 66608, free: 400
 No. of 1-blocks: 858, 2-blocks: 709, max blk sz: 512, max free sz: 19
mqtt client connected?: True
stack: 704 out of 5120
GC: total: 67008, used: 66624, free: 384
 No. of 1-blocks: 859, 2-blocks: 709, max blk sz: 512, max free sz: 19
mqtt client connected?: True
stack: 704 out of 5120
GC: total: 67008, used: 66656, free: 352
 No. of 1-blocks: 864, 2-blocks: 711, max blk sz: 512, max free sz: 19
Packet sent. (Length: 17)
mqtt client connected?: True
stack: 704 out of 5120
GC: total: 67008, used: 66768, free: 240
 No. of 1-blocks: 864, 2-blocks: 711, max blk sz: 512, max free sz: 12
mqtt client connected?: True
stack: 704 out of 5120
GC: total: 67008, used: 66752, free: 256
 No. of 1-blocks: 863, 2-blocks: 711, max blk sz: 512, max free sz: 12
mqtt client connected?: True
stack: 704 out of 5120
GC: total: 67008, used: 66768, free: 240
 No. of 1-blocks: 862, 2-blocks: 712, max blk sz: 512, max free sz: 10
mqtt client connected?: True
stack: 704 out of 5120
GC: total: 67008, used: 66816, free: 192
 No. of 1-blocks: 863, 2-blocks: 713, max blk sz: 512, max free sz: 8
mqtt client connected?: True
stack: 704 out of 5120
GC: total: 67008, used: 66832, free: 176
 No. of 1-blocks: 864, 2-blocks: 713, max blk sz: 512, max free sz: 8
mqtt client connected?: True
stack: 704 out of 5120
GC: total: 67008, used: 66848, free: 160
 No. of 1-blocks: 863, 2-blocks: 714, max blk sz: 512, max free sz: 6
mqtt client connected?: True
stack: 704 out of 5120
GC: total: 67008, used: 66912, free: 96
 No. of 1-blocks: 865, 2-blocks: 715, max blk sz: 512, max free sz: 3
mqtt client connected?: True
stack: 704 out of 5120
GC: total: 67008, used: 66960, free: 48
 No. of 1-blocks: 866, 2-blocks: 716, max blk sz: 512, max free sz: 2
mqtt client connected?: True
stack: 704 out of 5120
GC: total: 67008, used: 66928, free: 80
 No. of 1-blocks: 862, 2-blocks: 717, max blk sz: 512, max free sz: 2
Unhandled exception in callback handler
Traceback (most recent call last):
  File "main.py", line 12, in wakeup_handler
  File "MQTTLib.py", line 50, in publish
  File "MQTTClient.py", line 161, in publish
MemoryError: 
Unhandled exception in callback handler
Traceback (most recent call last):
  File "main.py", line 12, in wakeup_handler
  File "MQTTLib.py", line 50, in publish
  File "MQTTClient.py", line 161, in publish
MemoryError: 
Unhandled exception in callback handler
Traceback (most recent call last):
  File "main.py", line 12, in wakeup_handler
  File "MQTTLib.py", line 50, in publish
  File "MQTTClient.py", line 161, in publish
MemoryError: 
Unhandled exception in thread started by <bound_method>
Traceback (most recent call last):
  File "MQTTMsgHandler.py", line 262, in _io_thread_func
  File "MQTTMsgHandler.py", line 223, in _send_packet
  File "MQTTMsgHandler.py", line 220, in _send_packet
MemoryError: 
Unhandled exception in callback handler
Traceback (most recent call last):
  File "main.py", line 12, in wakeup_handler
  File "MQTTLib.py", line 50, in publish
  File "MQTTClient.py", line 161, in publish
MemoryError:

I'm definitely seeing packets get sent in my output but it doesn't seem to occur at the frequency I would expect. Did I not disable queueing/draining properly?

[oligauc]

The MQTT library requires 3 types of connections:

1. Wifi connection to your local router
2. Socket connection to the server
3. Connection to the broker

In the first 2 types, an exception is thrown if something goes wrong. In the 3rd type, conn.connect() will return false

The Pycom MQTT library was designed to work with AWS (Amazon IoT). It takes about 0.05 sec to send a publish request, process the reply and call the callback. You can test this with the chronometer.

In your case you are using the RabbitMQ. RabbitMQ is replying to the connect and ping requests, but it is not sending a reply to the publish request. This is making the receive timeout at 3 sec. If you are connected, the queue does not drop messages. You need to configure the maximum queue size, with a non zero value, to start dropping messages.

[rkeiii]

@oligauc

I don't understand what you're trying to say about there being "3 connections". To the best of my knowledge the socket connection to the server is made directly to RabbitMQ. This is the connection to the broker so there are in fact only two connections, right? In my case they are...

1. Wifi connection from my WiPy 2.0 to my local router
2. Socket connection from my WiPy 2.0 to my local RabbitMQ instance

Regarding the design concern: The client behavior seems extremely odd to me. If you feed the Pycom MQTT client an invalid MQTT host to connect to it will "pretend to connect" and just loop infinitely never even notifying the user there's a problem. This behavior really doesn't seem right to me. Why would this code not throw a sane error like "host not found" or "connection timed out"? It seems wrong for the end user to have to check conn.connect() and then throw a meaningful error because the Pycom code does not. Perhaps I should open a separate issue to address this.

Regarding the original issue: When you say "You need to configure the maximum queue size, with a non zero value, to start dropping messages." are you referring to ie mqtt_client.configureOfflinePublishQueueing(1)?

[oligauc]

The 3 rd connection is a packet. When you call conn.connect() a socket is set up and a connect packet is sent to the MQTT server.

If you try to set up a socket connection to a non existing server an exception is thrown.

[rkeiii]

@oligauc Would you prefer I open a separate issue for the design concern? Does it seem reasonable to you to expect the SocketError to not be suppressed?

This file: https://github.com/pycom/pycom-micropython-sigfox/blob/eca3b714a11c4b84e740a36b4096a20aac3c9be2/esp32/frozen/MQTTMsgHandler.py

At lines 92-99 the socket error is suppressed and not re-thrown. This hides the connection failure from downstream code unless the downstream code explicitly evaluates the return, this does not seem right to me. Why would it be desirable to return a boolean defining success/failure instead of letting the socket error bubble up?

[oligauc]

If the connection to the server is lost (e.g server down) the device re-attempts to connect. Ideally you want the device to recover from any failure instead of just stop working.

[rkeiii]

I definitely agree having the client try to re-establish the connection is a good idea. However, it is not necessary to permanently suppress the exception in order to attempt to re-establish the connection. The code could, for example, try to re-establish the connection N times (N being configurable) and then allow the exception to bubble up.

[danicampora]

The code could, for example, try to re-establish the connection N times (N being configurable) and then allow the exception to bubble up.

I agree, it's a good idea. @oligauc can we do that? Add a maximum number of retries? Thanks.

[oligauc]

@danicampora , @rkeiii

OK i will implement it for the next release