recv_timeout should be used as a receive timeout in _sock_exact_recv()

[vladak]

socket_timeout is period which the underlying implementation will break out from a "select" loop, "recv_timeout" should be the maximum period for which to wait for data from the server. _sock_exact_recv() however uses keep_alive as a receive timeout:

Adafruit_CircuitPython_MiniMQTT/adafruit_minimqtt/adafruit_minimqtt.py

Lines 1118 to 1127 in 1c25441

	read_timeout = self.keep_alive
	mv = mv[recv_len:]
	while to_read > 0:
	recv_len = self._sock.recv_into(mv, to_read)
	to_read -= recv_len
	mv = mv[recv_len:]
	if time.monotonic() - stamp > read_timeout:
	raise MMQTTException(
	f"Unable to receive {to_read} bytes within {read_timeout} seconds."
	)

By default socket_timeout is 1 second, recv_timeout is 10 seconds and keep_alive is 60 seconds.
As a result, when a server disconnects the client and the client pings it, it will take 60 seconds for the client to discover that the connection is unresponsive. Instead, recv_timeout should be used. The way I understand it is that keep alive is server side feature and should not trump receive timeout on the client.

The fix would simplify the various No data ... MMQTTExceptions used throughout the code.

[vladak]

Code to reproduce the issue with (assumes the server behaves according to the MQTT spec and disconnects the client after the keep alive timeout):

#!/usr/bin/env python3

import logging
import socket
import ssl
import time
import pytest

import adafruit_minimqtt.adafruit_minimqtt as MQTT


def test_keepalive(keep_alive_timeout):
    logging.basicConfig(format='%(asctime)s.%(msecs)03d %(levelname)s %(module)s - %(funcName)s: %(message)s',
                        datefmt='%H:%M:%S')
    logger = logging.getLogger(__name__)
    logger.setLevel(logging.DEBUG)

    host = "localhost"
    port = 1883
    mqtt_client = MQTT.MQTT(
        broker=host,
        port=port,
        socket_pool=socket,
        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()

    delay = 2 * keep_alive_timeout
    logger.debug(f"sleeping for {delay} seconds")
    time.sleep(delay)
    logger.debug("pinging the server")
    try:
        mqtt_client.ping()
    except MQTT.MMQTTException as e:
        logger.error(f"ping failed", exc_info=e)

test_keepalive(16)

The output looks like this:

22:55:41.240 DEBUG mq - test_keepalive: connecting with keep alive = 16
22:55:41.240 DEBUG adafruit_minimqtt - connect: Attempting to connect to MQTT broker (attempt #0)
22:55:41.240 DEBUG adafruit_minimqtt - _connect: Attempting to establish MQTT connection...
22:55:41.240 INFO adafruit_minimqtt - _get_connect_socket: Establishing an INSECURE connection to localhost:1883
22:55:41.241 DEBUG adafruit_minimqtt - _connect: Sending CONNECT to broker...
22:55:41.241 DEBUG adafruit_minimqtt - _connect: Fixed Header: bytearray(b'\x10\x14\x00')
22:55:41.241 DEBUG adafruit_minimqtt - _connect: Variable Header: bytearray(b'\x04MQTT\x04\x02\x00\x10')
22:55:41.241 DEBUG adafruit_minimqtt - _connect: Receiving CONNACK packet from broker
22:55:41.242 DEBUG adafruit_minimqtt - _wait_for_msg: Got message type: 0x20
22:55:41.242 DEBUG adafruit_minimqtt - _reset_reconnect_backoff: Resetting reconnect backoff
22:55:41.242 DEBUG mq - test_keepalive: sleeping for 32 seconds
22:56:13.271 DEBUG mq - test_keepalive: pinging the server
22:56:13.271 DEBUG adafruit_minimqtt - ping: Sending PINGREQ
22:56:29.272 ERROR mq - test_keepalive: ping failed
Traceback (most recent call last):
  File "/home/vkotal/Adafruit_CircuitPython_MiniMQTT/./mq.py", line 40, in test_keepalive
    mqtt_client.ping()
  File "/home/vkotal/Adafruit_CircuitPython_MiniMQTT/adafruit_minimqtt/adafruit_minimqtt.py", line 678, in ping
    rc = self._wait_for_msg()
  File "/home/vkotal/Adafruit_CircuitPython_MiniMQTT/adafruit_minimqtt/adafruit_minimqtt.py", line 1025, in _wait_for_msg
    res = self._sock_exact_recv(1)
  File "/home/vkotal/Adafruit_CircuitPython_MiniMQTT/adafruit_minimqtt/adafruit_minimqtt.py", line 1125, in _sock_exact_recv
    raise MMQTTException(
adafruit_minimqtt.adafruit_minimqtt.MMQTTException: Unable to receive 1 bytes within 16 seconds.

[schaefer01]

I have the same problem and solved it with a workaround/hack. With the hack, the lowest timeout into loop() and not have message dropouts is two seconds (I'm trying to alternate between mqtt polling and reading button presses from an oled). Reply to my issue and I'll provide details.

[vladak]

@schaefer01 I assume you meant issue #175 ?

[schaefer01]

yes, I have a hack that works good enough until there's an official fix.