Client Disconnects from Server on new publish

[sops21]

I'm running an Ethernet Feather Wing and the m4 Express Feather. I'm running the current version of adafruit_minimqtt and adafruit_minimqtt with CircuitPython 6.1.0.

After connecting to a local Mosquitto broker, the client will disconnected after I publish (From another client) to the same subscription. I don't see any error or crashes on the serial monitor, but on my broker log, I see:

"Client Test 2 closed its connection"

After what I assume is the timeout period, I receive "

 MQTT Error ----
 PINGRESP not returned from broker.

" on the serial monitor.

Any thoughts or where I should start to debug?

My test code and current version is below:

PS C:\Users\Jason> python3 -m circup freeze Found device at E:\, running CircuitPython 6.1.0. A newer version of CircuitPython (6.2.0-beta.0) is available. adafruit_debouncer==1.3.8 adafruit_displayio_ssd1306==1.2.3 adafruit_logging==1.2.5 adafruit_requests==1.9.4 neopixel==6.0.1 adafruit_bitmap_font==1.3.3 adafruit_bus_device==5.0.4 adafruit_led_animation==2.5.2 adafruit_character_lcd==3.3.6 adafruit_display_text==2.12.1 adafruit_minimqtt==5.0.0 adafruit_wiznet5k==1.9.0`

# SPDX-FileCopyrightText: 2021 ladyada for Adafruit Industries
# SPDX-License-Identifier: MIT

import board

import time
import terminalio
import sys
import busio
import digitalio
import adafruit_requests as requests
from adafruit_wiznet5k.adafruit_wiznet5k import WIZNET5K
import adafruit_wiznet5k.adafruit_wiznet5k_socket as socket
import adafruit_minimqtt.adafruit_minimqtt as MQTT
from adafruit_minimqtt.adafruit_minimqtt import MMQTTException
import gc

server_ip = "10.21.2.101"
apid = 1

# For Adafruit Ethernet FeatherWing
cs = digitalio.DigitalInOut(board.D10)
# For Particle Ethernet FeatherWing
# cs = digitalio.DigitalInOut(board.D5)
spi_bus = busio.SPI(board.SCK, MOSI=board.MOSI, MISO=board.MISO)

print(gc.mem_free())
# Initialize ethernet interface with DHCP
dhcp_retries = 3
while dhcp_retries:
  try:
    eth = WIZNET5K(spi_bus, cs, debug=False)

    # text_box(row1_label, 0, "Every time you t!", 18)
    break
  except:
    dhcp_retries = dhcp_retries - 1
if not dhcp_retries:
  print("Failed to get IP address from DHCP")

requests.set_socket(socket, eth)

print("Chip Version:", eth.chip)
print("MAC Address:", [hex(i) for i in eth.mac_address])
print("My IP address is:", eth.pretty_ip(eth.ip_address))

# MQTT Begin 
# Setup a feed named 'onoff' for subscribing to changes
onoff_feed = "/feeds/onoff"
#  Define callback methods which are called when events occur
# pylint: disable=unused-argument, redefined-outer-name
def connected(client, userdata, flags, rc):
    # This function will be called when the client is connected
    # successfully to the broker.
    print("Connected to Adafruit IO! Listening for topic changes on %s" % onoff_feed)
    # Subscribe to all changes on the onoff_feed.
    client.subscribe(onoff_feed)

def disconnected(client, userdata, rc):
    # This method is called when the client is disconnected
    print("Disconnected from Adafruit IO!")

def message(client, topic, message):
    # This method is called when a topic the client is subscribed to
    # has a new message.
    print("New message on topic {0}: {1}".format(topic, message))

# Initialize MQTT interface with the ethernet interface
MQTT.set_socket(socket, eth)

# Set up a MiniMQTT Client
# NOTE: We'll need to connect insecurely for ethernet configurations.
mqtt_client = MQTT.MQTT(
    broker=server_ip,
    # username=secrets["aio_username"],
    # password=secrets["aio_key"],
    is_ssl=False,
    client_id='Test2',
    # socket_pool=pool,
    # log=True,
    # keep_alive=15
)
# mqtt_client.set_logger_level("DEBUG")

# Setup the callback methods above
mqtt_client.on_connect = connected
mqtt_client.on_disconnect = disconnected
mqtt_client.on_message = message

# Connect the client to the MQTT broker.
print("Connecting to Adafruit IO...")
try:
    mqtt_client.connect()

except (ValueError, RuntimeError, MMQTTException) as e:
    print("Failed to get connect, retrying\n", e)

    mqtt_client.reconnect()

while True:
    # Keyboard Input
    try:
        mqtt_client.loop()        # Poll the message queue

    except (ValueError, RuntimeError, MMQTTException) as e:
        print("MQTT Error ---- \n", e)
    except (AssertionError,) as e:
        print("Assertion Error ----- \n", e)

    time.sleep(1)

[brentru]

You defined your MQTT topic in the "Adafruit.io style topic" format: onoff_feed = "/feeds/onoff"

Does the same error occur if you change the topic to a standardized MQTT topic format a-la: onoff_feed = "/test/topic"

[sops21]

I replaced onoff_feed = "/feeds/onoff" with onoff_feed = "/test/topic" as far as I can tell, it is having the same result.

This is how I see the disconnect from the server console:

1612813451: Received PUBLISH from Laptop (d0, q0, r0, m0, '/test/topic', ... (1 bytes))
1612813451: Sending PUBLISH to Test2 (d0, q0, r0, m0, '/test/topic', ... (1 bytes))
1612813451: Client Test2 closed its connection.

about a minute after that I start to see this error on the Feather console:

MQTT Error ---- PINGRESP not returned from broker.

If I ctr-c on the Feather console this is what I get: ` Traceback (most recent call last): File "code.py", line 126, in File "code.py", line 121, in File "/lib/adafruit_minimqtt/adafruit_minimqtt.py", line 809, in loop File "/lib/adafruit_minimqtt/adafruit_minimqtt.py", line 574, in ping File "/lib/adafruit_minimqtt/adafruit_minimqtt.py", line 831, in _wait_for_msg File "/lib/adafruit_minimqtt/adafruit_minimqtt.py", line 826, in _wait_for_msg File "/lib/adafruit_minimqtt/adafruit_minimqtt.py", line 909, in _sock_exact_recv File "/lib/adafruit_wiznet5k/adafruit_wiznet5k_socket.py", line 336, in recv_into File "/lib/adafruit_wiznet5k/adafruit_wiznet5k_socket.py", line 286, in recv File "/lib/adafruit_wiznet5k/adafruit_wiznet5k_socket.py", line 391, in available File "/lib/adafruit_wiznet5k/adafruit_wiznet5k.py", line 475, in socket_available File "/lib/adafruit_wiznet5k/adafruit_wiznet5k.py", line 786, in _get_rx_rcv_size File "/lib/adafruit_wiznet5k/adafruit_wiznet5k.py", line 827, in _read_snrx_rsr File "/lib/adafruit_wiznet5k/adafruit_wiznet5k.py", line 876, in _read_socket File "/lib/adafruit_wiznet5k/adafruit_wiznet5k.py", line 437, in read File "adafruit_bus_device/spi_device.py", line 83, in exit KeyboardInterrupt:

