Discovery code can trigger TimeoutError on some inverters when using ALL_COMPLETED

brew-your-own commented 5 months ago

I am logging this after discussing this with @Darsstar in the context of https://github.com/home-assistant/core/pull/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/python@3.11/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/python@3.11/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/python@3.11/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 commented 5 months ago

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 commented 5 months ago

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!

squishykid / solax

Discovery code can trigger TimeoutError on some inverters when using ALL_COMPLETED #150