postlund / pyatv

A client library for Apple TV and AirPlay devices
https://pyatv.dev
MIT License
839 stars 91 forks source link

Regular when using companion state check #2198

Open bowenjfung opened 9 months ago

bowenjfung commented 9 months ago

Describe the bug

I'm using homebridge-cmdswitch2 as a dummy switch for my ATV.

I've found that using Companion pairing (rather than Airplay) is more consistent when it comes to reading the power state of the ATV, and can accurately identify when just audio is playing (turning on speakers and avoiding turning on my TV).

However, when I use Companion pairing for the state_cmd atvremote command (rather than Airplay), I get a regularly recurring logged error a couple of times an hour.

My understanding is that the state_cmd is triggered off by an error, so a call like power_state | grep -i 'PowerState.On' will trigger the switch on when the ATV power state is on, but fail silently otherwise (or at least this is what is happening when I run it in a CLI). So the command itself seems fine, and that's validated by the fact that the regularity of the error doesn't seem to be related to the state_cmd polling interval.

This error doesn't seem to cause any issues with my setup, but might be incident with some RAM buildup. I can't quite tell what the timeout is related to.

Error log

[9/19/2023, 8:35:03 AM] [homebridge-cmdswitch2] Failed to determine atv state.
[9/19/2023, 8:35:03 AM] [homebridge-cmdswitch2] Traceback (most recent call last):
  File "/usr/local/lib/python3.8/dist-packages/pyatv/protocols/companion/api.py", line 163, in _send_command
    resp = await self._protocol.exchange_opack(
  File "/usr/local/lib/python3.8/dist-packages/pyatv/protocols/companion/protocol.py", line 157, in exchange_opack
    return await self._exchange_generic_opack(frame_type, data, identifier, timeout)
  File "/usr/local/lib/python3.8/dist-packages/pyatv/protocols/companion/protocol.py", line 170, in _exchange_generic_opack
    unpacked_object = await self._queues[identifier].wait(timeout)
  File "/usr/local/lib/python3.8/dist-packages/pyatv/support/collections.py", line 160, in wait
    await asyncio.wait_for(self._event.wait(), timeout)
  File "/usr/lib/python3.8/asyncio/tasks.py", line 501, in wait_for
    raise exceptions.TimeoutError()
asyncio.exceptions.TimeoutError

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/usr/local/lib/python3.8/dist-packages/pyatv/scripts/atvremote.py", line 974, in _run_application
    return await cli_handler(loop)
  File "/usr/local/lib/python3.8/dist-packages/pyatv/scripts/atvremote.py", line 723, in cli_handler
    return await _handle_commands(args, config, storage, loop)
  File "/usr/local/lib/python3.8/dist-packages/pyatv/scripts/atvremote.py", line 847, in _handle_commands
    atv = await connect(config, loop, protocol=args.protocol, storage=storage)
  File "/usr/local/lib/python3.8/dist-packages/pyatv/__init__.py", line 155, in connect
    await atv.connect()
  File "/usr/local/lib/python3.8/dist-packages/pyatv/core/facade.py", line 684, in connect
    if await setup_data.connect():
  File "/usr/local/lib/python3.8/dist-packages/pyatv/protocols/companion/__init__.py", line 571, in _connect
    await api.connect()
  File "/usr/local/lib/python3.8/dist-packages/pyatv/protocols/companion/api.py", line 145, in connect
    await self.system_info()
  File "/usr/local/lib/python3.8/dist-packages/pyatv/protocols/companion/api.py", line 184, in system_info
    await self._send_command(
  File "/usr/local/lib/python3.8/dist-packages/pyatv/protocols/companion/api.py", line 174, in _send_command
    raise exceptions.ProtocolError(f"Command {identifier} failed") from ex
pyatv.exceptions.ProtocolError: Command _systemInfo failed

>>> An error occurred, full stack trace above

How to reproduce the bug?

Set up a homebridge-cmdswitch2 using a Companion paired state_cmd atvremote call to check ATV power state (power_state | grep -i 'PowerState.On').

What is expected behavior?

No errors!

Operating System

Linux

Python

Other

pyatv

0.14.0

Device

Apple TV 4K (3rd Gen) iOS 17

Additional context

NA

postlund commented 6 months ago

It's really hard to tell why this happens, it obviously has to do with the connect phase somehow (when setting up the Companion connection). Would have to check logs in the Apple TV by enabling development mode to see what really happens. I recommend that you create a daemon that maintains a persistent connection instead of polling (and listen to power changes using a listener). It will be more reliable, faster and likely result in fewer issues. There will likely still be issues every now and then, don't believe there's any way to "fix" that. But you can just re-connect in those cases. Is also possible to use atvscript.