ol-iver / denonavr

Automation Library for Denon AVR receivers.
MIT License
176 stars 67 forks source link

async timeout triggers while awaiting other async methods #266

Closed chadrockey closed 9 months ago

chadrockey commented 1 year ago

It seems like the timeout or a connection watchdog triggers while running other (potentially long delayed) async methods:

So for example, I set a script to:

connect to an AVR wait for notification of an input change (d.register_callback("SI", update_callback)) use python async streams (open_connection, etc for TCP) to send commands to another device wait a long time for the other device to process, execute, succeed, and then finally reply via TCP

I tried to do these back to back:

for cmd in commands:
  writer.write(cmd)
  await writer.drain()

  res = await reader.read(100)

But this never really returned execution to denonavr and I saw errors similar to:

Traceback (most recent call last):
  File "/home/.../python3.11/site-packages/asyncstdlib/_lrucache.py", line 407, in __call__
    result = self.__cache[key]
             ~~~~~~~~~~~~^^^^^
KeyError: <asyncstdlib._lrucache.CallKey object at 0x7f8a128370>

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/......./..../py", line 34, in send_command
    res = await reader.read(100)
          ^^^^^^^^^^^^^^^^^^^^^^
GeneratorExit
Task was destroyed but it is pending!
task: <Task pending name='Task-108' coro=<DenonAVRTelnetApi._async_run_callbacks() done, defined at /home/....../venv/lib/python3.11/site-packages/denonavr/api.py:629> wait_for=<Future pending cb=[Task.task_wakeup()]>>

What seemed to resolve the issue for me was putting in little checkpoints where execution could continue in denonavr if required:

for cmd in commands:
  writer.write(cmd)
  await writer.drain()
  await asyncio.sleep(0.1)

  res = await reader.read(100)
  await asyncio.sleep(0.1)

Not sure if it's relevant, but I have multiple callbacks registered, so it's possible for one to call on top, but the PW callback only prints, it doesn't kick off the other async calls.

d.register_callback("PW", update_callback) # Power On or Off Events
d.register_callback("SI", update_callback) # Signal Input Change Events
ol-iver commented 9 months ago

Maybe your task DenonAVRTelnetApi._async_run_callbacks() is garbage collected before it finishes when it runs for a long time (see here). I'll check if it makes sense to register is as background tasks as the docs suggest. For the meantime, you could put your long running process in a task too and register it as a background task.