Discovery code can trigger TimeoutError on some inverters when using ALL_COMPLETED

[brew-your-own]

I am logging this after discussing this with @Darsstar in the context of home-assistant/core#115129

This happens in release 3.1.0 which features new improved discovery code by @Darsstar

Inverter: X1HybridGen4

Here is the code I am using to test:
`
loop = asyncio.new_event_loop()
asyncio.set_event_loop(loop)

inverters = loop.run_until_complete(solax.discover("solax.home.arpa", 80, "XXXXX", return_when=asyncio.ALL_COMPLETED))

if isinstance(inverters, set):
    logging.info("returned set of inverters")
    for inverter in inverters:
        logging.info("found inverter %s", inverter)
        print(loop.run_until_complete(inverter.get_data()))
else:
    logging.info("found inverter %s", inverters)
    print(loop.run_until_complete(inverters.get_data()))

loop.close()

`

This code will, most of the time, result in a TimeoutError:
`
INFO:root:Trying inverter X1Smart::http://solax.home.arpa:80/ using query in url
INFO:root:Trying inverter X1Smart::http://solax.home.arpa:80/ using data in the body
INFO:root:Trying inverter X1HybridGen4::http://solax.home.arpa:80/ using data in the body
INFO:root:Trying inverter QVOLTHYBG33P::http://solax.home.arpa:80/ using data in the body
INFO:root:Trying inverter X1::http://solax.home.arpa:80/ using query in url
INFO:root:Trying inverter X1::http://solax.home.arpa:80/ using data in the body
INFO:root:Trying inverter X3V34::http://solax.home.arpa:80/ using data in the body
INFO:root:Trying inverter X3V34::http://solax.home.arpa:80/ using query in url
INFO:root:Trying inverter X1Mini::http://solax.home.arpa:80/ using query in url
INFO:root:Trying inverter X1Mini::http://solax.home.arpa:80/ using data in the body
INFO:root:Trying inverter X1MiniV34::http://solax.home.arpa:80/ using data in the body
INFO:root:Trying inverter X1MiniV34::http://solax.home.arpa:80/ using query in url
INFO:root:Trying inverter X3::http://solax.home.arpa:80/ using query in url
INFO:root:Trying inverter X3::http://solax.home.arpa:80/ using data in the body
INFO:root:Trying inverter XHybrid::http://solax.home.arpa:80/api/realTimeData.htm using data in the body
INFO:root:Trying inverter X3MicProG2::http://solax.home.arpa:80/ using data in the body
INFO:root:Trying inverter X1Boost::http://solax.home.arpa:80/ using query in url
INFO:root:Trying inverter X1Boost::http://solax.home.arpa:80/ using data in the body
INFO:root:Trying inverter X3HybridG4::http://solax.home.arpa:80/ using data in the body
Traceback (most recent call last):
File "/Users/xxxxx/Documents/projects/solax/.venv/lib/python3.11/site-packages/solax/discovery.py", line 122, in discover
done, pending = await asyncio.wait(pending, return_when=return_when)
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/opt/homebrew/Cellar/[email protected]/3.11.9/Frameworks/Python.framework/Versions/3.11/lib/python3.11/asyncio/tasks.py", line 428, in wait
return await _wait(fs, timeout, return_when, loop)
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/opt/homebrew/Cellar/[email protected]/3.11.9/Frameworks/Python.framework/Versions/3.11/lib/python3.11/asyncio/tasks.py", line 535, in _wait
await waiter
asyncio.exceptions.CancelledError

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
File "/Users/xxxxx/Documents/projects/solax-simple/solax-simple copy.py", line 29, in
main()
File "/Users/xxxxx/Documents/projects/solax-simple/solax-simple copy.py", line 15, in main
inverters = loop.run_until_complete(solax.discover("solax.home.arpa", 80, "xxxxxx", return_when=asyncio.ALL_COMPLETED))
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/opt/homebrew/Cellar/[email protected]/3.11.9/Frameworks/Python.framework/Versions/3.11/lib/python3.11/asyncio/base_events.py", line 654, in run_until_complete
return future.result()
^^^^^^^^^^^^^^^
File "/Users/xxxxx/Documents/projects/solax/.venv/lib/python3.11/site-packages/solax/discovery.py", line 75, in discover
async with timeout(kwargs.get("timeout", 15)):
File "/Users/xxxxx/Documents/projects/solax/.venv/lib/python3.11/site-packages/async_timeout-4.0.3-py3.11.egg/async_timeout/init.py", line 141, in aexit
self._do_exit(exc_type)
File "/Users/xxxxx/Documents/projects/solax/.venv/lib/python3.11/site-packages/async_timeout-4.0.3-py3.11.egg/async_timeout/init.py", line 228, in _do_exit
raise asyncio.TimeoutError
TimeoutError
`

