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 <bound_method>
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