I've been trying to use the timeout parameter of the UART class and found that its behaviour does not appear to match the description in the documentation https://docs.micropython.org/en/latest/library/machine.UART.html and the actual behaviour is rather odd... so much so that I believe that the timeout parameter is not functioning as intended (i.e. there's a bug).

We've connected our ESP32 to a u-blox SARA-R410M-02B on a SparkFun SARA-R4 Shield via UART. On both 1.14 and 1.19.1 I'm able to use the script below to reproducibly observe in the REPL the following odd behaviour

Steps to Reproduce

1. Import the test script
2. Execute test_UART_timeout()
3. Execute test_UART_timeout(timeout=1000) (or any timeout value in ms)

Actual Result

MicroPython v1.19.1 on 2022-09-13; ESP32 module (spiram) with ESP32
Type "help()" for more information.

>>> from testScript import test_UART_timeout
>>> test_UART_timeout()
modem.read() elapsed time: 0 ms
Modem response: b'AT\r\r\nOK\r\n'

>>> test_UART_timeout(timeout=1000)
modem.read() elapsed time: 1999 ms
Modem response: b'AT\r\r\nOK\r\n'

Note that when the timeout parameter is used the elapsed time is nearly twice the timeout duration, even though there are characters immediately available to read. This occurs for other values, e.g. 100, 10, etc.

The only difference in function calls is that in the first invocation, test_UART_timeout(), instantiates a UART() object without using the timeout keyword-only parameter while the second invocation instantiates the object with the specified timeout period. Identical behaviour is seen when UART.init(timeout=<value> is used to change the timeout parameter value of an object.

I see this behaviour on both 1.14 and 1.19.1 (nightly), so I believe it's a core problem.

Expected Result

MicroPython v1.19.1 on 2022-09-13; ESP32 module (spiram) with ESP32
Type "help()" for more information.

>>> from testScript import test_UART_timeout
>>> test_UART_timeout()
modem.read() elapsed time: 0 ms
Modem response: b'AT\r\r\nOK\r\n'

>>> test_UART_timeout(timeout=1000)
modem.read() elapsed time: 0 ms
Modem response: b'AT\r\r\nOK\r\n'

I would expect:

1. As there are characters immediately available to read, UART.read() with a wait-for-first-character timeout should not wait for the entire timeout period before attempting to read the first character — that's not a timeout it's a wait period.

2. Even if the intended implementation is a wait period, the actual elapsed time when characters are immediately available to read should be, in this example where the read takes less than 1 ms, the wait period and not twice the wait period.

The immediate workaround is to not use the UART timeout parameter and instead to implement a "wait for first character with timeout" loop in the code, as shown in the test script below. That seems rather redundant, when there's supposed to be a timeout parameter which "specifies the time to wait for the first character (in ms)."

Test Script

Save this as testScript.py for this example and copy it to the target system:

import sys
import time
from machine import UART

# GPIO and SARA-R4 configuration
MODEM_TX_PIN = 27
MODEM_RX_PIN = 26
MODEM_DEFAULT_BAUD = 115200
MODEM_STANDARD_TIMEOUT = 1000  # Standard AT command time out

def test_UART_timeout(timeout=None):

    if timeout == None:
        modem = UART(1, MODEM_DEFAULT_BAUD, bits=8, parity=None, stop=1, tx=MODEM_TX_PIN, rx=MODEM_RX_PIN)
    else:
        modem = UART(1, MODEM_DEFAULT_BAUD, bits=8, parity=None, stop=1, tx=MODEM_TX_PIN, rx=MODEM_RX_PIN, timeout=timeout)

    modem.write("AT\r")  # Simplest modem command, response should be `AT\r\r\nOK\r\n`

    # Wait for first character on UART, with a timeout
    loop_count = 0
    start_time = time.ticks_ms()
    while modem.any() == 0 and time.ticks_ms() < (start_time + MODEM_STANDARD_TIMEOUT):
        loop_count += 1

    if time.ticks_ms() > (start_time + MODEM_STANDARD_TIMEOUT):
        print("AT{0}  No response within {1:d} ms.".format(MODEM_STANDARD_TIMEOUT))
        sys.exit()

    # There's something to read - let's read!
    start_time = time.ticks_ms()
    read_str = modem.read()
    end_time = time.ticks_ms()
    
    print("modem.read() elapsed time: {0} ms".format((end_time-start_time)))
    print("Modem response: {0}".format(repr(read_str)))