Using asyncio.FIRST_COMPLETED works:
INFO:root:Trying inverter X1Mini::http://solax.home.arpa:80/ using data in the body INFO:root:Trying inverter X1Mini::http://solax.home.arpa:80/ using query in url INFO:root:Trying inverter X1Smart::http://solax.home.arpa:80/ using query in url INFO:root:Trying inverter X1Smart::http://solax.home.arpa:80/ using data in the body INFO:root:Trying inverter X3MicProG2::http://solax.home.arpa:80/ using data in the body INFO:root:Trying inverter X3::http://solax.home.arpa:80/ using query in url INFO:root:Trying inverter X3::http://solax.home.arpa:80/ using data in the body INFO:root:Trying inverter X1MiniV34::http://solax.home.arpa:80/ using query in url INFO:root:Trying inverter X1MiniV34::http://solax.home.arpa:80/ using data in the body INFO:root:Trying inverter X3HybridG4::http://solax.home.arpa:80/ using data in the body INFO:root:Trying inverter X3V34::http://solax.home.arpa:80/ using query in url INFO:root:Trying inverter X3V34::http://solax.home.arpa:80/ using data in the body INFO:root:Trying inverter XHybrid::http://solax.home.arpa:80/api/realTimeData.htm using data in the body INFO:root:Trying inverter QVOLTHYBG33P::http://solax.home.arpa:80/ using data in the body INFO:root:Trying inverter X1::http://solax.home.arpa:80/ using query in url INFO:root:Trying inverter X1::http://solax.home.arpa:80/ using data in the body INFO:root:Trying inverter X1HybridGen4::http://solax.home.arpa:80/ using data in the body INFO:root:Trying inverter X1Boost::http://solax.home.arpa:80/ using query in url INFO:root:Trying inverter X1Boost::http://solax.home.arpa:80/ using data in the body INFO:root:Discovered inverters: {<solax.inverters.x1_hybrid_gen4.X1HybridGen4 object at 0x106c4b7d0>} INFO:root:found inverter X1HybridGen4::http://solax.home.arpa:80/ using data in the body InverterResponse(data={....})

[Darsstar]

Could you test two scenarios?

• The solax main branch, but with timeout=360 added to the discovery function
• Your unaltered reproducer, but with https://github.com/Darsstar/solax/tree/rework-discovery-timeout

If both work than a) I understand what is going on and b) we know how to fix it

Currently there are two timeouts:

• the one in solax's discovery function (default of 15 seconds)
• the default aiohttp timeout of 5 minutes

That branch removes the single timeout for the entire discovery function and replaces it with timeouts for each request via asyncio.wait_for(). Those wait_for calls are scheduled as tasks so they should not cause a TimeoutError to be thrown from discover() and instead be filtered out by remove_failures_from(done).

edit: the branch no longer uses asyncio.wait_for and instead gives the timeout to aiohttp's get and post methods.

[brew-your-own]

I should have looked at your code a bit closer, it was all there for me to see. I really appreciate your patience :)

3.1.0 with timeout=360 works. FYI it actually takes approx 304s
with timeout=250, it fails.

with your rework-discovery-timeout branch, it also works but does it in under 10s - much improved!