"keepalive" pings do not keep the connection alive with esp32spi

[dlizotte-uwo]

If I connect to a broker, subscribe to a topic, and no messages arrive from the broker within keep_alive seconds, an exception is thrown and the object disconnects. Pings are not sent to the broker to keep the connection alive.

This happens because loop() is actually blocking in the esp32spi implementation, and so doesn't get a chance to send/receive a ping to reset the object's timestamp.

loop() is blocking because _wait_for_msg() is blocking, which is because _sock_exact_recv() is blocking as currently implemented, I think just in the ESP32SPI implementation without socketpool. (Also note _sock_exact_recv() is defined twice in the file, once around line 312 and again at 894.) It's a bit weird because the timeout sent to loop() is applied to self._sock but then _wait_for_msg overwrites that (if it succeeds) with its own timeout. Either way the code in _sock_exact_recv for ESP32SPI waits for keep_alive seconds and then throws an exception, which defeats loop's ability to ping and reset the timestamp. I don't know what the "right behaviour" should be in this whole setup.

I am using a MatrixPortal with esp32spi.

[brentru]

Hi, thanks for filing an issue. I need some information in order to help replicate and fix this issue...

Which broker are you connecting to? What KeepAlive time are you specifying?

an exception is thrown and the object disconnects

Could you attach the REPL log when this happens so I can see which exception is thrown, and exactly where?

(Also note _sock_exact_recv() is defined twice in the file, once around line 312 and again at 894.)

This is not correct and will be addressed in a subsequent PR by removing the _sock_exact_recv() implementation which doesn't include compat. for socket pool.
https://github.com/adafruit/Adafruit_CircuitPython_MiniMQTT/blob/master/adafruit_minimqtt/adafruit_minimqtt.py#L312

[dlizotte-uwo]

Hi; I'm connecting to a local broker, no security. (Broker is mosquitto on a mac.) It connects fine, and as long as the matrixportal gets a message within the keepalive time (like if I post every so often with mosquitto_pub) it stays connected and works reliably.

I've tried a few different KeepAlives; the exception is raised always KeepAlive seconds after the last message was received. Here's the exception:

Traceback (most recent call last):
  File "code.py", line 259, in <module>
  File "code.py", line 255, in <module>
  File "adafruit_minimqtt/adafruit_minimqtt.py", line 813, in loop
  File "adafruit_minimqtt/adafruit_minimqtt.py", line 831, in _wait_for_msg
  File "adafruit_minimqtt/adafruit_minimqtt.py", line 826, in _wait_for_msg
  File "adafruit_minimqtt/adafruit_minimqtt.py", line 923, in _sock_exact_recv
MMQTTException: Unable to receive 1 bytes within 60 seconds.

[dlizotte-uwo]

Here's a minimal-ish example that you can also use to see the logging issue as well by changing from INFO to DEBUG.

# ON AIR sign when I'm on Zoom...
# Runs on Airlift Metro M4 with 64x32 RGB Matrix display & shield

import time
import board
import displayio
from adafruit_matrixportal.matrixportal import MatrixPortal
from adafruit_matrixportal.network import Network

import adafruit_esp32spi.adafruit_esp32spi_socket as socket
import adafruit_minimqtt.adafruit_minimqtt as MQTT

import adafruit_logging as logging

# Get wifi details and more from a secrets.py file
try:
    from secrets import secrets
except ImportError:
    print("WiFi secrets are kept in secrets.py, please add them there!")
    raise

# --- Display setup ---
matrixportal = MatrixPortal(status_neopixel=board.NEOPIXEL, debug=False)
display = matrixportal.display
network = matrixportal.network
network.connect()

### Code ###
# Define callback methods which are called when events occur
# pylint: disable=unused-argument, redefined-outer-name
def connect(mqtt_client, userdata, flags, rc):
    # This function will be called when the mqtt_client is connected
    # successfully to the broker.
    print("Connected to MQTT Broker!")
    print("Flags: {0}\n RC: {1}".format(flags, rc))


def disconnect(mqtt_client, userdata, rc):
    # This method is called when the mqtt_client disconnects
    # from the broker.
    print("Disconnected from MQTT Broker!")


def subscribe(mqtt_client, userdata, topic, granted_qos):
    # This method is called when the mqtt_client subscribes to a new feed.
    print("Subscribed to {0} with QOS level {1}".format(topic, granted_qos))


def unsubscribe(mqtt_client, userdata, topic, pid):
    # This method is called when the mqtt_client unsubscribes from a feed.
    print("Unsubscribed from {0} with PID {1}".format(topic, pid))


def publish(mqtt_client, userdata, topic, pid):
    # This method is called when the mqtt_client publishes data to a feed.
    print("Published to {0} with PID {1}".format(topic, pid))


def message(client, topic, message):
    # Method callled when a client's subscribed feed has a new value.
    print("New message on topic {0}: {1}".format(topic, message))

# Set socket for MQTT
MQTT.set_socket(socket, network._wifi.esp)

# Set up a MiniMQTT Client
mqtt_client = MQTT.MQTT(
    broker=secrets["mqtt_broker"],
    port=secrets["mqtt_port"],
    is_ssl = False,
)

# Setting logging level to DEBUG raises exception
# when bytearray is formatted using %x
mqtt_client.enable_logger(logging,logging.INFO)

# Connect callback handlers to mqtt_client
mqtt_client.on_connect = connect
mqtt_client.on_disconnect = disconnect
mqtt_client.on_subscribe = subscribe
mqtt_client.on_unsubscribe = unsubscribe
mqtt_client.on_publish = publish
mqtt_client.on_message = message

mqtt_topic = "display/mode"

print("Attempting to connect to %s" % mqtt_client.broker)
mqtt_client.connect()

print("Subscribing to %s" % mqtt_topic)
mqtt_client.subscribe(mqtt_topic)

while True:
    mqtt_client.loop()

[dlizotte-uwo]

Hi again; here's a modification that is working for me in case it's useful. https://github.com/dlizotte-uwo/Adafruit_CircuitPython_MiniMQTT

[brentru]

@dlizotte-uwo Would you mind opening these changes as a new pull request on this library and tagging me? I'd like to have a discussion around them. I think raising within exact_recv like you're doing in (dlizotte-uwo@1c0f6c8) is a good idea and will fix the blocking issue.

[dlizotte-uwo]

OK - I think I did the PR thing right but I've never done it before so let me know if anything is amiss. 😅

[brentru]

I'm able to replicate hanging on the adafruit io simpletest with esp32spi..

code.py output:
Connecting to WiFi...
Connected!
Connecting to Adafruit IO...
Connected to Adafruit IO! Listening for topic changes on brubell/feeds/onoff

Seems to be hanging in the same place you've pointed out:

  File "/lib/adafruit_minimqtt/adafruit_minimqtt.py", line 826, in _wait_for_msg
  File "/lib/adafruit_minimqtt/adafruit_minimqtt.py", line 918, in _sock_exact_recv

I'll try your PR next #69

[brentru]

Merged into master, closing