search

adafruit / Adafruit_CircuitPython_MiniMQTT

MQTT Client Library for CircuitPython
Other
79 stars 50 forks source link

improve ping handling #199

Closed vladak closed 10 months ago

vladak commented 10 months ago

This changes the way how pings are treated. Rather than sending PINGREQ based on how loop() is called, it is based on how messages are sent to the broker (in accordance with the MQTT spec). Also, the ping handling was folded into the loop in loop() to make it work in cases with loop timeouts longer than the keep alive timeout.

I plan to test this on a QtPy.

vladak commented 10 months ago

Tested on my trusty Adafruit CircuitPython 8.2.6 on 2023-09-12; Adafruit QT Py ESP32-S3 no psram with ESP32S3 with:

#!/usr/bin/env python3

"""
test for https://github.com/adafruit/Adafruit_CircuitPython_MiniMQTT/pull/199
"""

import ssl
import time
import wifi
import socketpool

import adafruit_minimqtt.adafruit_minimqtt as MQTT

import adafruit_logging as logging

from secrets import secrets

def main():
    logger = logging.getLogger(__name__)
    logger.setLevel(logging.DEBUG)

    logger.info(f"Connecting to wifi {secrets['SSID']}")
    wifi.radio.connect(secrets["SSID"], secrets["password"], timeout=20)
    logger.info(f"Connected to {secrets['SSID']}")
    logger.debug(f"IP: {wifi.radio.ipv4_address}")

    pool = socketpool.SocketPool(wifi.radio)

    keep_alive_timeout = 8
    host = "172.40.0.3"
    port = 1883
    mqtt_client = MQTT.MQTT(
        broker=host,
        port=port,
    socket_pool=pool,
        ssl_context=ssl.create_default_context(),
        connect_retries=1,
        recv_timeout=5,
        keep_alive=keep_alive_timeout,
    )

    # mqtt_client.logger = logger

    logger.debug(f"connecting with keep alive = {keep_alive_timeout}")
    mqtt_client.connect()

    # Subscribe to something with traffic to be more real. No on_message, tho.
    mqtt_client.subscribe("#")

    logger.info("### loop() with egress MQTT message traffic")
    # No PINGREQ should be sent during this cycle.
    rcs_test = []
    num_iter = 8 * keep_alive_timeout
    for i in range(1, num_iter):
        logger.debug(f"iteration #{i}/{num_iter - 1}")
        mqtt_client.publish("foo", "bar")
        rcs = mqtt_client.loop(1)
    rcs_test.extend(rcs)
    logger.info(f"rcs = {rcs_test}")
    assert 208 not in rcs_test

    # Give the user some time to digest the test result.
    logger.info("### sleeping for 10 seconds")
    time.sleep(10)

    logger.info("### loop() with no egress message traffic and long timeout")
    # Multiple PINGREQs should be sent during this cycle.
    delay = 2 * keep_alive_timeout
    rcs_test = []
    for _ in range(3):
        logger.debug(f"calling loop({delay})")
        try:
            rcs = mqtt_client.loop(delay)
        rcs_test.extend(rcs)
        logger.info(f"Got message types: {rcs}")
        except MQTT.MMQTTException as e:
            logger.error(f"failed: {e}")
    logger.info(f"rcs = {rcs_test}")
    assert 208 in rcs_test

if __name__ == "__main__":
    main()

the output looked like this:

code.py output:
1804.847: INFO - Connecting to wifi XXX
1804.848: INFO - Connected to XXX
1804.850: DEBUG - IP: 172.40.0.23
1804.853: DEBUG - connecting with keep alive = 8
1804.916: INFO - ### loop() with egress MQTT message traffic
1804.918: DEBUG - iteration #1/63
1806.383: DEBUG - iteration #2/63
1807.436: DEBUG - iteration #3/63
1808.456: DEBUG - iteration #4/63
1809.509: DEBUG - iteration #5/63
1810.621: DEBUG - iteration #6/63
1812.141: DEBUG - iteration #7/63
1813.678: DEBUG - iteration #8/63
1814.734: DEBUG - iteration #9/63
1815.791: DEBUG - iteration #10/63
1817.458: DEBUG - iteration #11/63
1818.513: DEBUG - iteration #12/63
1820.208: DEBUG - iteration #13/63
1822.050: DEBUG - iteration #14/63
1823.201: DEBUG - iteration #15/63
1825.043: DEBUG - iteration #16/63
1826.096: DEBUG - iteration #17/63
1827.154: DEBUG - iteration #18/63
1828.423: DEBUG - iteration #19/63
1829.476: DEBUG - iteration #20/63
1830.534: DEBUG - iteration #21/63
1832.176: DEBUG - iteration #22/63
1833.723: DEBUG - iteration #23/63
1834.874: DEBUG - iteration #24/63
1835.927: DEBUG - iteration #25/63
1836.984: DEBUG - iteration #26/63
1838.639: DEBUG - iteration #27/63
1839.703: DEBUG - iteration #28/63
1841.404: DEBUG - iteration #29/63
1842.456: DEBUG - iteration #30/63
1844.168: DEBUG - iteration #31/63
1845.677: DEBUG - iteration #32/63
1846.682: DEBUG - iteration #33/63
1847.776: DEBUG - iteration #34/63
1849.698: DEBUG - iteration #35/63
1850.750: DEBUG - iteration #36/63
1852.462: DEBUG - iteration #37/63
1853.515: DEBUG - iteration #38/63
1854.534: DEBUG - iteration #39/63
1855.587: DEBUG - iteration #40/63
1856.682: DEBUG - iteration #41/63
1858.220: DEBUG - iteration #42/63
1859.429: DEBUG - iteration #43/63
1860.483: DEBUG - iteration #44/63
1861.541: DEBUG - iteration #45/63
1863.430: DEBUG - iteration #46/63
1865.365: DEBUG - iteration #47/63
1866.418: DEBUG - iteration #48/63
1868.128: DEBUG - iteration #49/63
1869.183: DEBUG - iteration #50/63
1870.218: DEBUG - iteration #51/63
1872.044: DEBUG - iteration #52/63
1873.098: DEBUG - iteration #53/63
1874.823: DEBUG - iteration #54/63
1875.884: DEBUG - iteration #55/63
1876.938: DEBUG - iteration #56/63
1878.574: DEBUG - iteration #57/63
1879.625: DEBUG - iteration #58/63
1881.338: DEBUG - iteration #59/63
1882.875: DEBUG - iteration #60/63
1884.176: DEBUG - iteration #61/63
1885.183: DEBUG - iteration #62/63
1886.426: DEBUG - iteration #63/63
1887.485: INFO - rcs = [48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 
48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 
48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 
48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48]
1887.486: INFO - ### sleeping for 10 seconds
1897.488: INFO - ### loop() with no egress message traffic and long timeout
1897.490: DEBUG - calling loop(16)
1913.672: INFO - Got message types: [48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 208, 48, 48, 48, 48, 48, 48, 48, 48, 208, 48, 48, 48, 48, 48, 48, 48, 48, 48]
1913.674: DEBUG - calling loop(16)
1929.796: INFO - Got message types: [48, 208, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 208, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48]
1929.797: DEBUG - calling loop(16)
1945.927: INFO - Got message types: [208, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 208, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48]
1945.929: INFO - rcs = [48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 208, 48, 48, 48, 48, 48, 48, 48, 48, 208, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 208, 48, 4
8, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 208, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 208, 48, 48, 48, 48, 48, 48, 48, 48, 48, 48, 208, 48, 48, 48, 48
, 48, 48, 48, 48, 48, 48, 48, 48, 48]