many asyncio.exceptions.CancelledError

[scyto]

Describe the bug

Getting a lot of these errors in the logs, not sure if this is related to one of my 5 configured devices or the denon sat in a discovered state waiting to be configured.

Error log

This error originated from a custom integration.

Logger: custom_components.apple_tv
Source: custom_components/apple_tv/__init__.py:304
Integration: Apple TV
First occurred: 12:22:14 PM (22 occurrences)
Last logged: 12:37:52 PM

Failed to connect
Traceback (most recent call last):
  File "/usr/local/lib/python3.9/asyncio/locks.py", line 413, in acquire
    await fut
asyncio.exceptions.CancelledError

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.9/asyncio/tasks.py", line 492, in wait_for
    fut.result()
asyncio.exceptions.CancelledError

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

Traceback (most recent call last):
  File "/config/custom_components/apple_tv/__init__.py", line 227, in _connect_loop
    await self._connect(conf)
  File "/config/custom_components/apple_tv/__init__.py", line 304, in _connect
    self.atv = await connect(conf, self.hass.loop, session=session)
  File "/usr/local/lib/python3.9/site-packages/pyatv/__init__.py", line 110, in connect
    await atv.connect()
  File "/usr/local/lib/python3.9/site-packages/pyatv/core/facade.py", line 565, in connect
    if await setup_data.connect():
  File "/usr/local/lib/python3.9/site-packages/pyatv/protocols/airplay/__init__.py", line 278, in _connect_rc
    await mrp_connect()
  File "/usr/local/lib/python3.9/site-packages/pyatv/protocols/mrp/__init__.py", line 927, in _connect
    await protocol.start()
  File "/usr/local/lib/python3.9/site-packages/pyatv/protocols/mrp/protocol.py", line 156, in start
    await self.send_and_receive(messages.client_updates_config())
  File "/usr/local/lib/python3.9/site-packages/pyatv/protocols/mrp/protocol.py", line 255, in send_and_receive
    return await self._receive(identifier, timeout)
  File "/usr/local/lib/python3.9/site-packages/pyatv/protocols/mrp/protocol.py", line 267, in _receive
    await asyncio.wait_for(semaphore.acquire(), timeout)
  File "/usr/local/lib/python3.9/asyncio/tasks.py", line 494, in wait_for
    raise exceptions.TimeoutError() from exc
asyncio.exceptions.TimeoutError

How to reproduce the bug?

Install ATV integration on hass. Configure 4 ATVs Don't configure the discovered Denon amp ????

What is expected behavior?

This error doesn't show up or gives more meaningful info to ignore or action.

Operating System

home assistant (linux) 2021.12.4

Python

3.9

pyatv

0.9.8

Device

Denon AVR-X6400H + 5 $k ATVs

Additional context

not sure if this is related to the denon being sat in discovered but not configured?

let me know if you need me to turn further debug on.

[postlund]

Ok, so, the MRP-over-AirPlay tunnels fails to set up for some reason. I think we need to figure out which device this concerns. If it is easy to reproduce, maybe you can disable all devices and enable one at the time until you find the correct one?

[remyutxo]

I am having the same problem, with the same error stack. Running on Alpine Linux 3.14.2 in docker ghcr.io/postlund/pyatv:master pulled today, so it is sha-5a67911.

/ # python --version
Python 3.9.7
/ # atvremote --version
atvremote 0.9.8
/ # atvremote scan
   Name: GarAppleTV                                                                                                             
   Model/SW: Apple TV 4, tvOS 15.2 build 19K53                                                                                        
    Address: 10.1.10.15                                                                                                               
        MAC: <mac-addr>                                                                                                      
Deep Sleep: True                                                                                                                     
Identifiers:                                                                                                                          
...
Services:                                                                                                                             
 - Protocol: Companion, Port: 49152, Credentials: None, Requires Password: False, Password: None, Pairing: Disabled                   
 - Protocol: AirPlay, Port: 7000, Credentials: None, Requires Password: False, Password: None, Pairing: Mandatory                     
 - Protocol: MRP, Port: 49153, Credentials: None, Requires Password: False, Password: None, Pairing: Optional (Disabled)              
 - Protocol: RAOP, Port: 7000, Credentials: None, Requires Password: False, Password: None, Pairing: Mandatory      

       / # atvremote --id <mac-addr> --protocol mrp pair
2021-12-24 03:21:33 ERROR [pyatv.scripts.atvremote]: Pairing failed
Traceback (most recent call last):
  File "/usr/local/lib/python3.9/asyncio/locks.py", line 413, in acquire
    await fut
asyncio.exceptions.CancelledError

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.9/asyncio/tasks.py", line 492, in wait_for
    fut.result()
asyncio.exceptions.CancelledError

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

