home-assistant / core

:house_with_garden: Open source home automation that puts local control and privacy first.
https://www.home-assistant.io
Apache License 2.0
73.29k stars 30.61k forks source link

pyatv (atv4) does not keep pairing #65210

Closed gotschi closed 2 years ago

gotschi commented 2 years ago

The problem

apple tv4 (non-4k) here.

the integration does not remember pairing after HA restart.

Homepods work fine, already reset the Atv because it did initially not discover and connect at all, could have been a atv issue though.

Log:

Failed to set up remote control channel
Traceback (most recent call last):
  File "/usr/local/lib/python3.9/asyncio/locks.py", line 226, in wait
    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/http.py", line 388, in send_and_receive
    await asyncio.wait_for(event.wait(), timeout=4)
  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/protocols/airplay/__init__.py", line 258, in _connect_rc
    await control.start(str(core.config.address), control_port, credentials)
  File "/usr/local/lib/python3.9/site-packages/pyatv/protocols/airplay/remote_control.py", line 56, in start
    self.verifier = await verify_connection(credentials, self.connection)
  File "/usr/local/lib/python3.9/site-packages/pyatv/protocols/airplay/auth/__init__.py", line 103, in verify_connection
    has_encryption_keys = await verifier.verify_credentials()
  File "/usr/local/lib/python3.9/site-packages/pyatv/protocols/airplay/auth/hap.py", line 105, in verify_credentials
    resp = await self._send(
  File "/usr/local/lib/python3.9/site-packages/pyatv/protocols/airplay/auth/hap.py", line 132, in _send
    return await self.http.post(
  File "/usr/local/lib/python3.9/site-packages/pyatv/support/http.py", line 359, in post
    return await self.send_and_receive(
  File "/usr/local/lib/python3.9/site-packages/pyatv/support/http.py", line 391, in send_and_receive
    raise TimeoutError(f"no response to {method} {uri} ({protocol})") from ex
TimeoutError: no response to POST /pair-verify (HTTP/1.1)
Authentication failed for AppleTV, try reconfiguring device
Traceback (most recent call last):
  File "/usr/local/lib/python3.9/asyncio/locks.py", line 226, in wait
    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/protocols/companion/protocol.py", line 121, in _setup_encryption
    await pair_verifier.verify_credentials()
  File "/usr/local/lib/python3.9/site-packages/pyatv/protocols/companion/auth.py", line 146, in verify_credentials
    resp = await self.protocol.exchange_auth(
  File "/usr/local/lib/python3.9/site-packages/pyatv/protocols/companion/protocol.py", line 145, in exchange_auth
    return await self._exchange_generic_opack(frame_type, data, identifier, timeout)
  File "/usr/local/lib/python3.9/site-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.9/site-packages/pyatv/support/collections.py", line 130, in wait
    await asyncio.wait_for(self._event.wait(), 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/src/homeassistant/homeassistant/components/apple_tv/__init__.py", line 228, in _connect_loop
    await self._connect(conf)
  File "/usr/src/homeassistant/homeassistant/components/apple_tv/__init__.py", line 310, 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/companion/__init__.py", line 401, in _connect
    await api.connect()
  File "/usr/local/lib/python3.9/site-packages/pyatv/protocols/companion/api.py", line 121, in connect
    await self._protocol.start()
  File "/usr/local/lib/python3.9/site-packages/pyatv/protocols/companion/protocol.py", line 108, in start
    await self._setup_encryption()
  File "/usr/local/lib/python3.9/site-packages/pyatv/protocols/companion/protocol.py", line 127, in _setup_encryption
    raise exceptions.AuthenticationError(str(ex)) from ex
pyatv.exceptions.AuthenticationError
Got response without having a request: HttpResponse(protocol='HTTP', version='1.1', code=200, message='OK', headers={'date': 'Sat, 29 Jan 2022 20:21:49 GMT', 'content-length': '159', 'content-type': 'application/octet-stream', 'server': 'AirTunes/605.1'}, body=b'\x05xMU|C\xaa{\xf2{O\x8d\xb0K\xb8\xf6\x11\x87\xb1\x90H\xa2\xb2&\xe9\xa3b#\x1e\xcc\x80\x99^\x80x\x0bru#\xb5\x0eX3Ei,\x98pb\xeb\xde1\x19\xab\xdf\x98{\xb9\x9d\x9cg\xf8\xe4\xb9\x19]E\t{H\xef\xbf"\x8a\xf5\xad|\x0ej\x8e\xd0\x92!\x89\x02\xe2\xce\xb2)D\x12~J{0\x8d\xd8\x14\xd2\x18bfK\x9d\xaej\xf71M\t!6\x04\xe5\xd1\xed\xf5\xc0\x82\x82\x93\x95\x06\x01\x02\x03 @\xe3\x85\x14\xdb\x82\xf8\xda0\xf7\xe6U\x9b\x0b\xb2\x96\x85\x15\x1bn\xc0\x83}1x\xef/O.#-i')

What version of Home Assistant Core has the issue?

2022.2.0b3

What was the last working version of Home Assistant Core?

No response

What type of installation are you running?

Home Assistant Container

Integration causing the issue

appletv

Link to integration documentation on our website

https://rc.home-assistant.io/integrations/apple_tv/

Example YAML snippet

No response

Anything in the logs that might be useful for us?

^^

Additional information

No response

probot-home-assistant[bot] commented 2 years ago

apple_tv documentation apple_tv source (message by IssueLinks)

probot-home-assistant[bot] commented 2 years ago

Hey there @postlund, mind taking a look at this issue as it has been labeled with an integration (apple_tv) you are listed as a code owner for? Thanks! (message by CodeOwnersMention)

bdraco commented 2 years ago

It would probably help the code owners to know which version of TvOS the device is running.

gotschi commented 2 years ago

oh scusi, tvOS 15.3

postlund commented 2 years ago

Looks to me like the device does not respond to /pair-verify correctly. Did you try restarting the device as a start?

gotschi commented 2 years ago

yes, restarted both apple tv and ha

postlund commented 2 years ago

Then it would be great if you enabled debug logs for pyatv (just add pyatv: debug to log points) and attach the debug log here. The error and like ten lines above that is sufficient.

gotschi commented 2 years ago

https://gitlab.com/-/snippets/2245284

I should note that the pairing and re-pairing always completes fine and works until ha or atv is rebooted... and every time I do a re-pair it creates a new remote in Settings - Remotes on the atv

and there are 2 homepod minis in my setup, these work fine (except the volume not applying across UI which seems a integration problem too.. calling homeassistant.update_entity on the homepod entity syncs the state to UI)

... and I just saw that occasionally the error does not happen, apple tv is successfully connected. no idea what is going on there

gotschi commented 2 years ago

I just reset the atv and tried again, I get "Unexpected exception" evertime on the Airplay pairing...

followed by pyatv.exceptions.ConnectionFailedError: no response to POST /pair-setup and [pyatv.support.http] Got response without having a request: HttpResponse(protocol='HTTP', version='1.1', code=200, message='OK', headers={'date': 'Tue, 01 Feb 2022 07:39:32 GMT', 'content-length': '327', 'content-type': 'application/x-apple-binary-plist', 'server': 'AirTunes/605.1'}, body=b"\x05\....

The remotes created in the atv settings all have a "Unknown Device" name, sometimes it registers as "Living Room"

postlund commented 2 years ago

Is AirPlay enabled and access settings changed to "Everyone on the same network"? It won't work otherwise. You should get a proper error if it isn't, but I really don't have any ideas right now.

gotschi commented 2 years ago

Yes, I specifically only set this setting upon resetting the atv... not even pairing to my home at this point because i want to rule out stuff

gotschi commented 2 years ago

i trashed my whole homekit home, set up everything again after trying literally everything.

I then managed to somehow get through multiple Unhandled Exception pairing tries until it finally passed and stays paired when I restart HA.

and now I'm scared it will unpair if i reboot the atv so I just keep it on :P

edit: nope, it just went badonk again, out of the blue.

gotschi commented 2 years ago

whatever is happening here fails at some point, leaving me with 2 remotes ("Living Room" & "Unknown Device") every time...

here is a video of a few trials: https://x0.at/07Fc.mp4

I somehow can make it through to get it registered sometimes but this pairing will then stop working after some time sometimes it fails at companion, sometimes it fails at RAOP and most times I'm stuck at Airplay

2022-02-01 21:28:31 INFO (MainThread) [homeassistant.components.generic_thermostat.climate] Keep-alive - Turning on heater heater switch.bad_heizung
2022-02-01 21:28:31 INFO (MainThread) [homeassistant.components.generic_thermostat.climate] Keep-alive - Turning on heater heater switch.wohnzimmer_1_heizung
2022-02-01 21:28:31 INFO (MainThread) [homeassistant.components.generic_thermostat.climate] Keep-alive - Turning on heater heater switch.kueche_heizung
2022-02-01 21:28:31 INFO (MainThread) [homeassistant.components.generic_thermostat.climate] Keep-alive - Turning on heater heater switch.schlafzimmer_heizung
2022-02-01 21:28:32 INFO (MainThread) [homeassistant.components.media_player] Setting up media_player.apple_tv
2022-02-01 21:28:32 INFO (MainThread) [homeassistant.components.remote] Setting up remote.apple_tv
2022-02-01 21:28:32 DEBUG (MainThread) [homeassistant.components.apple_tv] Starting connect loop
2022-02-01 21:28:32 DEBUG (MainThread) [homeassistant.components.apple_tv] Discovering device AppleTv4
2022-02-01 21:28:32 DEBUG (MainThread) [pyatv.core.scan] Auto-discovered AppleTv4 at 10.0.57.54:7000 via Protocol.AirPlay ({'acl': '0', 'btaddr': 'D0:03:4B:38:4A:BD', 'deviceid': 'D0:03:4B:38:4A:BE', 'fex': '1d9/Wt5fFbwI', 'features': '0x5A7FDFD5,0xBC155FDE', 'flags': '0x18644', 'gid': 'A42E2D91-4C00-476A-8A61-28A01D45349E', 'igl': '1', 'gcgl': '1', 'model': 'AppleTV5,3', 'protovers': '1.1', 'pi': 'd16e190d-64f8-4cf7-90f5-695f66fa5842', 'psi': '4928B0BE-578E-40C6-BC60-69BA36B3E8B7', 'pk': 'ac3ba060fa91eb296593093856250285f428b04eecd27aa454673b894746108e', 'srcvers': '605.1', 'osvers': '15.3', 'vv': '2'})
2022-02-01 21:28:32 DEBUG (MainThread) [pyatv.core.scan] Auto-discovered AppleTv4 at 10.0.57.54:49152 via Protocol.Companion ({'rpmac': '1', 'rphn': '299b8d682e7c', 'rpfl': '0xB6782', 'rpha': '1a64f5ed571f', 'rpmd': 'AppleTV5,3', 'rpvr': '330.5', 'rpad': '8c8ba95cc174', 'rphi': 'fb5f3abf1e11', 'rpba': '76:10:3C:4D:95:24', 'rpmrtid': '4928B0BE-578E-40C6-BC60-69BA36B3E8B7'})
2022-02-01 21:28:32 DEBUG (MainThread) [pyatv.core.scan] Auto-discovered D0034B384ABE@AppleTv4 at 10.0.57.54:7000 via Protocol.RAOP ({'cn': '0,1,2,3', 'da': 'true', 'et': '0,3,5', 'ft': '0x5A7FDFD5,0xBC155FDE', 'sf': '0x18644', 'md': '0,1,2', 'am': 'AppleTV5,3', 'pk': 'ac3ba060fa91eb296593093856250285f428b04eecd27aa454673b894746108e', 'tp': 'UDP', 'vn': '65537', 'vs': '605.1', 'ov': '15.3', 'vv': '2'})
2022-02-01 21:28:32 DEBUG (MainThread) [homeassistant.components.apple_tv] Connecting to device AppleTv4
2022-02-01 21:28:32 DEBUG (MainThread) [pyatv.core.facade] Adding handler for protocol Protocol.AirPlay
2022-02-01 21:28:32 DEBUG (MainThread) [pyatv.protocols.airplay] Remote control channel is supported
2022-02-01 21:28:32 DEBUG (MainThread) [pyatv.core.facade] Adding handler for protocol Protocol.MRP
2022-02-01 21:28:32 DEBUG (MainThread) [pyatv.core.facade] Adding handler for protocol Protocol.Companion
2022-02-01 21:28:32 DEBUG (MainThread) [pyatv.core.facade] Adding handler for protocol Protocol.MRP
2022-02-01 21:28:32 DEBUG (MainThread) [pyatv.core.facade] Adding handler for protocol Protocol.RAOP
2022-02-01 21:28:32 DEBUG (MainThread) [pyatv.core.facade] Connecting to protocol: Protocol.AirPlay
2022-02-01 21:28:32 DEBUG (MainThread) [pyatv.core.facade] Connected to protocol: Protocol.AirPlay
2022-02-01 21:28:32 DEBUG (MainThread) [pyatv.core.facade] Connecting to protocol: Protocol.MRP
2022-02-01 21:28:32 DEBUG (MainThread) [pyatv.protocols.airplay.remote_control] Setting up remote control connection to 10.0.57.54:7000
2022-02-01 21:28:32 DEBUG (MainThread) [pyatv.support.http] Connected to 10.0.57.54
2022-02-01 21:28:32 DEBUG (MainThread) [pyatv.protocols.airplay.auth] Setting up new AirPlay Pair-Verify procedure with type AuthenticationType.HAP
2022-02-01 21:28:32 DEBUG (MainThread) [pyatv.support.http] Sending HTTP/1.1 message: b'POST /pair-verify HTTP/1.1\r\nContent-Length: 37\r\nUser-Agent: AirPlay/320.20\r\nConnection: keep-alive\r\nX-Apple-HKP: 3\r\nContent-Type: application/octet-stream\r\n\r\n\x06\x01\x01\x03 \xe9_|\xdf\xed\xc9\xb8\t\xdb\xc3\xa8 \xa6\xc0\x8d>] \x10\xa2^O \xf3\xb8$\xe1t2t\xc2"'
2022-02-01 21:28:32 DEBUG (MainThread) [pyatv.support.http] Connection closed
2022-02-01 21:28:35 INFO (SyncWorker_18) [homeassistant.components.command_line.switch] Running state code command: false
2022-02-01 21:28:35 INFO (SyncWorker_10) [homeassistant.components.command_line.switch] Running state code command: false
2022-02-01 21:28:35 INFO (SyncWorker_17) [homeassistant.components.command_line.switch] Running state code command: false
2022-02-01 21:28:35 INFO (SyncWorker_15) [homeassistant.components.command_line.switch] Running state code command: false
2022-02-01 21:28:35 INFO (SyncWorker_4) [homeassistant.components.command_line.switch] Running state value command: curl -s -H 'Accept: application/json' -X GET http://10.0.57.9/api/SOdfseamllUZQpi4hFDd8wNtoGfgSp3FtbHB-yO1/groups/13  | jq '.stream | .active'
2022-02-01 21:28:35 INFO (SyncWorker_16) [homeassistant.components.command_line.switch] Running state value command: curl -s -H 'Accept: application/json' -X GET http://10.0.57.9/api/SOdfseamllUZQpi4hFDd8wNtoGfgSp3FtbHB-yO1/groups/13  | jq '.stream | .active'
2022-02-01 21:28:35 INFO (SyncWorker_3) [homeassistant.components.command_line.switch] Running state value command: curl -k -s https://10.0.57.40:10443/endpoint/@scrypted/webhook/public/17/7c43b222a5a15c92/motionDetected
2022-02-01 21:28:35 INFO (SyncWorker_12) [homeassistant.components.command_line.switch] Running state code command: false
2022-02-01 21:28:35 INFO (SyncWorker_6) [homeassistant.components.command_line.switch] Running state code command: false
2022-02-01 21:28:36 ERROR (MainThread) [pyatv.protocols.airplay] Failed to set up remote control channel
Traceback (most recent call last):
  File "/usr/local/lib/python3.9/asyncio/locks.py", line 226, in wait
    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/http.py", line 388, in send_and_receive
    await asyncio.wait_for(event.wait(), timeout=4)
  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/protocols/airplay/__init__.py", line 258, in _connect_rc
    await control.start(str(core.config.address), control_port, credentials)
  File "/usr/local/lib/python3.9/site-packages/pyatv/protocols/airplay/remote_control.py", line 56, in start
    self.verifier = await verify_connection(credentials, self.connection)
  File "/usr/local/lib/python3.9/site-packages/pyatv/protocols/airplay/auth/__init__.py", line 103, in verify_connection
    has_encryption_keys = await verifier.verify_credentials()
  File "/usr/local/lib/python3.9/site-packages/pyatv/protocols/airplay/auth/hap.py", line 105, in verify_credentials
    resp = await self._send(
  File "/usr/local/lib/python3.9/site-packages/pyatv/protocols/airplay/auth/hap.py", line 132, in _send
    return await self.http.post(
  File "/usr/local/lib/python3.9/site-packages/pyatv/support/http.py", line 359, in post
    return await self.send_and_receive(
  File "/usr/local/lib/python3.9/site-packages/pyatv/support/http.py", line 391, in send_and_receive
    raise TimeoutError(f"no response to {method} {uri} ({protocol})") from ex
TimeoutError: no response to POST /pair-verify (HTTP/1.1)
2022-02-01 21:28:36 DEBUG (MainThread) [pyatv.core.facade] Connecting to protocol: Protocol.Companion
2022-02-01 21:28:36 DEBUG (MainThread) [pyatv.protocols.companion.api] Connect to Companion from API
2022-02-01 21:28:36 DEBUG (MainThread) [pyatv.protocols.companion.connection] Connected to companion device 10.0.57.54:49152
2022-02-01 21:28:36 DEBUG (MainThread) [pyatv.protocols.companion.protocol] Companion credentials: b126d9cc07090278a4b2c33c650d877bddd88e0f7232b7d74b965e8fc390c305:f848c87624c5d8d1607ffc99421a0785e7c66ce02ecf031da36dd7bc0e797000:34393238423042452d353738452d343043362d424336302d363942413336423345384237:63336532663236662d393132352d343134332d386431382d366464306334623738363834
2022-02-01 21:28:36 DEBUG (MainThread) [pyatv.protocols.companion.protocol] Exchange OPACK: {'_pd': b'\x06\x01\x01\x03 3\x1aX\xe8\xa6\xb7\xe6\xe0\xd5\x98/\xde\xa2\xc1\x1b\xbdG\xde\x19t\x88\xfd\x0b\x1e\x06`\xfa\x1b\xcbu\x1fA', '_auTy': 4}
2022-02-01 21:28:36 DEBUG (MainThread) [pyatv.protocols.companion.protocol] Send OPACK: {'_pd': b'\x06\x01\x01\x03 3\x1aX\xe8\xa6\xb7\xe6\xe0\xd5\x98/\xde\xa2\xc1\x1b\xbdG\xde\x19t\x88\xfd\x0b\x1e\x06`\xfa\x1b\xcbu\x1fA', '_auTy': 4, '_x': 40645}
2022-02-01 21:28:36 DEBUG (MainThread) [pyatv.protocols.companion.connection] >> Send data (Data=e3435f706491250601010320331a58e8a6b7e6e0d5982fdea2c11bbd47de197488fd0b1e0660fa1bcb751f41455f617554790c425f7831c59e, FrameType=05)
2022-02-01 21:28:41 ERROR (MainThread) [homeassistant.components.apple_tv] Authentication failed for AppleTv4, try reconfiguring device
Traceback (most recent call last):
  File "/usr/local/lib/python3.9/asyncio/locks.py", line 226, in wait
    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/protocols/companion/protocol.py", line 121, in _setup_encryption
    await pair_verifier.verify_credentials()
  File "/usr/local/lib/python3.9/site-packages/pyatv/protocols/companion/auth.py", line 146, in verify_credentials
    resp = await self.protocol.exchange_auth(
  File "/usr/local/lib/python3.9/site-packages/pyatv/protocols/companion/protocol.py", line 145, in exchange_auth
    return await self._exchange_generic_opack(frame_type, data, identifier, timeout)
  File "/usr/local/lib/python3.9/site-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.9/site-packages/pyatv/support/collections.py", line 130, in wait
    await asyncio.wait_for(self._event.wait(), 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/src/homeassistant/homeassistant/components/apple_tv/__init__.py", line 228, in _connect_loop
    await self._connect(conf)
  File "/usr/src/homeassistant/homeassistant/components/apple_tv/__init__.py", line 310, 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/companion/__init__.py", line 401, in _connect
    await api.connect()
  File "/usr/local/lib/python3.9/site-packages/pyatv/protocols/companion/api.py", line 121, in connect
    await self._protocol.start()
  File "/usr/local/lib/python3.9/site-packages/pyatv/protocols/companion/protocol.py", line 108, in start
    await self._setup_encryption()
  File "/usr/local/lib/python3.9/site-packages/pyatv/protocols/companion/protocol.py", line 127, in _setup_encryption
    raise exceptions.AuthenticationError(str(ex)) from ex
pyatv.exceptions.AuthenticationError
2022-02-01 21:28:41 DEBUG (MainThread) [homeassistant.components.apple_tv] Connect loop ended
2022-02-01 21:28:41 DEBUG (MainThread) [homeassistant.components.apple_tv] Disconnecting from device
2022-02-01 21:28:43 INFO (Thread-4) [custom_components.blitzortung.mqtt] Disconnected from MQTT server blitzortung.ha.sed.pl:1883 (7)
2022-02-01 21:28:46 DEBUG (MainThread) [pyatv.support.http] Received: b'HTTP/1.1 200 OK\r\nDate: Tue, 01 Feb 2022 20:28:46 GMT\r\nContent-Length: 159\r\nContent-Type: application/octet-stream\r\nServer: AirTunes/605.1\r\n\r\n\x05xDM;]n\x02\xbb\x152so\nO\xff\xcb(\xf0\x00\xb6\xbf$\x0f\xed\xa7\xe0\x9c\xc7)+#,z\xd0\xa3\xd4\xb3\xdc\x8b6\x88\x9c\xed\x13=\x03\x06[E\x1d\xe4\x03\x98\xd5\xb3EQ,\xff\xdd\xfe\x0c?E\xab\x1b\xd0\xbe\xc5\x91\x079\x17\xc0\x10\x0f\xc0\x9b\x08\x08(_\x80\x07\x07\xca\xf3W\xe4\x8e;.\xd5\xda\xad\x88G*\xfb\xc6^)\xacKa\xd9\x8e\xc0\x14\xc3CiW\x8bd\xa0Jg\xfc\xf6h\x06\x01\x02\x03 \xd3l\x01\xb7\x1f<.\x9dQ\xfa\xc5\xe6\xd6Ak\xec\r@\xfb8\n\xa6\xa8\xc8\xb5)j\xce\x83F\xcf3'
2022-02-01 21:28:46 WARNING (MainThread) [pyatv.support.http] Got response without having a request: HttpResponse(protocol='HTTP', version='1.1', code=200, message='OK', headers={'date': 'Tue, 01 Feb 2022 20:28:46 GMT', 'content-length': '159', 'content-type': 'application/octet-stream', 'server': 'AirTunes/605.1'}, body=b'\x05xDM;]n\x02\xbb\x152so\nO\xff\xcb(\xf0\x00\xb6\xbf$\x0f\xed\xa7\xe0\x9c\xc7)+#,z\xd0\xa3\xd4\xb3\xdc\x8b6\x88\x9c\xed\x13=\x03\x06[E\x1d\xe4\x03\x98\xd5\xb3EQ,\xff\xdd\xfe\x0c?E\xab\x1b\xd0\xbe\xc5\x91\x079\x17\xc0\x10\x0f\xc0\x9b\x08\x08(_\x80\x07\x07\xca\xf3W\xe4\x8e;.\xd5\xda\xad\x88G*\xfb\xc6^)\xacKa\xd9\x8e\xc0\x14\xc3CiW\x8bd\xa0Jg\xfc\xf6h\x06\x01\x02\x03 \xd3l\x01\xb7\x1f<.\x9dQ\xfa\xc5\xe6\xd6Ak\xec\r@\xfb8\n\xa6\xa8\xc8\xb5)j\xce\x83F\xcf3')
2022-02-01 21:28:46 DEBUG (MainThread) [pyatv.protocols.companion.connection] Received data (Data=060000a6e1435f7064919f0578b85f1d3521abe9f6c749d8f292910d7ec6542d788c61c1a01260078a30ea2ac1f334fdfa9dc9bf15784e2eba66d7e5979d714ad7e99f8cad4a7d3678ed6c47a696d52663d11530416f8f9e7090518067ce76682c5c33805a3a6273198c94a4a8b0303fd7ad887459484b9b4e5f4bfc301dd1cc1b3a084f1306010203204f138ce8b8b4075e8035b489dcd09462464918175b1f3bfe317f1d5fa5546e3d)
2022-02-01 21:28:46 DEBUG (MainThread) [pyatv.protocols.companion.protocol] Received frame FrameType.PV_Next: b'\xe1C_pd\x91\x9f\x05x\xb8_\x1d5!\xab\xe9\xf6\xc7I\xd8\xf2\x92\x91\r~\xc6T-x\x8ca\xc1\xa0\x12`\x07\x8a0\xea*\xc1\xf34\xfd\xfa\x9d\xc9\xbf\x15xN.\xbaf\xd7\xe5\x97\x9dqJ\xd7\xe9\x9f\x8c\xadJ}6x\xedlG\xa6\x96\xd5&c\xd1\x150Ao\x8f\x9ep\x90Q\x80g\xcevh,\\3\x80Z:bs\x19\x8c\x94\xa4\xa8\xb00?\xd7\xad\x88tYHK\x9bN_K\xfc0\x1d\xd1\xcc\x1b:\x08O\x13\x06\x01\x02\x03 O\x13\x8c\xe8\xb8\xb4\x07^\x805\xb4\x89\xdc\xd0\x94bFI\x18\x17[\x1f;\xfe1\x7f\x1d_\xa5Tn='
2022-02-01 21:28:46 DEBUG (MainThread) [pyatv.protocols.companion.protocol] Process incoming auth frame (FrameType.PV_Next): {'_pd': b'\x05x\xb8_\x1d5!\xab\xe9\xf6\xc7I\xd8\xf2\x92\x91\r~\xc6T-x\x8ca\xc1\xa0\x12`\x07\x8a0\xea*\xc1\xf34\xfd\xfa\x9d\xc9\xbf\x15xN.\xbaf\xd7\xe5\x97\x9dqJ\xd7\xe9\x9f\x8c\xadJ}6x\xedlG\xa6\x96\xd5&c\xd1\x150Ao\x8f\x9ep\x90Q\x80g\xcevh,\\3\x80Z:bs\x19\x8c\x94\xa4\xa8\xb00?\xd7\xad\x88tYHK\x9bN_K\xfc0\x1d\xd1\xcc\x1b:\x08O\x13\x06\x01\x02\x03 O\x13\x8c\xe8\xb8\xb4\x07^\x805\xb4\x89\xdc\xd0\x94bFI\x18\x17[\x1f;\xfe1\x7f\x1d_\xa5Tn='}
2022-02-01 21:29:05 INFO (SyncWorker_12) [homeassistant.components.command_line.switch] Running state code command: false
2022-02-01 21:29:05 INFO (SyncWorker_18) [homeassistant.components.command_line.switch] Running state code command: false
2022-02-01 21:29:05 INFO (SyncWorker_16) [homeassistant.components.command_line.switch] Running state code command: false
2022-02-01 21:29:05 INFO (SyncWorker_11) [homeassistant.components.command_line.switch] Running state code command: false
2022-02-01 21:29:05 INFO (SyncWorker_8) [homeassistant.components.command_line.switch] Running state value command: curl -s -H 'Accept: application/json' -X GET http://10.0.57.9/api/SOdfseamllUZQpi4hFDd8wNtoGfgSp3FtbHB-yO1/groups/13  | jq '.stream | .active'
2022-02-01 21:29:05 INFO (SyncWorker_4) [homeassistant.components.command_line.switch] Running state value command: curl -s -H 'Accept: application/json' -X GET http://10.0.57.9/api/SOdfseamllUZQpi4hFDd8wNtoGfgSp3FtbHB-yO1/groups/13  | jq '.stream | .active'
2022-02-01 21:29:05 INFO (SyncWorker_14) [homeassistant.components.command_line.switch] Running state value command: curl -k -s https://10.0.57.40:10443/endpoint/@scrypted/webhook/public/17/7c43b222a5a15c92/motionDetected
2022-02-01 21:29:05 INFO (SyncWorker_3) [homeassistant.components.command_line.switch] Running state code command: false
2022-02-01 21:29:05 DEBUG (MainThread) [pyatv.core.scan] Auto-discovered Fernseher at 10.0.57.17:7000 via Protocol.AirPlay ({'acl': '0', 'deviceid': 'CB:6E:16:21:CB:91', 'features': '0x7F8AD0,0x38BCB46', 'rsf': '0x3', 'fv': 'p20.04.30.55', 'flags': '0x244', 'model': 'OLED55CX9LA', 'manufacturer': 'LG Electronics', 'serialnumber': '010MAZVFN269_58:fd:b1:a7:88:db\n', 'protovers': '1.1', 'srcvers': '377.25.06', 'pi': 'CB:6E:16:21:CB:91', 'psi': '00000000-0000-0000-0000-CB6E1621CB91', 'gid': '00000000-0000-0000-0000-CB6E1621CB91', 'gcgl': '0', 'pk': '4bee3874aa188e00d4eee3af187942f4be61c9758ba4a8aa77c3d624cb667cc3'})
2022-02-01 21:29:05 DEBUG (MainThread) [pyatv.core.scan] Auto-discovered HomePod Dach at 10.0.57.26:7000 via Protocol.AirPlay ({'acl': '0', 'btaddr': '79:75:49:E7:5D:79', 'deviceid': 'F4:34:F0:23:93:E5', 'fex': 'AMp/StBLNbw', 'features': '0x4A7FCA00,0xBC354BD0', 'flags': '0x18404', 'gid': '37240B66-2638-4243-B3FF-06A869AD350A', 'igl': '1', 'gcgl': '1', 'model': 'AudioAccessory5,1', 'protovers': '1.1', 'pi': '26c47e1e-2a89-4632-b94d-003b9c5f66ca', 'psi': '15ACF911-6396-492F-B354-3D598231E513', 'pk': 'cbd6bd54ec56fc32ea9b335cb9f17f91fea88f09e50f350e72edee5a70816d35', 'srcvers': '605.1', 'osvers': '15.3', 'vv': '2'})
2022-02-01 21:29:05 DEBUG (MainThread) [pyatv.core.scan] Auto-discovered HomePod Dach at 10.0.57.26:49152 via Protocol.Companion ({'rpmac': '2', 'rphn': '47a40ace9ab9', 'rpfl': '0x62792', 'rpha': 'b0e887c56aab', 'rpmd': 'AudioAccessory5,1', 'rpvr': '330.5', 'rpad': '59dda02eb522', 'rphi': '2d869f49813b', 'rpba': '50:09:D6:09:B9:16'})
2022-02-01 21:29:05 DEBUG (MainThread) [pyatv.core.scan] Auto-discovered F434F02393E5@HomePod Dach at 10.0.57.26:7000 via Protocol.RAOP ({'cn': '0,1,2,3', 'da': 'true', 'et': '0,3,5', 'ft': '0x4A7FCA00,0xBC354BD0', 'sf': '0x18404', 'md': '0,1,2', 'am': 'AudioAccessory5,1', 'pk': 'cbd6bd54ec56fc32ea9b335cb9f17f91fea88f09e50f350e72edee5a70816d35', 'tp': 'UDP', 'vn': '65537', 'vs': '605.1', 'ov': '15.3', 'vv': '2'})
2022-02-01 21:29:05 DEBUG (MainThread) [pyatv.core.scan] Auto-discovered HomePod Wohnzimmer at 10.0.57.27:7000 via Protocol.AirPlay ({'acl': '0', 'btaddr': '5D:E2:20:74:6E:0C', 'deviceid': 'F4:34:F0:59:B6:31', 'fex': 'AMp/StBLNbw', 'features': '0x4A7FCA00,0xBC354BD0', 'flags': '0x18404', 'gid': '750CD296-E3A7-4593-A62D-0566370928ED', 'igl': '1', 'gcgl': '1', 'model': 'AudioAccessory5,1', 'protovers': '1.1', 'pi': '89ded496-ef2f-4be7-af67-efb9f204c377', 'psi': '576EE1BD-86BF-4B96-9093-BFAF9D458AF2', 'pk': 'cb47309b92d73a187d35cf4906847c028aaca9a0caa8ff6d5c4294ea3141e487', 'srcvers': '605.1', 'osvers': '15.3', 'vv': '2'})
2022-02-01 21:29:05 DEBUG (MainThread) [pyatv.core.scan] Auto-discovered HomePod Wohnzimmer at 10.0.57.27:49152 via Protocol.Companion ({'rpmac': '2', 'rphn': 'c4d7e79ac14f', 'rpfl': '0x62792', 'rpha': '5346c7e3f1db', 'rpmd': 'AudioAccessory5,1', 'rpvr': '330.5', 'rpad': '1a7bd019c845', 'rphi': 'fe740e5e6a65', 'rpba': '46:7D:18:37:FC:26'})
2022-02-01 21:29:05 DEBUG (MainThread) [pyatv.core.scan] Auto-discovered F434F059B631@HomePod Wohnzimmer at 10.0.57.27:7000 via Protocol.RAOP ({'cn': '0,1,2,3', 'da': 'true', 'et': '0,3,5', 'ft': '0x4A7FCA00,0xBC354BD0', 'sf': '0x18404', 'md': '0,1,2', 'am': 'AudioAccessory5,1', 'pk': 'cb47309b92d73a187d35cf4906847c028aaca9a0caa8ff6d5c4294ea3141e487', 'tp': 'UDP', 'vn': '65537', 'vs': '605.1', 'ov': '15.3', 'vv': '2'})
2022-02-01 21:29:05 DEBUG (MainThread) [pyatv.core.scan] Auto-discovered AppleTv4 at 10.0.57.54:7000 via Protocol.AirPlay ({'acl': '0', 'btaddr': 'D0:03:4B:38:4A:BD', 'deviceid': 'D0:03:4B:38:4A:BE', 'fex': '1d9/Wt5fFbwI', 'features': '0x5A7FDFD5,0xBC155FDE', 'flags': '0x18644', 'gid': 'A42E2D91-4C00-476A-8A61-28A01D45349E', 'igl': '1', 'gcgl': '1', 'model': 'AppleTV5,3', 'protovers': '1.1', 'pi': 'd16e190d-64f8-4cf7-90f5-695f66fa5842', 'psi': '4928B0BE-578E-40C6-BC60-69BA36B3E8B7', 'pk': 'ac3ba060fa91eb296593093856250285f428b04eecd27aa454673b894746108e', 'srcvers': '605.1', 'osvers': '15.3', 'vv': '2'})
2022-02-01 21:29:05 DEBUG (MainThread) [pyatv.core.scan] Auto-discovered AppleTv4 at 10.0.57.54:49152 via Protocol.Companion ({'rpmac': '1', 'rphn': '299b8d682e7c', 'rpfl': '0xB6782', 'rpha': '1a64f5ed571f', 'rpmd': 'AppleTV5,3', 'rpvr': '330.5', 'rpad': '8c8ba95cc174', 'rphi': 'fb5f3abf1e11', 'rpba': '76:10:3C:4D:95:24', 'rpmrtid': '4928B0BE-578E-40C6-BC60-69BA36B3E8B7'})
2022-02-01 21:29:05 DEBUG (MainThread) [pyatv.core.scan] Auto-discovered D0034B384ABE@AppleTv4 at 10.0.57.54:7000 via Protocol.RAOP ({'cn': '0,1,2,3', 'da': 'true', 'et': '0,3,5', 'ft': '0x5A7FDFD5,0xBC155FDE', 'sf': '0x18644', 'md': '0,1,2', 'am': 'AppleTV5,3', 'pk': 'ac3ba060fa91eb296593093856250285f428b04eecd27aa454673b894746108e', 'tp': 'UDP', 'vn': '65537', 'vs': '605.1', 'ov': '15.3', 'vv': '2'})
2022-02-01 21:29:05 DEBUG (MainThread) [pyatv.core.scan] Auto-discovered MacBookAir at 10.0.57.11:49166 via Protocol.Companion ({'rpmac': '0', 'rphn': 'e8d1c59fbb69', 'rpfl': '0x20000', 'rpha': 'a15abb2f9ab4', 'rpvr': '260.3', 'rpad': 'b3b52298ba1f', 'rphi': 'a6f84e42952a', 'rpba': '32:FE:63:64:59:0A'})
2022-02-01 21:29:05 DEBUG (MainThread) [pyatv.core.scan] Auto-discovered DCA6320C7080@Kodi (WohnzimmerPi) at 10.0.57.136:36666 via Protocol.RAOP ({'txtvers': '1', 'cn': '0,1', 'ch': '2', 'ek': '1', 'et': '0,1', 'sv': 'false', 'tp': 'UDP', 'sm': 'false', 'ss': '16', 'sr': '44100', 'pw': 'false', 'vn': '3', 'da': 'true', 'md': '0,1,2', 'am': 'Kodi,1', 'vs': '130.14'})
2022-02-01 21:29:05 DEBUG (MainThread) [homeassistant.components.apple_tv.config_flow] Protocol.AirPlay requires pairing
2022-02-01 21:29:05 DEBUG (MainThread) [pyatv.support.http] Connected to 10.0.57.54
2022-02-01 21:29:05 DEBUG (MainThread) [pyatv.protocols.airplay.auth] Setting up new AirPlay Pair-Setup procedure with type AuthenticationType.HAP
2022-02-01 21:29:06 DEBUG (MainThread) [pyatv.support.http] Sending HTTP/1.1 message: b'POST /pair-pin-start HTTP/1.1\r\nUser-Agent: AirPlay/320.20\r\nConnection: keep-alive\r\nX-Apple-HKP: 3\r\nContent-Type: application/octet-stream\r\n\r\n'
2022-02-01 21:29:06 DEBUG (MainThread) [pyatv.support.http] Received: b'HTTP/1.1 200 OK\r\nDate: Tue, 01 Feb 2022 20:29:05 GMT\r\nContent-Length: 0\r\nServer: AirTunes/605.1\r\n\r\n'
2022-02-01 21:29:06 DEBUG (MainThread) [pyatv.support.http] Got HTTP response: HttpResponse(protocol='HTTP', version='1.1', code=200, message='OK', headers={'date': 'Tue, 01 Feb 2022 20:29:05 GMT', 'content-length': '0', 'server': 'AirTunes/605.1'}, body=''):
2022-02-01 21:29:06 DEBUG (MainThread) [pyatv.support.http] Sending HTTP/1.1 message: b'POST /pair-setup HTTP/1.1\r\nContent-Length: 6\r\nUser-Agent: AirPlay/320.20\r\nConnection: keep-alive\r\nX-Apple-HKP: 3\r\nContent-Type: application/octet-stream\r\n\r\n\x00\x01\x00\x06\x01\x01'
2022-02-01 21:29:06 INFO (SyncWorker_12) [homeassistant.components.command_line.switch] Running state code command: false
2022-02-01 21:29:06 DEBUG (MainThread) [pyatv.support.http] Received: b'HTTP/1.1 200 OK\r\nDate: Tue, 01 Feb 2022 20:29:06 GMT\r\nContent-Length: 409\r\nContent-Type: application/x-apple-binary-plist\r\nServer: AirTunes/605.1\r\n\r\n\x06\x01\x02\x02\x10\xcc\x17\xc6".\x90\xa2\x84q\x9a\xe7\xa4\x98\xb4\xbb\x8c\x03\xff\x9d\x05|\x8e!\xec\x9d,\xe4\xeb\xac\xe7\xc0\xacb\xca\x1b\x96tx\xfb\xd5\xd3!D\xa0\xca\x1e\xbet\xcf/]\x1d\x9d\n. \xeb\xca\x91\x91\x82\xc6\x00\x99\xa5\xcb\xd74F\xfc\xb1D]\xc1\x9cn\xd2F\xd7\xf7\xf4\xb0%$\xf9\t\xd4\xa1\xe2\xff,lOT|\x82WI\x81\xe7!S\xef\xa1\x0e\xd5\x1d.\x1b\x19\xcd&\x9cx%\xd2\x9d\xdcb\xab\x0f%Sh\xdd\xae\xb1En\x1e\x00\x06\xb4\xa8\xfa\xd8\xa5o\xd8\xf4Iq#g\xf6)\x10\x92\xcba\x84-\x8cT\xa7fzT?\xfa\xd9\x05\xd5\xf03.\xd76\x99\xa3\x14\x15`\xb7\xe0}\xc4g,\xfa\xd0\x16\xc4\x81\xe9\xcf\x16Wj\x90\xe5\x14\x9e\x9b\x91\x8f\x82\xbf#*\x0b\xe0m\xb5\xec\x89NR\xa1B~}E\xeb`*`z,\xdf\xb0\x13\x8b\x85\xb2I%\xf3\xfc\x9c2\xd9c\xd4\xf2\xb8|\xa9\xf2,F\xec\xb2\x9d\x97\x90\x90\x97t\xd2-=\xda\xc3\xa4[z\x1a_3q\xc6\xcf\x94=3Ggy?\xaf^\xaa\x03\x81\xe8dS\x7fE\xdd\xceu\x88\xfbE\xcdP\xcf\x01c\xa9_\x0b-[\xf7\xac\x1bwo\xf1F\x85U\xb2\x8e\x1a&\x13\xeec:\x18\xa9\xf6!.h\xc8*\xfd\xae\x8f)[\xc5\x1e\xd6\x1c\x1a$\xb1{\x96n\xba\xa70\xfe\x95\x17\x8c\xf6\x02\x9e\x0b/\xd4\x90\x909\x12\xae\xb4\xd9\xd8-\xfa\x11I{\xf7\x01\xab\x84L7\xb6\xb9\xe8\x97\xc8\xb04\xed\xeb\x19\xea\x95\xd2f>-e\xb5\x13\xac\xc1\x9fD,\xc6\x8cl\x9a\x06\xc4Xt\xc7\xee!\xcd'
2022-02-01 21:29:06 DEBUG (MainThread) [pyatv.support.http] Got HTTP response: HttpResponse(protocol='HTTP', version='1.1', code=200, message='OK', headers={'date': 'Tue, 01 Feb 2022 20:29:06 GMT', 'content-length': '409', 'content-type': 'application/x-apple-binary-plist', 'server': 'AirTunes/605.1'}, body=b'\x06\x01\x02\x02\x10\xcc\x17\xc6".\x90\xa2\x84q\x9a\xe7\xa4\x98\xb4\xbb\x8c\x03\xff\x9d\x05|\x8e!\xec\x9d,\xe4\xeb\xac\xe7\xc0\xacb\xca\x1b\x96tx\xfb\xd5\xd3!D\xa0\xca\x1e\xbet\xcf/]\x1d\x9d\n. \xeb\xca\x91\x91\x82\xc6\x00\x99\xa5\xcb\xd74F\xfc\xb1D]\xc1\x9cn\xd2F\xd7\xf7\xf4\xb0%$\xf9\t\xd4\xa1\xe2\xff,lOT|\x82WI\x81\xe7!S\xef\xa1\x0e\xd5\x1d.\x1b\x19\xcd&\x9cx%\xd2\x9d\xdcb\xab\x0f%Sh\xdd\xae\xb1En\x1e\x00\x06\xb4\xa8\xfa\xd8\xa5o\xd8\xf4Iq#g\xf6)\x10\x92\xcba\x84-\x8cT\xa7fzT?\xfa\xd9\x05\xd5\xf03.\xd76\x99\xa3\x14\x15`\xb7\xe0}\xc4g,\xfa\xd0\x16\xc4\x81\xe9\xcf\x16Wj\x90\xe5\x14\x9e\x9b\x91\x8f\x82\xbf#*\x0b\xe0m\xb5\xec\x89NR\xa1B~}E\xeb`*`z,\xdf\xb0\x13\x8b\x85\xb2I%\xf3\xfc\x9c2\xd9c\xd4\xf2\xb8|\xa9\xf2,F\xec\xb2\x9d\x97\x90\x90\x97t\xd2-=\xda\xc3\xa4[z\x1a_3q\xc6\xcf\x94=3Ggy?\xaf^\xaa\x03\x81\xe8dS\x7fE\xdd\xceu\x88\xfbE\xcdP\xcf\x01c\xa9_\x0b-[\xf7\xac\x1bwo\xf1F\x85U\xb2\x8e\x1a&\x13\xeec:\x18\xa9\xf6!.h\xc8*\xfd\xae\x8f)[\xc5\x1e\xd6\x1c\x1a$\xb1{\x96n\xba\xa70\xfe\x95\x17\x8c\xf6\x02\x9e\x0b/\xd4\x90\x909\x12\xae\xb4\xd9\xd8-\xfa\x11I{\xf7\x01\xab\x84L7\xb6\xb9\xe8\x97\xc8\xb04\xed\xeb\x19\xea\x95\xd2f>-e\xb5\x13\xac\xc1\x9fD,\xc6\x8cl\x9a\x06\xc4Xt\xc7\xee!\xcd'):
2022-02-01 21:29:07 INFO (MainThread) [pyhap.hap_protocol] ('10.0.57.27', 49568): Connection made to HA General
2022-02-01 21:29:11 DEBUG (MainThread) [pyatv.protocols.airplay.pairing] AirPlay PIN changed to 5405
2022-02-01 21:29:12 DEBUG (MainThread) [pyatv.auth.hap_srp] Client (Proof=02d3bbb04bff014277c30f8fa112d3a7119fa45db0902af874a20519dd01bf569678f9d3bd1a1c8fd56ef7873115d9445cacbd8ea728f46728ca38813a494b10, Public=1a21788e53f53d6b9974526672e1855af1d1dfa00d4b2cbc7b085cb93218a4790b5b169a044c112df2ed2195dac664d3c8edeecdfd864857235ae9a8a9e5f2bc28e199bb79fefa85c691b7a34a0d47b26d38c254749191ceb5a6cbd337f970714f34f88a61bf8f35a52d4f71e84e96e267f3d17eac4e5982c3c977694e2a08fe63a3f0ecb983b00e7f3536b1ac2b6d8900b72139d1561d7d3976a8f54711d45dd1b1248dde26a248cc8cadba98ab0a8ec0a8f845c43f37d9f1d24b5684d2864d74c9d3d3adc67efe2e7f10e7326e86de5b88097e8b2d7a446f338329a7319fd8b8d38163720557e95bbab45462e234cca9ee8705de7f5ada798976c1d1ca2...)
2022-02-01 21:29:12 DEBUG (MainThread) [pyatv.support.http] Sending HTTP/1.1 message: b"POST /pair-setup HTTP/1.1\r\nContent-Length: 457\r\nUser-Agent: AirPlay/320.20\r\nConnection: keep-alive\r\nX-Apple-HKP: 3\r\nContent-Type: application/octet-stream\r\n\r\n\x06\x01\x03\x03\xff\x1a!x\x8eS\xf5=k\x99tRfr\xe1\x85Z\xf1\xd1\xdf\xa0\rK,\xbc{\x08\\\xb92\x18\xa4y\x0b[\x16\x9a\x04L\x11-\xf2\xed!\x95\xda\xc6d\xd3\xc8\xed\xee\xcd\xfd\x86HW#Z\xe9\xa8\xa9\xe5\xf2\xbc(\xe1\x99\xbby\xfe\xfa\x85\xc6\x91\xb7\xa3J\rG\xb2m8\xc2Tt\x91\x91\xce\xb5\xa6\xcb\xd37\xf9pqO4\xf8\x8aa\xbf\x8f5\xa5-Oq\xe8N\x96\xe2g\xf3\xd1~\xacNY\x82\xc3\xc9wiN*\x08\xfec\xa3\xf0\xec\xb9\x83\xb0\x0e\x7f56\xb1\xac+m\x89\x00\xb7!9\xd1V\x1d}9v\xa8\xf5G\x11\xd4]\xd1\xb1$\x8d\xde&\xa2H\xcc\x8c\xad\xba\x98\xab\n\x8e\xc0\xa8\xf8E\xc4?7\xd9\xf1\xd2KV\x84\xd2\x86Mt\xc9\xd3\xd3\xad\xc6~\xfe.\x7f\x10\xe72n\x86\xde[\x88\t~\x8b-zDo3\x83)\xa71\x9f\xd8\xb8\xd3\x81cr\x05W\xe9[\xba\xb4Tb\xe24\xcc\xa9\xee\x87\x05\xde\x7fZ\xday\x89v\xc1\xd1\xca&\x03\x81\xeb\x12[\x1b\x9a,\xe6\xf6\xbb\xd7\xd4k9\x02\xd5\xb3\x9dn\xafF\xd1\xc4w\xfe\xec\x9a\xb9\x1aZ\xa4,3/\x0c'\x8b\xc7\x99eSS\xd0L\xf9\xd2\xde\xab\xd3\x8d4\xba\xcb\x03\x01C\xd0\x96\xffR3\xe0$\xe9\xfa\xf6\x846\xae}\xa9_\xdd\xdc\x1a1\x9b\x97\xc7\xe0ih\xaa\xe6%\xce3\x9f\xb8\x07t\xb1\xc6M\x12\x9bFa\x13\xf2_x\xaaZ\x03\xec\x05\x88\xc2\xe1>r\x94\xc2\x85\xa3\xcb\xf4D \xea{\x8b\xb2\xc2%t\xfb\xe5p\x04@\x02\xd3\xbb\xb0K\xff\x01Bw\xc3\x0f\x8f\xa1\x12\xd3\xa7\x11\x9f\xa4]\xb0\x90*\xf8t\xa2\x05\x19\xdd\x01\xbfV\x96x\xf9\xd3\xbd\x1a\x1c\x8f\xd5n\xf7\x871\x15\xd9D\\\xac\xbd\x8e\xa7(\xf4g(\xca8\x81:IK\x10"
2022-02-01 21:29:12 DEBUG (MainThread) [pyatv.support.http] Received: b'HTTP/1.1 200 OK\r\nDate: Tue, 01 Feb 2022 20:29:12 GMT\r\nContent-Length: 69\r\nContent-Type: application/x-apple-binary-plist\r\nServer: AirTunes/605.1\r\n\r\n\x06\x01\x04\x04@\xeeu\x1a\x03\x0f\x1d=\x17\x99\x11\x87@\xeb\x9b\x08\x93\x91\x12\xb6e\xb5O\xee\xfe\x82\x17Dd\xe8a\xd0\x85\x1cy\xbb\xb2D\xd3X\x05"\xb0\x93]u\x11\xb46\x05u\xe2\xb8R\xcb\x9d\x02?]\x8aC\x85\x8e\xcb\xd5'
2022-02-01 21:29:12 DEBUG (MainThread) [pyatv.support.http] Got HTTP response: HttpResponse(protocol='HTTP', version='1.1', code=200, message='OK', headers={'date': 'Tue, 01 Feb 2022 20:29:12 GMT', 'content-length': '69', 'content-type': 'application/x-apple-binary-plist', 'server': 'AirTunes/605.1'}, body=b'\x06\x01\x04\x04@\xeeu\x1a\x03\x0f\x1d=\x17\x99\x11\x87@\xeb\x9b\x08\x93\x91\x12\xb6e\xb5O\xee\xfe\x82\x17Dd\xe8a\xd0\x85\x1cy\xbb\xb2D\xd3X\x05"\xb0\x93]u\x11\xb46\x05u\xe2\xb8R\xcb\x9d\x02?]\x8aC\x85\x8e\xcb\xd5'):
2022-02-01 21:29:12 DEBUG (MainThread) [pyatv.auth.hap_srp] Data (Encrypted=5b43e7e18a6be778f5f341fb2a3d355e9680493ba7c118b23bcbc80ab826a301c3adb74b28e3d76f1e175b357986fad5c3d9e7402ecef91ec80ffcad79d64cee38c9308c0594d599905c70857d4a2605f643e156e130a039f15f7d8df540eecd9712ee9fe058117836e97c38631cd3cb4aaecbd4f1d3ac052e592bb5488fb4b3db4c3e0167395713883fc66ec5b688cb8d554cf9620a387aed06)
2022-02-01 21:29:12 DEBUG (MainThread) [pyatv.support.http] Sending HTTP/1.1 message: b'POST /pair-setup HTTP/1.1\r\nContent-Length: 159\r\nUser-Agent: AirPlay/320.20\r\nConnection: keep-alive\r\nX-Apple-HKP: 3\r\nContent-Type: application/octet-stream\r\n\r\n\x06\x01\x05\x05\x9a[C\xe7\xe1\x8ak\xe7x\xf5\xf3A\xfb*=5^\x96\x80I;\xa7\xc1\x18\xb2;\xcb\xc8\n\xb8&\xa3\x01\xc3\xad\xb7K(\xe3\xd7o\x1e\x17[5y\x86\xfa\xd5\xc3\xd9\xe7@.\xce\xf9\x1e\xc8\x0f\xfc\xady\xd6L\xee8\xc90\x8c\x05\x94\xd5\x99\x90\\p\x85}J&\x05\xf6C\xe1V\xe10\xa09\xf1_}\x8d\xf5@\xee\xcd\x97\x12\xee\x9f\xe0X\x11x6\xe9|8c\x1c\xd3\xcbJ\xae\xcb\xd4\xf1\xd3\xac\x05.Y+\xb5H\x8f\xb4\xb3\xdbL>\x01g9W\x13\x88?\xc6n\xc5\xb6\x88\xcb\x8dUL\xf9b\n8z\xed\x06'
2022-02-01 21:29:12 DEBUG (MainThread) [pyatv.support.http] Received: b'HTTP/1.1 200 OK\r\nDate: Tue, 01 Feb 2022 20:29:12 GMT\r\nContent-Length: 318\r\nContent-Type: application/x-apple-binary-plist\r\nServer: AirTunes/605.1\r\n\r\n\x05\xffB\x14\x9b\x08\xc9k\xbeK\xc3\xa9\xf5.\x8f\xeb\xcd\x04\xb7\x92#\x97\nl\xd2\xed\x1c\x12!\x1c\x1eC+\x9d\xe1\xc09\xb1\xa9\x8e\ts\\\xf4\\\xf7\xf6\xd8\t\xc1\x93|\xbf\x17V\x94by\xb1\xa2\xcdL\x9ah\x1ffX\x88\x16\xdc\xaa[\xba\x90>\xfe\xf5=\xb3\xd3\xef\xbf\xab\x10}\xcbM(\xba8|\xc0\x1c\xef\\\x06f5\xae\x08#\xd2!\x90~2R\xc8\x19b\xf07\x9fw\xa8\x06T\x07\xa1\x07S\xccR\xe1e;\x82i\x8b\xa5\xb9\xd9\x7fAv\xd7b\x9b\xd8\xbc~\xe0\xc8\xb1 \x87+*\xf0\xce\xd0E\x848\x8a\xaf\x0c\xdc\x109Q\xb7@\x85\xdc qr_>\xae:D\x02&*H\xf1\xc1\xb6>Q@\xf32\x05o\x0bn\x84P\xb4\x00\xed\xf5u\x11\xf2\xc9&\\\xc1o\xd1\xec\x0b\xf9\r\xfc\xcf\x0bU\x18\x08y>\x1c\x1e\xc2?\n6\xbe\xd7C\xe4g\xad\xed\xff\x88\xad\xbc\x90\xfb\xaf.\xe8\xd8\x8e/1\xbc5A;c\x1bzy\x90p\xe4Ei0\x80\x058\xc5\x0e\xd7L#\xb4\x1e\xc7\x8e\xba\xc2\xb7\x81|\x82q\xa0\xb3\xb1\x1c\xfa\x98[\xe4\x9b\x02\xdc-\xa5cC!m\x1d`\xd0\xder\x13\x03\\j5>d#}V]W\x8d\x9c{c)T\x06\x01\x06'
2022-02-01 21:29:12 DEBUG (MainThread) [pyatv.support.http] Got HTTP response: HttpResponse(protocol='HTTP', version='1.1', code=200, message='OK', headers={'date': 'Tue, 01 Feb 2022 20:29:12 GMT', 'content-length': '318', 'content-type': 'application/x-apple-binary-plist', 'server': 'AirTunes/605.1'}, body=b'\x05\xffB\x14\x9b\x08\xc9k\xbeK\xc3\xa9\xf5.\x8f\xeb\xcd\x04\xb7\x92#\x97\nl\xd2\xed\x1c\x12!\x1c\x1eC+\x9d\xe1\xc09\xb1\xa9\x8e\ts\\\xf4\\\xf7\xf6\xd8\t\xc1\x93|\xbf\x17V\x94by\xb1\xa2\xcdL\x9ah\x1ffX\x88\x16\xdc\xaa[\xba\x90>\xfe\xf5=\xb3\xd3\xef\xbf\xab\x10}\xcbM(\xba8|\xc0\x1c\xef\\\x06f5\xae\x08#\xd2!\x90~2R\xc8\x19b\xf07\x9fw\xa8\x06T\x07\xa1\x07S\xccR\xe1e;\x82i\x8b\xa5\xb9\xd9\x7fAv\xd7b\x9b\xd8\xbc~\xe0\xc8\xb1 \x87+*\xf0\xce\xd0E\x848\x8a\xaf\x0c\xdc\x109Q\xb7@\x85\xdc qr_>\xae:D\x02&*H\xf1\xc1\xb6>Q@\xf32\x05o\x0bn\x84P\xb4\x00\xed\xf5u\x11\xf2\xc9&\\\xc1o\xd1\xec\x0b\xf9\r\xfc\xcf\x0bU\x18\x08y>\x1c\x1e\xc2?\n6\xbe\xd7C\xe4g\xad\xed\xff\x88\xad\xbc\x90\xfb\xaf.\xe8\xd8\x8e/1\xbc5A;c\x1bzy\x90p\xe4Ei0\x80\x058\xc5\x0e\xd7L#\xb4\x1e\xc7\x8e\xba\xc2\xb7\x81|\x82q\xa0\xb3\xb1\x1c\xfa\x98[\xe4\x9b\x02\xdc-\xa5cC!m\x1d`\xd0\xder\x13\x03\\j5>d#}V]W\x8d\x9c{c)T\x06\x01\x06'):
2022-02-01 21:29:12 DEBUG (MainThread) [pyatv.auth.hap_srp] PS-Msg06: {1: b'4928B0BE-578E-40C6-BC60-69BA36B3E8B7', 3: b'\xb1&\xd9\xcc\x07\t\x02x\xa4\xb2\xc3<e\r\x87{\xdd\xd8\x8e\x0fr2\xb7\xd7K\x96^\x8f\xc3\x90\xc3\x05', 10: b'\xdf8NdJ@o\xd9\xc3F\n\xf91\x99C>\'4O\t\xd5\xdb\xa7\x11yNM_\xb6k1\xe8\x83\x1c\x0em\x97\x10\xe4\xb1R\\\xe5\xf2N\xd8J\x9f}=L\x97\x07\xfe\xef\xee\x84:\xd80\x94\xed"\x07', 17: b'\xe7FaltIRK\x80\xc3]\xb3\xb1\x96\xac3\xe9<*\xae\x17\xb8,\x811FbtAddrQd0:03:4b:38:4a:bdCmacv\xd0\x03K8J\xbeIaccountIDa$4928B0BE-578E-40C6-BC60-69BA36B3E8B7EmodelJAppleTV5,3GwifiMACv\xd0\x03K8J\xbcDnameHAppleTv4'}
2022-02-01 21:29:12 DEBUG (MainThread) [pyatv.auth.hap_srp] Device (Identifier=34393238423042452d353738452d343043362d424336302d363942413336423345384237, Public=b126d9cc07090278a4b2c33c650d877bddd88e0f7232b7d74b965e8fc390c305, Signature=df384e644a406fd9c3460af93199433e27344f09d5dba711794e4d5fb66b31e8831c0e6d9710e4b1525ce5f24ed84a9f7d3d4c9707feefee843ad83094ed2207)
2022-02-01 21:29:12 DEBUG (MainThread) [homeassistant.components.apple_tv.config_flow] Protocol.Companion requires pairing
2022-02-01 21:29:12 DEBUG (MainThread) [pyatv.protocols.companion.pairing] Start pairing Companion
2022-02-01 21:29:12 DEBUG (MainThread) [pyatv.support.http] Connection closed
2022-02-01 21:29:12 DEBUG (MainThread) [pyatv.protocols.companion.connection] Connected to companion device 10.0.57.54:49152
2022-02-01 21:29:12 DEBUG (MainThread) [pyatv.protocols.companion.protocol] Companion credentials: None
2022-02-01 21:29:12 DEBUG (MainThread) [pyatv.protocols.companion.protocol] Exchange OPACK: {'_pd': b'\x00\x01\x00\x06\x01\x01', '_pwTy': 1}
2022-02-01 21:29:12 DEBUG (MainThread) [pyatv.protocols.companion.protocol] Send OPACK: {'_pd': b'\x00\x01\x00\x06\x01\x01', '_pwTy': 1, '_x': 28258}
2022-02-01 21:29:12 DEBUG (MainThread) [pyatv.protocols.companion.connection] >> Send data (Data=e3435f706476000100060101455f7077547909425f7831626e, FrameType=03)
2022-02-01 21:29:13 DEBUG (MainThread) [pyatv.protocols.companion.connection] Received data (Data=040001a4e1435f7064929c010601020210a14ffba0626d4d9329f617b68cda0f1703ff7b8161a6ee1f89c8190f182a80e4ac42439809a35f5c9e87463c7ace3c37c3b755b5c8a373659ba61650190770f42b1be1d685169f3ed1402e64b58967d7ab9879c0410f65a88f7096622ad222d6d5d269da2ef4227db9430993561e52f0f0a3a4505002c5d8d1d7f9884c69280ef39487859dd075fd54b49570396135e378401b5b24ee4d1667bacee960fc836d4b778de700d0ea465ac1534a5267a1d9108da9f271bc7c97b612bd1b8b2e17e2ade128ffdacc8954f1b968ff26d50457846388a60a69dc45a459c5c0b322548d4602b49ed4ecc82b6770143658b...)
2022-02-01 21:29:13 DEBUG (MainThread) [pyatv.protocols.companion.protocol] Received frame FrameType.PS_Next: b'\xe1C_pd\x92\x9c\x01\x06\x01\x02\x02\x10\xa1O\xfb\xa0bmM\x93)\xf6\x17\xb6\x8c\xda\x0f\x17\x03\xff{\x81a\xa6\xee\x1f\x89\xc8\x19\x0f\x18*\x80\xe4\xacBC\x98\t\xa3_\\\x9e\x87F<z\xce<7\xc3\xb7U\xb5\xc8\xa3se\x9b\xa6\x16P\x19\x07p\xf4+\x1b\xe1\xd6\x85\x16\x9f>\xd1@.d\xb5\x89g\xd7\xab\x98y\xc0A\x0fe\xa8\x8fp\x96b*\xd2"\xd6\xd5\xd2i\xda.\xf4"}\xb9C\t\x93V\x1eR\xf0\xf0\xa3\xa4PP\x02\xc5\xd8\xd1\xd7\xf9\x88Li(\x0e\xf3\x94\x87\x85\x9d\xd0u\xfdT\xb4\x95p9a5\xe3x@\x1b[$\xeeM\x16g\xba\xce\xe9`\xfc\x83mKw\x8d\xe7\x00\xd0\xeaFZ\xc1SJRg\xa1\xd9\x10\x8d\xa9\xf2q\xbc|\x97\xb6\x12\xbd\x1b\x8b.\x17\xe2\xad\xe1(\xff\xda\xcc\x89T\xf1\xb9h\xff&\xd5\x04W\x84c\x88\xa6\ni\xdcE\xa4Y\xc5\xc0\xb3"T\x8dF\x02\xb4\x9e\xd4\xec\xc8+gp\x146X\xb0`\xb30\xa1\xf9\x1cf$!\x19\xdc\x0f\x84-1\xf9\xbbI\x87Y\xf9\'wr\t\xb5*\xae\x1ey\x14\x90\xe1\xf5\xe7\x03\x81\xbc\xf7ob\xb3\xb4\xb16\xb35\x90\x01M\x90$`\xc0\xee\xa2=i\xe7\x07\xdb\xe7~-\r\xdb\xeay\x19)*\xb3gS\xea\xf5\xf4|\x8bI`\xcc\xe0\xb2\xe8\x9cs\xd5\xec\xd2\xbc\xc3\xda\xee.\xa5\x7f\xca\xbfzy\xde\xb5\xf3\xd1\xcd\x8b_\xca>>\x7f\xc7\x0b\x0e\xa3\x85C\xd6|\xa8\xf9\xab\x00QU\xcfF\xed\x9a2;X9\x91cjj\xf3\x16\t\xda<9\x00=\xb6\xf8\x96\xe0\xe8}\xf7\xcd\x83\x01t\xde\xb7\xa8\x891b\xa5y\x96\x1b\x01\x01'
2022-02-01 21:29:13 DEBUG (MainThread) [pyatv.protocols.companion.protocol] Process incoming auth frame (FrameType.PS_Next): {'_pd': b'\x06\x01\x02\x02\x10\xa1O\xfb\xa0bmM\x93)\xf6\x17\xb6\x8c\xda\x0f\x17\x03\xff{\x81a\xa6\xee\x1f\x89\xc8\x19\x0f\x18*\x80\xe4\xacBC\x98\t\xa3_\\\x9e\x87F<z\xce<7\xc3\xb7U\xb5\xc8\xa3se\x9b\xa6\x16P\x19\x07p\xf4+\x1b\xe1\xd6\x85\x16\x9f>\xd1@.d\xb5\x89g\xd7\xab\x98y\xc0A\x0fe\xa8\x8fp\x96b*\xd2"\xd6\xd5\xd2i\xda.\xf4"}\xb9C\t\x93V\x1eR\xf0\xf0\xa3\xa4PP\x02\xc5\xd8\xd1\xd7\xf9\x88Li(\x0e\xf3\x94\x87\x85\x9d\xd0u\xfdT\xb4\x95p9a5\xe3x@\x1b[$\xeeM\x16g\xba\xce\xe9`\xfc\x83mKw\x8d\xe7\x00\xd0\xeaFZ\xc1SJRg\xa1\xd9\x10\x8d\xa9\xf2q\xbc|\x97\xb6\x12\xbd\x1b\x8b.\x17\xe2\xad\xe1(\xff\xda\xcc\x89T\xf1\xb9h\xff&\xd5\x04W\x84c\x88\xa6\ni\xdcE\xa4Y\xc5\xc0\xb3"T\x8dF\x02\xb4\x9e\xd4\xec\xc8+gp\x146X\xb0`\xb30\xa1\xf9\x1cf$!\x19\xdc\x0f\x84-1\xf9\xbbI\x87Y\xf9\'wr\t\xb5*\xae\x1ey\x14\x90\xe1\xf5\xe7\x03\x81\xbc\xf7ob\xb3\xb4\xb16\xb35\x90\x01M\x90$`\xc0\xee\xa2=i\xe7\x07\xdb\xe7~-\r\xdb\xeay\x19)*\xb3gS\xea\xf5\xf4|\x8bI`\xcc\xe0\xb2\xe8\x9cs\xd5\xec\xd2\xbc\xc3\xda\xee.\xa5\x7f\xca\xbfzy\xde\xb5\xf3\xd1\xcd\x8b_\xca>>\x7f\xc7\x0b\x0e\xa3\x85C\xd6|\xa8\xf9\xab\x00QU\xcfF\xed\x9a2;X9\x91cjj\xf3\x16\t\xda<9\x00=\xb6\xf8\x96\xe0\xe8}\xf7\xcd\x83\x01t\xde\xb7\xa8\x891b\xa5y\x96\x1b\x01\x01'}
2022-02-01 21:29:13 DEBUG (MainThread) [pyatv.protocols.companion.auth] Got pub key and salt (PubKey=7b8161a6ee1f89c8190f182a80e4ac42439809a35f5c9e87463c7ace3c37c3b755b5c8a373659ba61650190770f42b1be1d685169f3ed1402e64b58967d7ab9879c0410f65a88f7096622ad222d6d5d269da2ef4227db9430993561e52f0f0a3a4505002c5d8d1d7f9884c69280ef39487859dd075fd54b49570396135e378401b5b24ee4d1667bacee960fc836d4b778de700d0ea465ac1534a5267a1d9108da9f271bc7c97b612bd1b8b2e17e2ade128ffdacc8954f1b968ff26d50457846388a60a69dc45a459c5c0b322548d4602b49ed4ecc82b6770143658b060b330a1f91c66242119dc0f842d31f9bb498759f927777209b52aae1e791490e1f5e..., Salt=a14ffba0626d4d9329f617b68cda0f17)
2022-02-01 21:29:20 DEBUG (MainThread) [pyatv.protocols.companion.pairing] Companion PIN changed to 2430
2022-02-01 21:29:20 DEBUG (MainThread) [pyatv.protocols.companion.pairing] Finish pairing Companion
2022-02-01 21:29:20 DEBUG (MainThread) [pyatv.auth.hap_srp] Client (Proof=c5eb64d4f11f51556f70f82ab2de9c00cdfb71a468e929ccc8a65d91ffac31d6dded12a51b223980f16cc34ca574324dbc9550c71c71c64ec016ecadc29ec01a, Public=c5e4ebc5b8dd70e9ea511e9dbf2b40e3f8a5b389d240a658aa22091f4911e2cdc0ca46f29801febaf187b353968db0a199c517658224cacdfe63241832dba6d3c72f8a7f4723b3bada3f3fd5be799099a87188df8e8cc63f6e2ec75c7a88e26c1777e6b6362463b91405e3dfc56478755da9c15b8dec13393e12c9d7995c287a564825290cef0fc14accc2be25f61c45fc13abcbd8cd6436aece5c6a795fcb4cd2a7cf921903380ec0ffb48eb78030d332d11895622bb9acdef97910de30b5e28e344704c090211d57440b985d5cb0c00ed2f6b58dd7dd855714afe50b313fb38874e392b0560b416cf37c8fd08bc0c48655b2654002bee1e2d62eb67ad00...)
2022-02-01 21:29:20 DEBUG (MainThread) [pyatv.protocols.companion.protocol] Exchange OPACK: {'_pd': b'\x06\x01\x03\x03\xff\xc5\xe4\xeb\xc5\xb8\xddp\xe9\xeaQ\x1e\x9d\xbf+@\xe3\xf8\xa5\xb3\x89\xd2@\xa6X\xaa"\t\x1fI\x11\xe2\xcd\xc0\xcaF\xf2\x98\x01\xfe\xba\xf1\x87\xb3S\x96\x8d\xb0\xa1\x99\xc5\x17e\x82$\xca\xcd\xfec$\x182\xdb\xa6\xd3\xc7/\x8a\x7fG#\xb3\xba\xda??\xd5\xbey\x90\x99\xa8q\x88\xdf\x8e\x8c\xc6?n.\xc7\\z\x88\xe2l\x17w\xe6\xb66$c\xb9\x14\x05\xe3\xdf\xc5dxu]\xa9\xc1[\x8d\xec\x139>\x12\xc9\xd7\x99\\(zVH%)\x0c\xef\x0f\xc1J\xcc\xc2\xbe%\xf6\x1cE\xfc\x13\xab\xcb\xd8\xcdd6\xae\xce\\jy_\xcbL\xd2\xa7\xcf\x92\x19\x038\x0e\xc0\xff\xb4\x8e\xb7\x800\xd32\xd1\x18\x95b+\xb9\xac\xde\xf9y\x10\xde0\xb5\xe2\x8e4G\x04\xc0\x90!\x1dWD\x0b\x98]\\\xb0\xc0\x0e\xd2\xf6\xb5\x8d\xd7\xdd\x85W\x14\xaf\xe5\x0b1?\xb3\x88t\xe3\x92\xb0V\x0bAl\xf3|\x8f\xd0\x8b\xc0\xc4\x86U\xb2e@\x02\xbe\xe1\xe2\xd6.\xb6z\xd0\r\x03\x81Q\xb0\x9dX\xb4\x95\x8b#\xc8\xdc\x85#\x84*\x12\x0bZ\xda?\xc1\x81f\xf3\xa81\x1f\x97H%\x00\xf8?\xafi\xbb}\xf5\xcf\xb3\x14\xaa\xb1%\xf2\x91\x92Dbp\n\xebk\x11W]\xfa\xb6L*5P\xe8Y\xef\xacE((\x06\x02\xad\x00\xebO\x04\x12!\xbb\x92r\xbe\x04w\xc7k1\x12\x04E\xd30h\xa6\x13\x1b\xaa\xab\x8d\xf8M\xe4\xdf\x9a\xd8#mr\xbd\xaeiUz\'Gu\xce\xec\n\x04\x99\x0e\x8a\xca\xab\x83B\x82\x11\xbe\x04@\xc5\xebd\xd4\xf1\x1fQUop\xf8*\xb2\xde\x9c\x00\xcd\xfbq\xa4h\xe9)\xcc\xc8\xa6]\x91\xff\xac1\xd6\xdd\xed\x12\xa5\x1b"9\x80\xf1l\xc3L\xa5t2M\xbc\x95P\xc7\x1cq\xc6N\xc0\x16\xec\xad\xc2\x9e\xc0\x1a', '_pwTy': 1}
2022-02-01 21:29:20 DEBUG (MainThread) [pyatv.protocols.companion.protocol] Send OPACK: {'_pd': b'\x06\x01\x03\x03\xff\xc5\xe4\xeb\xc5\xb8\xddp\xe9\xeaQ\x1e\x9d\xbf+@\xe3\xf8\xa5\xb3\x89\xd2@\xa6X\xaa"\t\x1fI\x11\xe2\xcd\xc0\xcaF\xf2\x98\x01\xfe\xba\xf1\x87\xb3S\x96\x8d\xb0\xa1\x99\xc5\x17e\x82$\xca\xcd\xfec$\x182\xdb\xa6\xd3\xc7/\x8a\x7fG#\xb3\xba\xda??\xd5\xbey\x90\x99\xa8q\x88\xdf\x8e\x8c\xc6?n.\xc7\\z\x88\xe2l\x17w\xe6\xb66$c\xb9\x14\x05\xe3\xdf\xc5dxu]\xa9\xc1[\x8d\xec\x139>\x12\xc9\xd7\x99\\(zVH%)\x0c\xef\x0f\xc1J\xcc\xc2\xbe%\xf6\x1cE\xfc\x13\xab\xcb\xd8\xcdd6\xae\xce\\jy_\xcbL\xd2\xa7\xcf\x92\x19\x038\x0e\xc0\xff\xb4\x8e\xb7\x800\xd32\xd1\x18\x95b+\xb9\xac\xde\xf9y\x10\xde0\xb5\xe2\x8e4G\x04\xc0\x90!\x1dWD\x0b\x98]\\\xb0\xc0\x0e\xd2\xf6\xb5\x8d\xd7\xdd\x85W\x14\xaf\xe5\x0b1?\xb3\x88t\xe3\x92\xb0V\x0bAl\xf3|\x8f\xd0\x8b\xc0\xc4\x86U\xb2e@\x02\xbe\xe1\xe2\xd6.\xb6z\xd0\r\x03\x81Q\xb0\x9dX\xb4\x95\x8b#\xc8\xdc\x85#\x84*\x12\x0bZ\xda?\xc1\x81f\xf3\xa81\x1f\x97H%\x00\xf8?\xafi\xbb}\xf5\xcf\xb3\x14\xaa\xb1%\xf2\x91\x92Dbp\n\xebk\x11W]\xfa\xb6L*5P\xe8Y\xef\xacE((\x06\x02\xad\x00\xebO\x04\x12!\xbb\x92r\xbe\x04w\xc7k1\x12\x04E\xd30h\xa6\x13\x1b\xaa\xab\x8d\xf8M\xe4\xdf\x9a\xd8#mr\xbd\xaeiUz\'Gu\xce\xec\n\x04\x99\x0e\x8a\xca\xab\x83B\x82\x11\xbe\x04@\xc5\xebd\xd4\xf1\x1fQUop\xf8*\xb2\xde\x9c\x00\xcd\xfbq\xa4h\xe9)\xcc\xc8\xa6]\x91\xff\xac1\xd6\xdd\xed\x12\xa5\x1b"9\x80\xf1l\xc3L\xa5t2M\xbc\x95P\xc7\x1cq\xc6N\xc0\x16\xec\xad\xc2\x9e\xc0\x1a', '_pwTy': 1, '_x': 28259}
2022-02-01 21:29:20 DEBUG (MainThread) [pyatv.protocols.companion.connection] >> Send data (Data=e3435f706492c90106010303ffc5e4ebc5b8dd70e9ea511e9dbf2b40e3f8a5b389d240a658aa22091f4911e2cdc0ca46f29801febaf187b353968db0a199c517658224cacdfe63241832dba6d3c72f8a7f4723b3bada3f3fd5be799099a87188df8e8cc63f6e2ec75c7a88e26c1777e6b6362463b91405e3dfc56478755da9c15b8dec13393e12c9d7995c287a564825290cef0fc14accc2be25f61c45fc13abcbd8cd6436aece5c6a795fcb4cd2a7cf921903380ec0ffb48eb78030d332d11895622bb9acdef97910de30b5e28e344704c090211d57440b985d5cb0c00ed2f6b58dd7dd855714afe50b313fb38874e392b0560b416cf37c8fd08bc0c4865..., FrameType=04)
2022-02-01 21:29:20 DEBUG (MainThread) [pyatv.protocols.companion.connection] Received data (Data=0400004ce1435f706491450601040440d6f957ba18d124252bf1177d5926ff98b57c590e3149609d8b1d1faacc777b041aa7884c6458365df52f70a212fb5e31b6a3eb8d3ef21b237861f165732512f0)
2022-02-01 21:29:20 DEBUG (MainThread) [pyatv.protocols.companion.protocol] Received frame FrameType.PS_Next: b'\xe1C_pd\x91E\x06\x01\x04\x04@\xd6\xf9W\xba\x18\xd1$%+\xf1\x17}Y&\xff\x98\xb5|Y\x0e1I`\x9d\x8b\x1d\x1f\xaa\xccw{\x04\x1a\xa7\x88LdX6]\xf5/p\xa2\x12\xfb^1\xb6\xa3\xeb\x8d>\xf2\x1b#xa\xf1es%\x12\xf0'
2022-02-01 21:29:20 DEBUG (MainThread) [pyatv.protocols.companion.protocol] Process incoming auth frame (FrameType.PS_Next): {'_pd': b'\x06\x01\x04\x04@\xd6\xf9W\xba\x18\xd1$%+\xf1\x17}Y&\xff\x98\xb5|Y\x0e1I`\x9d\x8b\x1d\x1f\xaa\xccw{\x04\x1a\xa7\x88LdX6]\xf5/p\xa2\x12\xfb^1\xb6\xa3\xeb\x8d>\xf2\x1b#xa\xf1es%\x12\xf0'}
2022-02-01 21:29:20 DEBUG (MainThread) [pyatv.protocols.companion.auth] Device (Proof=d6f957ba18d124252bf1177d5926ff98b57c590e3149609d8b1d1faacc777b041aa7884c6458365df52f70a212fb5e31b6a3eb8d3ef21b237861f165732512f0)
2022-02-01 21:29:20 DEBUG (MainThread) [pyatv.auth.hap_srp] Data (Encrypted=a68a91fc5073d470258cd5b6ff1ab303f3dcf9c5cdc12720c889046dc9676c2b4f3b1764f0b08871d844e441a9b94b3667220879b75cd74beba4338784e11e2027044add0b1e1b6174e46513a532080f43cb7c3f9b95bc71398249c6627ef0d1907e4f3f8a0aff728967bacd698953bcf5f3efc6704026a7b3134e528904fe9a0ec1480ad52a357598d4a8dd19e373c78ec8771eefe7f2a034899be57795d887b25f7ef30f121f41089b47ae3eb42083411d649eba8974ee32f7263371073df29346e6423f79d993417ced1c9a3b6cd363926e45390d354e7f6531fe3e562110b16df9532fa0ec965c4bc2dac354496672e4d08885d777f3166fb4190bf16...)
2022-02-01 21:29:20 DEBUG (MainThread) [pyatv.protocols.companion.protocol] Exchange OPACK: {'_pd': b'\x06\x01\x05\x05\xff\xa6\x8a\x91\xfcPs\xd4p%\x8c\xd5\xb6\xff\x1a\xb3\x03\xf3\xdc\xf9\xc5\xcd\xc1\' \xc8\x89\x04m\xc9gl+O;\x17d\xf0\xb0\x88q\xd8D\xe4A\xa9\xb9K6g"\x08y\xb7\\\xd7K\xeb\xa43\x87\x84\xe1\x1e \'\x04J\xdd\x0b\x1e\x1bat\xe4e\x13\xa52\x08\x0fC\xcb|?\x9b\x95\xbcq9\x82I\xc6b~\xf0\xd1\x90~O?\x8a\n\xffr\x89g\xba\xcdi\x89S\xbc\xf5\xf3\xef\xc6p@&\xa7\xb3\x13NR\x89\x04\xfe\x9a\x0e\xc1H\n\xd5*5u\x98\xd4\xa8\xdd\x19\xe3s\xc7\x8e\xc8w\x1e\xef\xe7\xf2\xa04\x89\x9b\xe5w\x95\xd8\x87\xb2_~\xf3\x0f\x12\x1fA\x08\x9bG\xae>\xb4 \x83A\x1dd\x9e\xba\x89t\xee2\xf7&3q\x07=\xf2\x93F\xe6B?y\xd9\x93A|\xed\x1c\x9a;l\xd3c\x92nE9\r5N\x7fe1\xfe>V!\x10\xb1m\xf9S/\xa0\xec\x96\\K\xc2\xda\xc3TIfr\xe4\xd0\x88\x85\xd7w\xf3\x16o\xb4\x19\x0b\xf1i\x05"\xa5\xff$,\r\x84 $/\xa6\xbb\xfed\x89\xbd.\xaf+\x1a\x0b\x9a\x1c\x05\xb1\xcf\xbbI\xba\xd1\xc1\r\xc0\x9a\x1c', '_pwTy': 1}
2022-02-01 21:29:20 DEBUG (MainThread) [pyatv.protocols.companion.protocol] Send OPACK: {'_pd': b'\x06\x01\x05\x05\xff\xa6\x8a\x91\xfcPs\xd4p%\x8c\xd5\xb6\xff\x1a\xb3\x03\xf3\xdc\xf9\xc5\xcd\xc1\' \xc8\x89\x04m\xc9gl+O;\x17d\xf0\xb0\x88q\xd8D\xe4A\xa9\xb9K6g"\x08y\xb7\\\xd7K\xeb\xa43\x87\x84\xe1\x1e \'\x04J\xdd\x0b\x1e\x1bat\xe4e\x13\xa52\x08\x0fC\xcb|?\x9b\x95\xbcq9\x82I\xc6b~\xf0\xd1\x90~O?\x8a\n\xffr\x89g\xba\xcdi\x89S\xbc\xf5\xf3\xef\xc6p@&\xa7\xb3\x13NR\x89\x04\xfe\x9a\x0e\xc1H\n\xd5*5u\x98\xd4\xa8\xdd\x19\xe3s\xc7\x8e\xc8w\x1e\xef\xe7\xf2\xa04\x89\x9b\xe5w\x95\xd8\x87\xb2_~\xf3\x0f\x12\x1fA\x08\x9bG\xae>\xb4 \x83A\x1dd\x9e\xba\x89t\xee2\xf7&3q\x07=\xf2\x93F\xe6B?y\xd9\x93A|\xed\x1c\x9a;l\xd3c\x92nE9\r5N\x7fe1\xfe>V!\x10\xb1m\xf9S/\xa0\xec\x96\\K\xc2\xda\xc3TIfr\xe4\xd0\x88\x85\xd7w\xf3\x16o\xb4\x19\x0b\xf1i\x05"\xa5\xff$,\r\x84 $/\xa6\xbb\xfed\x89\xbd.\xaf+\x1a\x0b\x9a\x1c\x05\xb1\xcf\xbbI\xba\xd1\xc1\r\xc0\x9a\x1c', '_pwTy': 1, '_x': 28260}
2022-02-01 21:29:20 DEBUG (MainThread) [pyatv.protocols.companion.connection] >> Send data (Data=e3435f706492280106010505ffa68a91fc5073d470258cd5b6ff1ab303f3dcf9c5cdc12720c889046dc9676c2b4f3b1764f0b08871d844e441a9b94b3667220879b75cd74beba4338784e11e2027044add0b1e1b6174e46513a532080f43cb7c3f9b95bc71398249c6627ef0d1907e4f3f8a0aff728967bacd698953bcf5f3efc6704026a7b3134e528904fe9a0ec1480ad52a357598d4a8dd19e373c78ec8771eefe7f2a034899be57795d887b25f7ef30f121f41089b47ae3eb42083411d649eba8974ee32f7263371073df29346e6423f79d993417ced1c9a3b6cd363926e45390d354e7f6531fe3e562110b16df9532fa0ec965c4bc2dac354496672e..., FrameType=04)
2022-02-01 21:29:24 DEBUG (MainThread) [pyatv.support.http] Connection closed
2022-02-01 21:29:25 ERROR (MainThread) [homeassistant.components.apple_tv.config_flow] Unexpected exception
Traceback (most recent call last):
  File "/usr/local/lib/python3.9/asyncio/locks.py", line 226, in wait
    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/companion/auth.py", line 112, in finish_pairing
    resp = await self.protocol.exchange_auth(
  File "/usr/local/lib/python3.9/site-packages/pyatv/protocols/companion/protocol.py", line 145, in exchange_auth
    return await self._exchange_generic_opack(frame_type, data, identifier, timeout)
  File "/usr/local/lib/python3.9/site-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.9/site-packages/pyatv/support/collections.py", line 130, in wait
    await asyncio.wait_for(self._event.wait(), 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/src/homeassistant/homeassistant/components/apple_tv/config_flow.py", line 426, in async_step_pair_with_pin
    await self.pairing.finish()
  File "/usr/local/lib/python3.9/site-packages/pyatv/protocols/companion/pairing.py", line 64, in finish
    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
gotschi commented 2 years ago

ok so the error seems to be maybe in the room naming/syncing with icloud settings or something..

When I start with a new Home in iOS, only add the atv and then add the atv to HA it works and keeps pairing across reboots.

As soon as I add the Homekit Bridge provided by HA to the Home it fails with a message that a integration needs attention (atv4).

I do not provide the media_player or anything else atv related on this bridge, only light, switches, cover and climate entities.

So I'm going to see if I can find out what is the conflict here with the Homekit Integration.

edit: suspecting there is something fishy going on in combination with the homekit integration, climate entities only on the bridge seemed to keep the pairing intact - adding light entities to the bridge makes it fail

gotschi commented 2 years ago

yep. this was it.

it's the homekit integration, including something a) cached, nowhere else visible b) something from remote home assistant integration (custom component)

that was hard to track down. I got the clues from having 2 'home' zones in my entities list (remote home), and searched my whole .storage for 'home' resulting in a weird entity in core.entity_registry I have no idea where it came from

edit: it is 3 entities in my homekit integration prohibiting pairing:

1 Temperature sensor from a "MultiSensor Gen5" ZwaveJS Device (the binary_sensoroccuption part of the same device works fine) 2 coverentities from a template Cover

tbh I believe this will make it fail for a lot of people on release

Maybe you guys can shed some light to it, but these were the culprits I had. Keep in mind that my airpods worked fine, this was only the atv acting up. They themselves work fine in Homekit, but prevent pyatv from succesful connect. Will attach the difference in logs debug mode soon

Final Edit: It was working for 30 minutes now. Homekit is still making it fail with only light entities on the bridge, there is defo something wrong

gotschi commented 2 years ago

here is the complete debug log where I start Homeassistant with Homekit integration disabled. Then I do a successful Pairing with my ATV, start a app on Atv and play some music afterwards. Then I enable the Homekit Integration (I marked this point with < ------------ Homekit Integration Enabling ------------- >in the log). Then pyatv loses the pairing and fails.

too much for github, here is the LOG: https://x0.at/wrpc.txt

Issue persists in 2022.2.0