Code done running. `

I tried to figure out if it was a timeout issue sending publish commands from anther client constantly to the channel the feather was subscribed to and timed when the feather client would disconnect. It varied from 15 to 45 seconds after connecting to the MQTT server.

[brentru]

This may be related to https://github.com/adafruit/Adafruit_CircuitPython_MiniMQTT/issues/68

[sops21]

I think I have a theory on what is happening. Still trying to come up with a solution. I do believe this is causing the problem with #68

Part 1: self._timestamp is never reset when receiving new messages. This means that the keepalive ping is sent every X seconds. (Where X is the keepalive timeout). I believe this can be fixed by adding self._timestamp = 0 above the return on line 870

Part 2: If self._sock.send(MQTT_PINGREQ) is called, but the MQTT server returns a non ping response. (Because there is a Message queued to send). The MQTT client disconnects from the server.

Part 3: Once disconnected from the server the next time that Ping is called the loop inside Ping:

while rc != MQTT_PINGRESP:
            # print('Waiting')
            rc = self._wait_for_msg()
            if rc:
                rcs.append(rc)
            if time.monotonic() - stamp > ping_timeout:
                raise MMQTTException("PINGRESP not returned from broker.")

gets stuck because it will never receive a response from the server because its disconnected.

[brentru]

@sops21

re: part 1...The timestamp is reset within the loop call (https://github.com/adafruit/Adafruit_CircuitPython_MiniMQTT/blob/master/adafruit_minimqtt/adafruit_minimqtt.py#L810). _wait_for_msg is not meant to be called publicly.

Part 2 and 3 are likely correct, the issue may be with _wait_for_msg's sock_exact_recv call which does not handle the case of a socket timing out. (addressed in https://github.com/dlizotte-uwo/Adafruit_CircuitPython_MiniMQTT/commit/1c0f6c80b203573ae87d280c81d072317af2b747#diff-ed5d6af26d778ffe55c444bd3cc480b8d80c833bc13fc8e300d2fe3f672bf930R912)

[brentru]

@sops21 I did some testing and I believe this is fixed with this pull request: https://github.com/adafruit/Adafruit_CircuitPython_MiniMQTT/pull/69. Could you also try it out?

Previously, on master and an Ethernet Featherwing, I'd get the following output:

code.py output:
Connecting to Adafruit IO...
1023.02: DEBUG - Attempting to establish MQTT connection...
1023.24: DEBUG - Sending CONNECT to broker...
1023.24: DEBUG - Fixed Header: bytearray(b'\x10?\x00')
Variable Header: bytearray(b'\x04MQTT\x04\xc2\x00<')
1023.36: DEBUG - Receiving CONNACK packet from broker
Connected to Adafruit IO! Listening for topic changes on brubell/feeds/onoff
1023.43: DEBUG - SUBSCRIBING to topic brubell/feeds/onoff with QoS 0```
and PINGRESP is not returned.