Traceback (most recent call last):
  File "/usr/local/lib/python3.9/site-packages/pyatv/support/__init__.py", line 33, in error_handler
    return await func(*args, **kwargs)
  File "/usr/local/lib/python3.9/site-packages/pyatv/protocols/mrp/auth.py", line 40, in start_pairing
    await self.protocol.start(skip_initial_messages=True)
  File "/usr/local/lib/python3.9/site-packages/pyatv/protocols/mrp/protocol.py", line 140, in start
    self.device_info = await self.send_and_receive(
  File "/usr/local/lib/python3.9/site-packages/pyatv/protocols/mrp/protocol.py", line 259, in send_and_receive
    return await self._receive(identifier, timeout)
  File "/usr/local/lib/python3.9/site-packages/pyatv/protocols/mrp/protocol.py", line 271, in _receive
    await asyncio.wait_for(semaphore.acquire(), timeout)
  File "/usr/local/lib/python3.9/asyncio/tasks.py", line 494, in wait_for
    raise exceptions.TimeoutError() from exc
asyncio.exceptions.TimeoutError

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

Traceback (most recent call last):
  File "/usr/local/lib/python3.9/site-packages/pyatv/scripts/atvremote.py", line 179, in pair
    await self._perform_pairing(pairing)
  File "/usr/local/lib/python3.9/site-packages/pyatv/scripts/atvremote.py", line 189, in _perform_pairing
    await pairing.begin()
  File "/usr/local/lib/python3.9/site-packages/pyatv/protocols/mrp/pairing.py", line 51, in begin
    return await error_handler(
  File "/usr/local/lib/python3.9/site-packages/pyatv/support/__init__.py", line 35, in error_handler
    raise exceptions.ConnectionFailedError(str(ex)) from ex
pyatv.exceptions.ConnectionFailedError
/ #

I have three apple TVs on this network, and pairing worked for the other two. The one that did not work - GarAppleTV is the only one upgraded to tvOS 15.2 It also is the only one incorrectly reporting Deep Sleep: True.

[postlund]

@scyto Did you send the log to me? I got an email about an update but I can't see any log?

@remyutxo In your case it's because you are trying to pair MRP on tvOS 15, which isn't possible since that protocol is not available there anymore. You should just pair airplay instead. It's a bit misleading though as it's reporting "Optional" as pairing requirement, which I would say is a regression that I need to fix. Currently I don't "guard" pairing protocols that can't be paired for any reason, so you will just get whatever error the underlying protocol happens to generate. I will try to improve that as well. It aligns pretty well with the work I'm currently doing with better error handling for pairing.

[scyto]

I think this is fixed from the other work.

[scyto]

I lied, i see i am still getting this, @postlund did you still want me to remove all the devices and re-add one by one to try and figure out what is generating?

2022-03-07 12:41:29 ERROR (MainThread) [custom_components.apple_tv] Failed to connect
Traceback (most recent call last):
File "/usr/local/lib/python3.9/asyncio/locks.py", line 413, in acquire
await fut
asyncio.exceptions.CancelledError
During handling of the above exception, another exception occurred:
Traceback (most recent call last):
File "/usr/local/lib/python3.9/asyncio/tasks.py", line 492, in wait_for
fut.result()
asyncio.exceptions.CancelledError
The above exception was the direct cause of the following exception:
Traceback (most recent call last):
File "/config/custom_components/apple_tv/__init__.py", line 225, in _connect_loop
await self._connect(conf)
File "/config/custom_components/apple_tv/__init__.py", line 307, in _connect
self.atv = await connect(conf, self.hass.loop, session=session)
File "/usr/local/lib/python3.9/site-packages/pyatv/__init__.py", line 135, in connect
await atv.connect()
File "/usr/local/lib/python3.9/site-packages/pyatv/core/facade.py", line 565, in connect
if await setup_data.connect():
File "/usr/local/lib/python3.9/site-packages/pyatv/protocols/airplay/__init__.py", line 269, in _connect_rc
await mrp_connect()
File "/usr/local/lib/python3.9/site-packages/pyatv/protocols/mrp/__init__.py", line 934, in _connect
await protocol.start()
File "/usr/local/lib/python3.9/site-packages/pyatv/protocols/mrp/protocol.py", line 160, in start
await self.send_and_receive(messages.client_updates_config())
File "/usr/local/lib/python3.9/site-packages/pyatv/protocols/mrp/protocol.py", line 259, in send_and_receive
return await self._receive(identifier, timeout)
File "/usr/local/lib/python3.9/site-packages/pyatv/protocols/mrp/protocol.py", line 271, in _receive
await asyncio.wait_for(semaphore.acquire(), timeout)
File "/usr/local/lib/python3.9/asyncio/tasks.py", line 494, in wait_for
raise exceptions.TimeoutError() from exc
asyncio.exceptions.TimeoutError

[postlund]

@scyto That would be great!

[postlund]

Still interested in feedback here!