After applying https://github.com/adafruit/Adafruit_CircuitPython_MiniMQTT/pull/69, I no longer have this issue when connecting to Adafruit IO's MQTT broker:

Connecting to Adafruit IO...
1165.25: DEBUG - Attempting to establish MQTT connection...
1165.37: DEBUG - Sending CONNECT to broker...
1165.38: DEBUG - Fixed Header: bytearray(b'\x10?\x00')
Variable Header: bytearray(b'\x04MQTT\x04\xc2\x00<')
1165.5: DEBUG - Receiving CONNACK packet from broker
Connected to Adafruit IO! Listening for topic changes on brubell/feeds/onoff
1165.56: DEBUG - SUBSCRIBING to topic brubell/feeds/onoff with QoS 0
1226.02: DEBUG - KeepAlive period elapsed - requesting a PINGRESP from the server...
1226.02: DEBUG - Sending PINGREQ
1226.08: DEBUG - Got PINGRESP
1287.49: DEBUG - KeepAlive period elapsed - requesting a PINGRESP from the server...
1287.49: DEBUG - Sending PINGREQ
1287.77: DEBUG - Got PINGRESP
1349.18: DEBUG - KeepAlive period elapsed - requesting a PINGRESP from the server...
1349.18: DEBUG - Sending PINGREQ
1349.23: DEBUG - Got PINGRESP

[sops21]

@brentru I can confirm that this fixed my test as well. Thanks!