search

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.81k stars 30.9k forks source link

AirPlay to Apple TV - pyatv.exceptions.NotSupportedError: play_url is not supported #53785

Closed skylarv closed 2 years ago

skylarv commented 3 years ago

The problem

With latest 2021.8.0b5 pre-release, AirPlaying to Apple TV is failing with pyatv.exceptions.NotSupportedError: play_url is not supported.

What is version of Home Assistant Core has the issue?

2021.8.0b5

What was the last working version of Home Assistant Core?

No response

What type of installation are you running?

Home Assistant OS

Integration causing the issue

No response

Link to integration documentation on our website

No response

Example YAML snippet

service: media_extractor.play_media
data:
  media_content_id: https://www.youtube.com/watch?v=ROMMtHHyCp8
  media_content_type: VIDEO
target:
  entity_id: media_player.living_room_tv_4k

Anything in the logs that might be useful for us?

Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/core.py", line 1507, in catch_exceptions
    await coro_or_task
  File "/usr/src/homeassistant/homeassistant/core.py", line 1526, in _execute_service
    await handler.job.target(service_call)
  File "/usr/src/homeassistant/homeassistant/helpers/entity_component.py", line 213, in handle_service
    await self.hass.helpers.service.entity_service_call(
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 658, in entity_service_call
    future.result()  # pop exception if have
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 856, in async_request_call
    await coro
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 695, in _handle_entity_call
    await result
  File "/usr/src/homeassistant/homeassistant/components/apple_tv/media_player.py", line 176, in async_play_media
    await self.atv.stream.play_url(media_id)
  File "/usr/local/lib/python3.9/site-packages/pyatv/support/facade.py", line 326, in play_url
    await self.relay("play_url")(url, **kwargs)
  File "/usr/local/lib/python3.9/site-packages/pyatv/support/relayer.py", line 75, in relay
    instance = self._find_instance(target, priority or self._priorities)
  File "/usr/local/lib/python3.9/site-packages/pyatv/support/relayer.py", line 97, in _find_instance
    raise exceptions.NotSupportedError(f"{target} is not supported")
pyatv.exceptions.NotSupportedError: play_url is not supported

Additional information

I've also tested Vimeo, Soundcloud, etc. and can't seem to get AirPlay to Apple TV working. The media_content_type used to be "video/youtube" prior to latest core update. Any help will be appreciated!

postlund commented 3 years ago

AirPlay credentials are missing. Try removing the device and adding it again. Make sure you get a prompt about "pairing AirPlay".

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

apple_tv documentation apple_tv source (message by IssueLinks)

skylarv commented 3 years ago

Hi @postlund! I did try repairing and on both Apple TVs I got two code prompts including the airplay prompt. Running tvOS 14.7 (18M60) and both ATV 4K.

Unfortunately, even after repairing, still getting this same play_url is not supported error. Thanks for taking a look and let me know if you need anymore info.

I also tried media_player.play_media and that gave me same error.

Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/websocket_api/commands.py", line 185, in handle_call_service
    await hass.services.async_call(
  File "/usr/src/homeassistant/homeassistant/core.py", line 1491, in async_call
    task.result()
  File "/usr/src/homeassistant/homeassistant/core.py", line 1526, in _execute_service
    await handler.job.target(service_call)
  File "/usr/src/homeassistant/homeassistant/components/script/__init__.py", line 278, in service_handler
    await script_entity.async_turn_on(
  File "/usr/src/homeassistant/homeassistant/components/script/__init__.py", line 382, in async_turn_on
    await coro
  File "/usr/src/homeassistant/homeassistant/components/script/__init__.py", line 409, in _async_run
    return await self.script.async_run(script_vars, context)
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 1219, in async_run
    await asyncio.shield(run.async_run())
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 353, in async_run
    await self._async_step(log_exceptions=False)
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 371, in _async_step
    await getattr(self, handler)()
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 571, in _async_call_service_step
    await service_task
  File "/usr/src/homeassistant/homeassistant/core.py", line 1491, in async_call
    task.result()
  File "/usr/src/homeassistant/homeassistant/core.py", line 1526, in _execute_service
    await handler.job.target(service_call)
  File "/usr/src/homeassistant/homeassistant/helpers/entity_component.py", line 213, in handle_service
    await self.hass.helpers.service.entity_service_call(
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 658, in entity_service_call
    future.result()  # pop exception if have
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 856, in async_request_call
    await coro
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 695, in _handle_entity_call
    await result
  File "/usr/src/homeassistant/homeassistant/components/apple_tv/media_player.py", line 176, in async_play_media
    await self.atv.stream.play_url(media_id)
  File "/usr/local/lib/python3.9/site-packages/pyatv/support/facade.py", line 326, in play_url
    await self.relay("play_url")(url, **kwargs)
  File "/usr/local/lib/python3.9/site-packages/pyatv/support/relayer.py", line 75, in relay
    instance = self._find_instance(target, priority or self._priorities)
  File "/usr/local/lib/python3.9/site-packages/pyatv/support/relayer.py", line 97, in _find_instance
    raise exceptions.NotSupportedError(f"{target} is not supported")
pyatv.exceptions.NotSupportedError: play_url is not supported
postlund commented 3 years ago

@skylarv Thanks for verifying! Seems strange that AirPlay would break like this, but maybe it is solved by the changes I made for #52862. I would suggest that you try running from dev or wait for next HA release and try again, hopefully that will work better.

skylarv commented 3 years ago

Interesting. I’m on HA core v2021.8.0b5 which includes that deploy. I was able to find my Apple TV’s again after updating to this version, which that ticket fixed, but not airplay anymore.

skylarv commented 3 years ago

@postlund Do you think you'll have time to test AirPlay to Apple TVs? I'm on latest 2021.8.6 and still having this issue. Thanks for looking into it!

postlund commented 3 years ago

@skylarv I don't see this problem myself. Can you try removing the device and add it again on the latest release and enable debug logs for pyatv? I would like to see what pyatv discovers during a connect.

arstropica commented 3 years ago

@postlund I have the same issue. It started after I updated home assistant to 2021.8.6.

2021-08-12 08:33:22 DEBUG (MainThread) [pyatv.mrp.connection] 192.168.xxx.xxx:39010<->192.168.xxx.xxx:49153 << Receive (Data=xxx...)
2021-08-12 08:33:22 DEBUG (MainThread) [pyatv.mrp.connection] 192.168.xxx.xxx:39010<->192.168.xxx.xxx:49153 << Receive: Protobuf: type: DEVICE_INFO_MESSAGE
identifier: "xxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxxxxx"
errorCode: NoError
[deviceInfoMessage] {
  uniqueIdentifier: "xxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxxxxx"
  name: "AppleTV"
  localizedModelName: "Apple\302\240TV"
  systemBuildVersion: "18M60"
  applicationBundleIdentifier: "com.apple.mediaremoted"
  protocolVersion: 1
  lastSupportedMessageType: 108
  supportsSystemPairing: true
  allowsPairing: true
  systemMediaApplication: "com.apple.TVMusic"
  supportsACL: true
  supportsSharedQueue: true
  supportsExtendedMotion: true
  sharedQueueVersion: 3
  deviceUID: "xxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxxxxx"
  managedConfigDeviceID: "c8:d0:83:e8:ac:cf"
  deviceClass: AppleTV
  logicalDeviceCount: 1
  isProxyGroupPlayer: false
  groupUID: "xxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxxxxx"
  isGroupLeader: true
  isAirplayActive: true
  systemPodcastApplication: "com.apple.podcasts"
  enderDefaultGroupUID: "xxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxxxxx"
  airplayReceivers: "TVAirPlay"
  clusterType: 0
  isClusterAware: true
  modelID: "AppleTV6,2"
}
uniqueIdentifier: "xxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxxxxx"
2021-08-12 08:33:22 DEBUG (MainThread) [websockets.protocol] client - event = data_received(<6 bytes>)
2021-08-12 08:33:22 DEBUG (MainThread) [websockets.protocol] client - event = data_received(<6 bytes>)
2021-08-12 08:33:22 DEBUG (MainThread) [websockets.protocol] client < Frame(fin=True, opcode=<Opcode.PONG: 10>, Data=xxx...)
2021-08-12 08:33:22 DEBUG (MainThread) [websockets.protocol] client - received solicited pong: 109d21a4
2021-08-12 08:33:22 DEBUG (MainThread) [websockets.protocol] client < Frame(fin=True, opcode=<Opcode.PONG: 10>, Data=xxx...)
2021-08-12 08:33:22 DEBUG (MainThread) [websockets.protocol] client - received solicited pong: 3fe61998
2021-08-12 08:33:22 DEBUG (MainThread) [pyatv.mrp.connection] 192.168.xxx.xxx:39010<->192.168.xxx.xxx:49153 >> Send (Data=xxx...)
2021-08-12 08:33:22 DEBUG (MainThread) [pyatv.mrp.connection] 192.168.xxx.xxx:39010<->192.168.xxx.xxx:49153 >> Send: Protobuf: type: CRYPTO_PAIRING_MESSAGE
errorCode: NoError
[cryptoPairingMessage] {
  pairingData: "\000\001\000\006\001\001"
  status: 0
  isRetrying: false
  isUsingSystemPairing: false
  state: 2
}
2021-08-12 08:33:22 DEBUG (MainThread) [pyatv.mrp.connection] 192.168.xxx.xxx:39010<->192.168.xxx.xxx:49153 << Receive (Data=xxx...)
2021-08-12 08:33:22 DEBUG (MainThread) [pyatv.mrp.connection] 192.168.xxx.xxx:39010<->192.168.xxx.xxx:49153 << Receive: Protobuf: type: CRYPTO_PAIRING_MESSAGE
errorCode: NoError
[cryptoPairingMessage] {
  pairingData: "\006\001\002\002\020[\204\207\201^r/:\031S\356\310\253D\322\030\003\377U\352\373w\025\021\272\314Bx\314y\026\311\365\371\2552\022\2...
  status: 0
  isRetrying: false
  isUsingSystemPairing: false
  state: 0
}
uniqueIdentifier: "xxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxxxxx"
2021-08-12 08:33:23 DEBUG (MainThread) [websockets.protocol] client > Frame(fin=True, opcode=<Opcode.PING: 9>, Data=xxx...)
2021-08-12 08:33:23 DEBUG (MainThread) [websockets.protocol] client > Frame(fin=True, opcode=<Opcode.PING: 9>, Data=xxx...)
2021-08-12 08:33:23 DEBUG (MainThread) [websockets.protocol] client - event = data_received(<6 bytes>)
2021-08-12 08:33:23 DEBUG (MainThread) [websockets.protocol] client < Frame(fin=True, opcode=<Opcode.PONG: 10>, Data=xxx...)
2021-08-12 08:33:23 DEBUG (MainThread) [websockets.protocol] client - received solicited pong: a1910532
2021-08-12 08:33:23 DEBUG (MainThread) [websockets.protocol] client - event = data_received(<6 bytes>)
2021-08-12 08:33:23 DEBUG (MainThread) [websockets.protocol] client < Frame(fin=True, opcode=<Opcode.PONG: 10>, Data=xxx...)
2021-08-12 08:33:23 DEBUG (MainThread) [websockets.protocol] client - received solicited pong: 3ae9c5ae
2021-08-12 08:33:24 DEBUG (MainThread) [websockets.protocol] client > Frame(fin=True, opcode=<Opcode.PING: 9>, Data=xxx...)
2021-08-12 08:33:24 DEBUG (MainThread) [websockets.protocol] client > Frame(fin=True, opcode=<Opcode.PING: 9>, Data=xxx...)
2021-08-12 08:33:24 DEBUG (MainThread) [websockets.protocol] client - event = data_received(<6 bytes>)
2021-08-12 08:33:24 DEBUG (MainThread) [websockets.protocol] client < Frame(fin=True, opcode=<Opcode.PONG: 10>, Data=xxx...)
2021-08-12 08:33:24 DEBUG (MainThread) [websockets.protocol] client - received solicited pong: cf89433b
2021-08-12 08:33:24 DEBUG (MainThread) [websockets.protocol] client - event = data_received(<6 bytes>)
2021-08-12 08:33:24 DEBUG (MainThread) [websockets.protocol] client < Frame(fin=True, opcode=<Opcode.PONG: 10>, Data=xxx...)
2021-08-12 08:33:24 DEBUG (MainThread) [websockets.protocol] client - received solicited pong: 8527af07

2021-08-12 08:33:25 DEBUG (MainThread) [websockets.protocol] client > Frame(fin=True, opcode=<Opcode.PING: 9>, Data=xxx...)
2021-08-12 08:33:25 DEBUG (MainThread) [websockets.protocol] client > Frame(fin=True, opcode=<Opcode.PING: 9>, Data=xxx...)
2021-08-12 08:33:25 DEBUG (MainThread) [websockets.protocol] client - event = data_received(<6 bytes>)
2021-08-12 08:33:25 DEBUG (MainThread) [websockets.protocol] client < Frame(fin=True, opcode=<Opcode.PONG: 10>, Data=xxx...)
2021-08-12 08:33:25 DEBUG (MainThread) [websockets.protocol] client - received solicited pong: 4ddbcbc8
2021-08-12 08:33:25 DEBUG (MainThread) [websockets.protocol] client - event = data_received(<6 bytes>)
2021-08-12 08:33:25 DEBUG (MainThread) [websockets.protocol] client < Frame(fin=True, opcode=<Opcode.PONG: 10>, Data=xxx...)
2021-08-12 08:33:25 DEBUG (MainThread) [websockets.protocol] client - received solicited pong: ad7b2f12
2021-08-12 08:33:25 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection] [140653328996000] Received {'type': 'supervisor/api', 'endpoint': '/ingress/validate_session', 'method': 'post', 'data': {'session': 'xxx'}, 'id': 61}
2021-08-12 08:33:25 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection] [140653328996000] Sending {"id": 61, "type": "result", "success": true, "result": {}}
2021-08-12 08:33:26 DEBUG (Recorder) [homeassistant.components.recorder.pool.RecorderPool] Connection <sqlite3.Connection object at 0x7fec75a3f5d0> being returned to pool
2021-08-12 08:33:26 DEBUG (Recorder) [homeassistant.components.recorder.pool.RecorderPool] Connection <sqlite3.Connection object at 0x7fec75a3f5d0> rollback-on-return
2021-08-12 08:33:26 DEBUG (MainThread) [websockets.protocol] client > Frame(fin=True, opcode=<Opcode.PING: 9>, Data=xxx...)
.
.
.
2021-08-12 08:33:32 DEBUG (MainThread) [websockets.protocol] client - received solicited pong: 9749963c
2021-08-12 08:33:33 DEBUG (MainThread) [homeassistant.components.http.auth] Authenticated 192.168.xxx.xxx for /api/config/config_entries/flow/3b0e23a2c62d4f15b5f8b2888b889b2a using bearer token
2021-08-12 08:33:33 DEBUG (MainThread) [homeassistant.components.http.view] Serving /api/config/config_entries/flow/3b0e23a2c62d4f15b5f8b2888b889b2a to 192.168.xxx.xxx (auth: True)
2021-08-12 08:33:33 DEBUG (MainThread) [pyatv.mrp.pairing] MRP PIN changed to xxxx
2021-08-12 08:33:33 DEBUG (MainThread) [pyatv.support.hap_srp] Client (Proof=27216aa1d7a4276327afa0a191ed17f5c6d6715a8db2fd349020a6ff7edca623ce631cfa78b4e810697977334d9f7e0c01e99b3106ba32f68e36027191bedce5, Public=653ec21b235490cc54df30f0c6ff248646a2ac43d989aa745a2f3256ae3b4080d996fe522033d1bc2661b1844171cef4016528f793aa9f4f1daba676c769e2346c45b1a7b4f1d96cfe8fd1fe9ebd158ebdb08453a993568cac9d5e39780123eb4e1dabaec61f69c33d66ef29d0d317a967853795fd6a42d73c97ff72fc2b2fc9bf891db524f2a1391a446115ea5515ab13a8419af917c360c488585122aa823fa8169828c58777412e634d93cd68261dd6c549d1cf81db0b21a169f1b760bee58b394368a25b45f5f602cca50462e41e37cf09fdb009e6928a323136a3e39a912ac04d5afc24a52472d995aa430859b7cc4042cd1207475bb043d86113872...)
2021-08-12 08:33:33 DEBUG (MainThread) [pyatv.mrp.connection] 192.168.xxx.xxx:39010<->192.168.xxx.xxx:49153 >> Send (Data=xxx...)
2021-08-12 08:33:33 DEBUG (MainThread) [pyatv.mrp.connection] 192.168.xxx.xxx:39010<->192.168.xxx.xxx:49153 >> Send: Protobuf: type: CRYPTO_PAIRING_MESSAGE
errorCode: NoError
[cryptoPairingMessage] {
  pairingData: "\006\001\003\003\377e>\302\033#T\220\314T\3370\360\306\377$\206F\242\254C\331\211\252tZ/2V\256;@\200\331\226\376R 3\321\274&a\261\2...
  status: 0
  isRetrying: false
  isUsingSystemPairing: false
  state: 0
}
2021-08-12 08:33:33 DEBUG (MainThread) [websockets.protocol] client > Frame(fin=True, opcode=<Opcode.PING: 9>, Data=xxx...)
2021-08-12 08:33:33 DEBUG (MainThread) [websockets.protocol] client > Frame(fin=True, opcode=<Opcode.PING: 9>, Data=xxx...)
2021-08-12 08:33:33 DEBUG (MainThread) [websockets.protocol] client - event = data_received(<6 bytes>)
2021-08-12 08:33:33 DEBUG (MainThread) [websockets.protocol] client < Frame(fin=True, opcode=<Opcode.PONG: 10>, Data=xxx...)
2021-08-12 08:33:33 DEBUG (MainThread) [websockets.protocol] client - received solicited pong: 5342fb7b
2021-08-12 08:33:33 DEBUG (MainThread) [websockets.protocol] client - event = data_received(<6 bytes>)
2021-08-12 08:33:33 DEBUG (MainThread) [websockets.protocol] client < Frame(fin=True, opcode=<Opcode.PONG: 10>, Data=xxx...)
2021-08-12 08:33:33 DEBUG (MainThread) [websockets.protocol] client - received solicited pong: 19230202
2021-08-12 08:33:34 DEBUG (MainThread) [pyatv.mrp.connection] 192.168.xxx.xxx:39010<->192.168.xxx.xxx:49153 << Receive (Data=xxx...)
2021-08-12 08:33:34 DEBUG (MainThread) [pyatv.mrp.connection] 192.168.xxx.xxx:39010<->192.168.xxx.xxx:49153 << Receive: Protobuf: type: CRYPTO_PAIRING_MESSAGE
errorCode: NoError
[cryptoPairingMessage] {
  pairingData: "\006\001\004\004@\024H\243\256\232\222\311\361\214\226\n\221fp\221i\233\001*\264P\270^\225g\237\217\300{z{9\354%\014\331\361\225\03...
  status: 0
  isRetrying: false
  isUsingSystemPairing: false
  state: 0
}
uniqueIdentifier: "xxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxxxxx"
2021-08-12 08:33:34 DEBUG (MainThread) [pyatv.mrp.auth] Device (Proof=1448a3ae9a92c9f18c960a91667091699b012ab450b85e95679f8fc07b7a7b39ec250cd9f1951a2aee24c24cdcbd315f867bd463c8aff36035f3613120f1d53a)
2021-08-12 08:33:34 DEBUG (MainThread) [pyatv.support.hap_srp] Data (Encrypted=xxx...)
2021-08-12 08:33:34 DEBUG (MainThread) [pyatv.mrp.connection] 192.168.xxx.xxx:39010<->192.168.xxx.xxx:49153 >> Send (Data=xxx...)
2021-08-12 08:33:34 DEBUG (MainThread) [pyatv.mrp.connection] 192.168.xxx.xxx:39010<->192.168.xxx.xxx:49153 >> Send: Protobuf: type: CRYPTO_PAIRING_MESSAGE
errorCode: NoError
[cryptoPairingMessage] {
  pairingData: "\006\001\005\005\2326=\264\302\372R\254\020]\"\247#W\232,\344\252\212\256\265\376\345j\002\330\0145\033d?Z\245\341-\203vi\035\262\3...
  status: 0
  isRetrying: false
  isUsingSystemPairing: false
  state: 0
}
2021-08-12 08:33:34 DEBUG (MainThread) [pyatv.mrp.connection] 192.168.xxx.xxx:39010<->192.168.xxx.xxx:49153 << Receive (Data=xxx...)
2021-08-12 08:33:34 DEBUG (MainThread) [pyatv.mrp.connection] 192.168.xxx.xxx:39010<->192.168.xxx.xxx:49153 << Receive: Protobuf: type: CRYPTO_PAIRING_MESSAGE
errorCode: NoError
[cryptoPairingMessage] {
  pairingData: "\005\232\212\320s3=\303\001\327\337\207~\227\023\377/K\263\240Ri\n\237\264\360\017\203\274l\2355n\323o5\253r&\033\0250\360g\250=<6\...
  status: 0
  isRetrying: false
  isUsingSystemPairing: false
  state: 0
}
uniqueIdentifier: "xxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxxxxx"
2021-08-12 08:33:34 DEBUG (MainThread) [pyatv.support.hap_srp] PS-Msg06: {1: b'xxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxxxxx', 3: b'\xf6\x9a\xb2\x86\xbd\x0f\xb5\x92\x94\x87\x95\x1f\xc1cE\xc5\n\xd8L\x9b$`\xd4/A \xdf\x17\x90\xf1xM', 10: b"\x07\x82.+6=\x7fw(\x87\x94\xffJ)5k6\x9cu\xf9\x8e\x06\xf8\x0b\xb5\xa7\xdd\xc1\xb9\xfe~\xfb2]\xb1f=\xa9\xa4N\x88\x9fs+\xa7G\xc1'\xfc\xd2A\xbb@Grv\x9c\x1a\xd9>tl\x9c\r"}
2021-08-12 08:33:34 DEBUG (MainThread) [pyatv.support.hap_srp] Device (Identifier=32383031646163362d353433622d343730382d396439332d306536316137303437366364, Public=f69ab286bd0fb5929487951fc16345c50ad84c9b2460d42f4120df1790f1784d, Signature=07822e2b363d7f77288794ff4a29356b369c75f98e06f80bb5a7ddc1b9fe7efb325db1663da9a44e889f732ba747c127fcd241bb404772769c1ad93e746c9c0d)
2021-08-12 08:33:34 DEBUG (MainThread) [pyatv.mrp.pairing] Verifying credentials f69ab286bd0fb5929487951fc16345c50ad84c9b2460d42f4120df1790f1784d:204a57f0e8d2d288c61fb9a45cabdedc61ca187f0efd5dd11348bf68a7ca78ee:32383031646163362d353433622d343730382d396439332d306536316137303437366364:62353063376361332d623633612d343231612d383037302d336364376438346133626633
2021-08-12 08:33:34 DEBUG (MainThread) [pyatv.mrp.connection] 192.168.xxx.xxx:39010<->192.168.xxx.xxx:49153 >> Send (Data=xxx...)
2021-08-12 08:33:34 DEBUG (MainThread) [pyatv.mrp.connection] 192.168.xxx.xxx:39010<->192.168.xxx.xxx:49153 >> Send: Protobuf: type: CRYPTO_PAIRING_MESSAGE
errorCode: NoError
[cryptoPairingMessage] {
  pairingData: "\006\001\001\003 ]:\226\"\206\370]\317G\373\330\276\232\316\010\021\030\223\322\224\212r\323\205\'\372\326\243\305\025\322\016"
  status: 0
  isRetrying: false
  isUsingSystemPairing: false
  state: 0
}
2021-08-12 08:33:34 DEBUG (MainThread) [pyatv.mrp.connection] 192.168.xxx.xxx:39010<->192.168.xxx.xxx:49153 << Receive (Data=xxx...)
2021-08-12 08:33:34 DEBUG (MainThread) [pyatv.mrp.connection] 192.168.xxx.xxx:39010<->192.168.xxx.xxx:49153 << Receive: Protobuf: type: CRYPTO_PAIRING_MESSAGE
errorCode: NoError
[cryptoPairingMessage] {
  pairingData: "\005xGwP\377\033\023\033\246!\212\304\245\307G0\343\223|\020\264\002\201\330\020YB\330\235\020E#\342\020RP\215{\226=s:RV6\354dit\n\...
  status: 0
  isRetrying: false
  isUsingSystemPairing: false
  state: 0
}
uniqueIdentifier: "xxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxxxxx"
2021-08-12 08:33:34 DEBUG (MainThread) [pyatv.mrp.auth] Device (Encrypted=xxx...)
2021-08-12 08:33:34 DEBUG (MainThread) [pyatv.mrp.connection] 192.168.xxx.xxx:39010<->192.168.xxx.xxx:49153 >> Send (Data=xxx...)
2021-08-12 08:33:34 DEBUG (MainThread) [pyatv.mrp.connection] 192.168.xxx.xxx:39010<->192.168.xxx.xxx:49153 >> Send: Protobuf: type: CRYPTO_PAIRING_MESSAGE
errorCode: NoError
[cryptoPairingMessage] {
  pairingData: "\006\001\003\005x\007\351$)\267\235\274\260\014\350\343\354@\025x6\233Z\306\333\261\323(\204\370)`\2321\313\312\313\375\220Cv\007\3...
  status: 0
  isRetrying: false
  isUsingSystemPairing: false
  state: 0
}
2021-08-12 08:33:34 DEBUG (MainThread) [pyatv.mrp.connection] 192.168.xxx.xxx:39010<->192.168.xxx.xxx:49153 << Receive (Data=xxx...)
2021-08-12 08:33:34 DEBUG (MainThread) [pyatv.mrp.connection] 192.168.xxx.xxx:39010<->192.168.xxx.xxx:49153 << Receive: Protobuf: type: CRYPTO_PAIRING_MESSAGE
errorCode: NoError
[cryptoPairingMessage] {
  pairingData: "\006\001\004"
  status: 0
  isRetrying: false
  isUsingSystemPairing: false
  state: 0
}
uniqueIdentifier: "xxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxxxxx"
2021-08-12 08:33:34 DEBUG (MainThread) [pyatv.support.hap_srp] Keys (Input=f02b4db5dfb06ff7e088dfd34f53ca2cf2d520633603a8d79d5df96d5cac3428, Output=583cb7d6518e109c64b33a1b22cf1eb817be9ec3765247ba697c27d215c5a21d)
2021-08-12 08:33:34 DEBUG (MainThread) [pyatv.mrp.connection] 192.168.xxx.xxx:39010<->192.168.xxx.xxx:49153  Closing connection
2021-08-12 08:33:34 DEBUG (MainThread) [pyatv.airplay.pairing] Starting AirPlay pairing with credentials 31F49072C524C987:06F3CC134F388C53CD0D5B8C523DB5694E0F02882553EB84B0C4BE4DFC7DC2C6
2021-08-12 08:33:34 DEBUG (MainThread) [pyatv.airplay.srp] Authentication keys (Private=06f3cc134f388c53cd0d5b8c523db5694e0f02882553eb84b0c4be4dfc7dc2c6, Public=4b9a9f92404796cc12bc255aec4fd506605f2802e8698a49112a6429ec9857fa)
2021-08-12 08:33:34 DEBUG (MainThread) [pyatv.mrp.connection] 192.168.xxx.xxx:39010<->192.168.xxx.xxx:49153  Disconnected from device: None
2021-08-12 08:33:34 DEBUG (MainThread) [pyatv.support.http] Connected to 192.168.xxx.xxx
2021-08-12 08:33:34 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\n\r\n'
2021-08-12 08:33:34 DEBUG (MainThread) [pyatv.support.http] Received: b'HTTP/1.1 200 OK\r\nDate: Thu, 12 Aug 2021 12:33:34 GMT\r\nContent-Length: 0\r\nServer: AirTunes/550.10\r\n\r\n'
2021-08-12 08:33:34 DEBUG (MainThread) [pyatv.support.http] Got HTTP response: HttpResponse(protocol='HTTP', version='1.1', code=200, message='OK', headers={'date': 'Thu, 12 Aug 2021 12:33:34 GMT', 'content-length': '0', 'server': 'AirTunes/550.10'}, body=''):
2021-08-12 08:33:34 DEBUG (MainThread) [websockets.protocol] client > Frame(fin=True, opcode=<Opcode.PING: 9>, Data=xxx...)
2021-08-12 08:33:34 DEBUG (MainThread) [websockets.protocol] client > Frame(fin=True, opcode=<Opcode.PING: 9>, Data=xxx...)
2021-08-12 08:33:34 DEBUG (MainThread) [async_upnp_client.search] Sending M-SEARCH packet
2021-08-12 08:33:34 DEBUG (MainThread) [async_upnp_client.traffic.ssdp] Sending M-SEARCH packet: b'M-SEARCH * HTTP/1.1\r\nHOST:239.255.255.250:1900\r\nMAN:"ssdp:discover"\r\nMX:4\r\nST:ssdp:all\r\n\r\n'
2021-08-12 08:33:34 DEBUG (MainThread) [async_upnp_client.search] Sending M-SEARCH packet
2021-08-12 08:33:34 DEBUG (MainThread) [async_upnp_client.traffic.ssdp] Sending M-SEARCH packet: b'M-SEARCH * HTTP/1.1\r\nHOST:239.255.255.250:1900\r\nMAN:"ssdp:discover"\r\nMX:4\r\nST:ssdp:all\r\n\r\n'
2021-08-12 08:33:34 DEBUG (MainThread) [async_upnp_client.ssdp] Received error: [Errno 13] Permission denied
2021-08-12 08:33:34 DEBUG (MainThread) [async_upnp_client.traffic.ssdp] Received packet from ('192.168.xxx.xxx', 1900): b'HTTP/1.1 200 OK\r\nCACHE-CONTROL: max-age=1810\r\nDATE: Thu, 12 Aug 2021 12:33:34 GMT\r\nST: uuid:xxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxxxxx\r\nUSN: uuid:xxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxxxxx\r\nEXT:\r\nSERVER: 3.4.6-generic Microsoft-Windows/6.1 Windows-Media-Player-DMS/12.0.7601.17514 DLNADOC/1.50 UPnP/1.0 QNAPDLNA/1.0\r\nLOCATION: http://192.168.xxx.xxx:8200/rootDesc.xml\r\nContent-Length: 0\r\n\r\n'
2021-08-12 08:33:35 DEBUG (MainThread) [websockets.protocol] client - event = data_received(<6 bytes>)
2021-08-12 08:33:35 DEBUG (MainThread) [websockets.protocol] client - event = data_received(<6 bytes>)
2021-08-12 08:33:35 DEBUG (MainThread) [async_upnp_client.search] Received response, request line: HTTP/1.1 200 OK, headers: {'CACHE-CONTROL': 'max-age=1810', 'DATE': 'Thu, 12 Aug 2021 12:33:34 GMT', 'ST': 'uuid:xxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxxxxx', 'USN': 'uuid:xxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxxxxx', 'EXT': '', 'SERVER': '3.4.6-generic Microsoft-Windows/6.1 Windows-Media-Player-DMS/12.0.7601.17514 DLNADOC/1.50 UPnP/1.0 QNAPDLNA/1.0', 'location': 'http://192.168.xxx.xxx:8200/rootDesc.xml', 'Content-Length': '0', '_location_original': 'http://192.168.xxx.xxx:8200/rootDesc.xml', '_timestamp': datetime.datetime(2021, 8, 12, 8, 33, 34, 999144), '_host': '192.168.xxx.xxx', '_port': 1900, '_udn': 'uuid:xxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxxxxx'}
2021-08-12 08:33:35 DEBUG (MainThread) [homeassistant.components.ssdp] _async_process_entry: {'CACHE-CONTROL': 'max-age=1810', 'DATE': 'Thu, 12 Aug 2021 12:33:34 GMT', 'ST': 'uuid:xxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxxxxx', 'USN': 'uuid:xxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxxxxx', 'EXT': '', 'SERVER': '3.4.6-generic Microsoft-Windows/6.1 Windows-Media-Player-DMS/12.0.7601.17514 DLNADOC/1.50 UPnP/1.0 QNAPDLNA/1.0', 'location': 'http://192.168.xxx.xxx:8200/rootDesc.xml', 'Content-Length': '0', '_location_original': 'http://192.168.xxx.xxx:8200/rootDesc.xml', '_timestamp': datetime.datetime(2021, 8, 12, 8, 33, 34, 999144), '_host': '192.168.xxx.xxx', '_port': 1900, '_udn': 'uuid:xxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxxxxx', '_source': 'search'}
2021-08-12 08:33:35 DEBUG (MainThread) [websockets.protocol] client < Frame(fin=True, opcode=<Opcode.PONG: 10>, Data=xxx...)
2021-08-12 08:33:35 DEBUG (MainThread) [websockets.protocol] client - received solicited pong: fe66e228
2021-08-12 08:33:35 DEBUG (MainThread) [websockets.protocol] client < Frame(fin=True, opcode=<Opcode.PONG: 10>, Data=xxx...)
2021-08-12 08:33:35 DEBUG (MainThread) [websockets.protocol] client - received solicited pong: 5aa1f627
.
.
.
2021-08-12 08:33:35 DEBUG (MainThread) [homeassistant.components.ssdp] _async_process_entry: {'location': 'http://192.168.xxx.xxx:1080/', 'Cache-Control': 'max-age=1800', 'Server': 'WebOS/4.1.0 UPnP/1.0', 'EXT': '', 'USN': 'uuid:xxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxxxxx::urn:lge-com:service:webos-second-screen:1', 'ST': 'urn:lge-com:service:webos-second-screen:1', 'Date': 'Thu, 12 Aug 2021 12:33:34 GMT', '_location_original': 'http://192.168.xxx.xxx:1080/', '_timestamp': datetime.datetime(2021, 8, 12, 8, 33, 35, 515441), '_host': '192.168.xxx.xxx', '_port': 50143, '_udn': 'uuid:xxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxxxxx', '_source': 'search'}
2021-08-12 08:33:36 DEBUG (MainThread) [websockets.protocol] client > Frame(fin=True, opcode=<Opcode.PING: 9>, Data=xxx...)
2021-08-12 08:33:36 DEBUG (MainThread) [websockets.protocol] client > Frame(fin=True, opcode=<Opcode.PING: 9>, Data=xxx...)
2021-08-12 08:33:36 DEBUG (MainThread) [websockets.protocol] client - event = data_received(<6 bytes>)
2021-08-12 08:33:36 DEBUG (MainThread) [websockets.protocol] client < Frame(fin=True, opcode=<Opcode.PONG: 10>, Data=xxx...)
2021-08-12 08:33:36 DEBUG (MainThread) [websockets.protocol] client - received solicited pong: 3131817c
2021-08-12 08:33:36 DEBUG (MainThread) [websockets.protocol] client - event = data_received(<6 bytes>)
2021-08-12 08:33:36 DEBUG (MainThread) [websockets.protocol] client < Frame(fin=True, opcode=<Opcode.PONG: 10>, Data=xxx...)
2021-08-12 08:33:36 DEBUG (MainThread) [websockets.protocol] client - received solicited pong: 5cf88aea
2021-08-12 08:33:36 DEBUG (MainThread) [pyvizio.api._protocol] Using Command: GetCurrentPowerStateCommand({'_url': '/state/device/power_mode', 'item_name': 'POWER_MODE', 'default_return': 0})
2021-08-12 08:33:36 DEBUG (MainThread) [pyvizio.api._protocol] Using Request: {'method': 'get', 'url': 'https://192.168.xxx.xxx:7345/state/device/power_mode', 'headers': {}}
.
.
.
2021-08-12 08:33:37 DEBUG (MainThread) [websockets.protocol] client > Frame(fin=True, opcode=<Opcode.PING: 9>, Data=xxx...)
2021-08-12 08:33:37 DEBUG (MainThread) [websockets.protocol] client > Frame(fin=True, opcode=<Opcode.PING: 9>, Data=xxx...)
2021-08-12 08:33:37 DEBUG (MainThread) [websockets.protocol] client - event = data_received(<6 bytes>)
2021-08-12 08:33:37 DEBUG (MainThread) [websockets.protocol] client < Frame(fin=True, opcode=<Opcode.PONG: 10>, Data=xxx...)
2021-08-12 08:33:37 DEBUG (MainThread) [websockets.protocol] client - received solicited pong: d29b6f8d
2021-08-12 08:33:37 DEBUG (MainThread) [websockets.protocol] client - event = data_received(<6 bytes>)
2021-08-12 08:33:37 DEBUG (MainThread) [websockets.protocol] client < Frame(fin=True, opcode=<Opcode.PONG: 10>, Data=xxx...)
2021-08-12 08:33:37 DEBUG (MainThread) [websockets.protocol] client - received solicited pong: 57bec0be
2021-08-12 08:33:37 DEBUG (MainThread) [async_upnp_client.traffic.ssdp] Received packet from ('192.168.xxx.xxx', 56163): b'HTTP/1.1 200 OK\r\nLocation: http://192.168.xxx.xxx:1796/\r\nCache-Control: max-age=1800\r\nServer: WebOS/1.5 UPnP/1.0\r\nEXT: \r\nUSN: uuid:xxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxxxxx::upnp:rootdevice\r\nST: upnp:rootdevice\r\nDate: Thu, 12 Aug 2021 12:33:36 GMT\r\nWAKEUP: MAC=2c:2b:f9:ad:b2:08;Timeout=60\r\n\r\n'
2021-08-12 08:33:37 DEBUG (MainThread) [async_upnp_client.search] Received response, request line: HTTP/1.1 200 OK, headers: {'location': 'http://192.168.xxx.xxx:1796/', 'Cache-Control': 'max-age=1800', 'Server': 'WebOS/1.5 UPnP/1.0', 'EXT': '', 'USN': 'uuid:xxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxxxxx::upnp:rootdevice', 'ST': 'upnp:rootdevice', 'Date': 'Thu, 12 Aug 2021 12:33:36 GMT', 'WAKEUP': 'MAC=2c:2b:f9:ad:b2:08;Timeout=60', '_location_original': 'http://192.168.xxx.xxx:1796/', '_timestamp': datetime.datetime(2021, 8, 12, 8, 33, 37, 198550), '_host': '192.168.xxx.xxx', '_port': 56163, '_udn': 'uuid:xxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxxxxx'}
.
.
.
2021-08-12 08:33:38 DEBUG (MainThread) [websockets.protocol] client > Frame(fin=True, opcode=<Opcode.PING: 9>, Data=xxx...)
2021-08-12 08:33:38 DEBUG (MainThread) [websockets.protocol] client > Frame(fin=True, opcode=<Opcode.PING: 9>, Data=xxx...)
2021-08-12 08:33:38 DEBUG (MainThread) [websockets.protocol] client - event = data_received(<6 bytes>)
2021-08-12 08:33:38 DEBUG (MainThread) [websockets.protocol] client < Frame(fin=True, opcode=<Opcode.PONG: 10>, Data=xxx...)
2021-08-12 08:33:38 DEBUG (MainThread) [websockets.protocol] client - received solicited pong: 4d11c556
2021-08-12 08:33:38 DEBUG (MainThread) [websockets.protocol] client - event = data_received(<6 bytes>)
2021-08-12 08:33:38 DEBUG (MainThread) [websockets.protocol] client < Frame(fin=True, opcode=<Opcode.PONG: 10>, Data=xxx...)
2021-08-12 08:33:38 DEBUG (MainThread) [websockets.protocol] client - received solicited pong: 75739220
2021-08-12 08:33:39 DEBUG (MainThread) [websockets.protocol] client > Frame(fin=True, opcode=<Opcode.PING: 9>, Data=xxx...)
.
.
.
2021-08-12 08:33:46 DEBUG (MainThread) [zeroconf] IPv6 scope_id 2 associated to the receiving interface
2021-08-12 08:33:46 DEBUG (MainThread) [zeroconf] Received from 'fe80::104e:9145:d7a0:c477':5353 [socket 16 (('::', 5353, 0, 0))]: <DNSIncoming:{id=0, flags=0, truncated=False, n_q=1, n_ans=0, n_auth=0, n_add=0, questions=[ptr[question,QM,in,_googlecast._tcp.local.]], answers=[]}> (40 bytes) as [b'\x00\x00\x00\x00\x00\x01\x00\x00\x00\x00\x00\x00\x0b_googlecast\x04_tcp\x05local\x00\x00\x0c\x00\x01']
2021-08-12 08:33:46 DEBUG (MainThread) [zeroconf] IPv6 scope_id 0 associated to the receiving interface
2021-08-12 08:33:46 DEBUG (MainThread) [zeroconf] Ignoring duplicate message received from '::ffff:192.168.xxx.xxx':5353 [socket 16 (('::', 5353, 0, 0))] (40 bytes) as [b'\x00\x00\x00\x00\x00\x01\x00\x00\x00\x00\x00\x00\x0b_googlecast\x04_tcp\x05local\x00\x00\x0c\x00\x01']
2021-08-12 08:33:46 DEBUG (MainThread) [zeroconf] IPv6 scope_id 0 associated to the receiving interface
2021-08-12 08:33:46 DEBUG (MainThread) [zeroconf] Received from '::ffff:192.168.xxx.xxx':5353 [socket 16 (('::', 5353, 0, 0))]: <DNSIncoming:{id=0, flags=33792, truncated=False, n_q=0, n_ans=1, n_auth=0, n_add=3, questions=[], answers=[record[ptr,in,_googlecast._tcp.local.]=120/119,Google-Home-Mini-65b2979632a1d31872a69fed70cd166d._googlecast._tcp.local., record[txt,in-unique,Google-Home-Mini-65b2979632a1d31872a69fed70cd166d._googlecast._tcp.local.]=4500/4499,b'#id=65b'..., record[srv,in-unique,Google-Home-Mini-65b2979632a1d31872a69fed70cd166d._googlecast._tcp.local.]=120/119,xxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxxxxx.local.:8009, record[a,in-unique,xxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxxxxx.local.]=120/119,192.168.xxx.xxx]}> (360 bytes) as [b'\x00\x00\x84\x00\x00\x00\x00\x01\x00\x00\x00\x03\x0b_googlecast\x04_tcp\x05local\x00\x00\x0c\x00\x01\x00\x00\x00x\x0041Google-Home-Mini-65b2979632a1d31872a69fed70cd166d\xc0\x0c\xc0.\x00\x10\x80\x01\x00\x00\x11\x94\x00\xb1#id=65b2979632a1d31872a69fed70cd166d#cd=1612C910BC34EBE963848290B49D73A5\x03rm=\x05ve=05\x13md=Google Home Mini\x12ic=/setup/icon.png\x0ffn=TropicalMini\tca=199172\x04st=0\x0fbs=FA8FCA3DEA14\x04nf=1\x03rs=\xc0.\x00!\x80\x01\x00\x00\x00x\x00-\x00\x00\x00\x00\x1fI$xxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxxxxx\xc0\x1d\xc11\x00\x01\x80\x01\x00\x00\x00x\x00\x04\xc0\xa82G']
2021-08-12 08:33:46 DEBUG (MainThread) [zeroconf] Increasing effective ttl of record[ptr,in,_googlecast._tcp.local.]=120/119,Google-Home-Mini-65b2979632a1d31872a69fed70cd166d._googlecast._tcp.local. to minimum of 1125.0 to protect against excessive refreshes.
2021-08-12 08:33:46 DEBUG (MainThread) [websockets.protocol] client > Frame(fin=True, opcode=<Opcode.PING: 9>, Data=xxx...)
2021-08-12 08:33:46 DEBUG (MainThread) [websockets.protocol] client > Frame(fin=True, opcode=<Opcode.PING: 9>, Data=xxx...)
2021-08-12 08:33:46 DEBUG (MainThread) [websockets.protocol] client - event = data_received(<6 bytes>)
2021-08-12 08:33:46 DEBUG (MainThread) [websockets.protocol] client < Frame(fin=True, opcode=<Opcode.PONG: 10>, Data=xxx...)
2021-08-12 08:33:46 DEBUG (MainThread) [websockets.protocol] client - received solicited pong: ab3a413c
2021-08-12 08:33:46 DEBUG (MainThread) [websockets.protocol] client - event = data_received(<6 bytes>)
2021-08-12 08:33:46 DEBUG (MainThread) [websockets.protocol] client < Frame(fin=True, opcode=<Opcode.PONG: 10>, Data=xxx...)
2021-08-12 08:33:46 DEBUG (MainThread) [websockets.protocol] client - received solicited pong: 8fe572c1
2021-08-12 08:33:47 DEBUG (MainThread) [homeassistant.components.http.auth] Authenticated 192.168.xxx.xxx for /api/config/config_entries/flow/3b0e23a2c62d4f15b5f8b2888b889b2a using bearer token
2021-08-12 08:33:47 DEBUG (MainThread) [homeassistant.components.http.view] Serving /api/config/config_entries/flow/3b0e23a2c62d4f15b5f8b2888b889b2a to 192.168.xxx.xxx (auth: True)
2021-08-12 08:33:47 DEBUG (MainThread) [pyatv.airplay.pairing] AirPlay PIN changed to xxxx
2021-08-12 08:33:47 DEBUG (MainThread) [pyatv.support.http] Sending HTTP/1.1 message: b'POST /pair-setup-pin HTTP/1.1\r\nUser-Agent: pyatv/0.8.2\r\nContent-Length: 85\r\n\r\nbplist00\xd2\x01\x02\x03\x04VmethodTuserSpin_\x10\x1031F49072C524C987\x08\r\x14\x19\x1d\x00\x00\x00\x00\x00\x00\x01\x01\x00\x00\x00\x00\x00\x00\x00\x05\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x000'
2021-08-12 08:33:47 DEBUG (MainThread) [websockets.protocol] client > Frame(fin=True, opcode=<Opcode.PING: 9>, Data=xxx...)
2021-08-12 08:33:47 DEBUG (MainThread) [websockets.protocol] client > Frame(fin=True, opcode=<Opcode.PING: 9>, Data=xxx...)
2021-08-12 08:33:47 DEBUG (MainThread) [websockets.protocol] client - event = data_received(<6 bytes>)
2021-08-12 08:33:47 DEBUG (MainThread) [websockets.protocol] client < Frame(fin=True, opcode=<Opcode.PONG: 10>, Data=xxx...)
2021-08-12 08:33:47 DEBUG (MainThread) [websockets.protocol] client - received solicited pong: 5b25998c
2021-08-12 08:33:47 DEBUG (MainThread) [websockets.protocol] client - event = data_received(<6 bytes>)
2021-08-12 08:33:47 DEBUG (MainThread) [websockets.protocol] client < Frame(fin=True, opcode=<Opcode.PONG: 10>, Data=xxx...)
2021-08-12 08:33:47 DEBUG (MainThread) [websockets.protocol] client - received solicited pong: 20a82a28
2021-08-12 08:33:47 DEBUG (MainThread) [pyatv.support.http] Received: b'HTTP/1.1 200 OK\r\nDate: Thu, 12 Aug 2021 12:33:47 GMT\r\nContent-Length: 342\r\nContent-Type: application/x-apple-binary-plist\r\nServer: AirTunes/550.10\r\n\r\nbplist00\xd2\x01\x02\x03\x04RpkTsaltO\x11\x01\x00\x99uW\x86\xed\x04\x00\xa4\xfb\x83\x0c\x13.\xed~\xde\xddCJs\xac\x90\xfb\xeb\xa2^\xcf\xfa\x975\x95)\xa5\xc9\xcd\xf4U#\xc9\xdaK\xd8\'\xf2\xab\x94_\xbc+\x07\x93\xada\x92\xeb\n\xc4\xb4k\xcf\xa2\xec\x94l\x12\xd0U\xab\xda\'(X0t\xaf\xec\xc4\x9f<\xdc\xcd\x83\xee-/Q6\xfb\xf2"\x07\xf9\x9f\xf8\x1ad\xf2A\xa1\xce\x96\x11\xee\xf7\x8fl\x83\xe0c\x1b\x8e\xd0\x17m\xaeR\th\n\xf6]6\xdd\x06\xe1fR\xbf\xc1\xbe[c\x91\xec>V\xf5\x99\x8e\x99\x01(\xf3"\xf7\xc0\x07\xae\xf9\x97Q\xf9\x98\xef\xc19\x04?B\x81D|\xd9Br\xc4\xd0\x90\xc3\x9f\x0f{\x19\x06\xdf4\x1d\x9d\xee\xe4U\xb7q\xc0`h\xd3\x8a\x88\xde\xf9(;\x1c\x0cN\xc6\x82\x1fXn\x8cLe#F\x89pQ3X%L\x1c\xb5e\xaaIc\x1b\x1ft8u\xfd1\xdf\x9b\xaa\xb1\x06\xaf\x07\xfbl\x8e~3Z\x90\xc9\x1aRq\xe10\xbe\xabp4J\x87@\x89\x1d\xe5O\x10\x10\xe9U\x13\x05\xc2\xf4\xfc^\xfa"\xa1\xef\xc2&\xffV\x00\x08\x00\r\x00\x10\x00\x15\x01\x19\x00\x00\x00\x00\x00\x00\x02\x01\x00\x00\x00\x00\x00\x00\x00\x05\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x01,'
2021-08-12 08:33:47 DEBUG (MainThread) [pyatv.support.http] Got HTTP response: HttpResponse(protocol='HTTP', version='1.1', code=200, message='OK', headers={'date': 'Thu, 12 Aug 2021 12:33:47 GMT', 'content-length': '342', 'content-type': 'application/x-apple-binary-plist', 'server': 'AirTunes/550.10'}, body=b'bplist00\xd2\x01\x02\x03\x04RpkTsaltO\x11\x01\x00\x99uW\x86\xed\x04\x00\xa4\xfb\x83\x0c\x13.\xed~\xde\xddCJs\xac\x90\xfb\xeb\xa2^\xcf\xfa\x975\x95)\xa5\xc9\xcd\xf4U#\xc9\xdaK\xd8\'\xf2\xab\x94_\xbc+\x07\x93\xada\x92\xeb\n\xc4\xb4k\xcf\xa2\xec\x94l\x12\xd0U\xab\xda\'(X0t\xaf\xec\xc4\x9f<\xdc\xcd\x83\xee-/Q6\xfb\xf2"\x07\xf9\x9f\xf8\x1ad\xf2A\xa1\xce\x96\x11\xee\xf7\x8fl\x83\xe0c\x1b\x8e\xd0\x17m\xaeR\th\n\xf6]6\xdd\x06\xe1fR\xbf\xc1\xbe[c\x91\xec>V\xf5\x99\x8e\x99\x01(\xf3"\xf7\xc0\x07\xae\xf9\x97Q\xf9\x98\xef\xc19\x04?B\x81D|\xd9Br\xc4\xd0\x90\xc3\x9f\x0f{\x19\x06\xdf4\x1d\x9d\xee\xe4U\xb7q\xc0`h\xd3\x8a\x88\xde\xf9(;\x1c\x0cN\xc6\x82\x1fXn\x8cLe#F\x89pQ3X%L\x1c\xb5e\xaaIc\x1b\x1ft8u\xfd1\xdf\x9b\xaa\xb1\x06\xaf\x07\xfbl\x8e~3Z\x90\xc9\x1aRq\xe10\xbe\xabp4J\x87@\x89\x1d\xe5O\x10\x10\xe9U\x13\x05\xc2\xf4\xfc^\xfa"\xa1\xef\xc2&\xffV\x00\x08\x00\r\x00\x10\x00\x15\x01\x19\x00\x00\x00\x00\x00\x00\x02\x01\x00\x00\x00\x00\x00\x00\x00\x05\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x01,'):
2021-08-12 08:33:47 DEBUG (MainThread) [pyatv.airplay.srp] Client session key: b'8b2c30db9fc2392a9bc25bf1c3da8c9520c8b1e62ccf2ff2038c75a6a9c0595088a725c452a70e3f'
2021-08-12 08:33:47 DEBUG (MainThread) [pyatv.airplay.srp] Client public: 7664535e47ba9435d1573a363dd36d867670c3b8c0b5719f7944b9f025a59f7d1c04e59b2b053c074b7baf4b0860ce91f98f40c8faa45b83549d331155a4154d2ac46df193ac00674a8aa737b7534f84547cd13ebb950182fd11a9210a5346fad4390f8cf322695a745095d84ee3efb350c49184bd9b3fc004cc27f7e2e53490931028569228cacce163d204bdba982bbc9074a91543edb7d1867cdff20a8837e15d5c4b9f0e0bb78509a920c41623d5ecbd0e78b431e963eaacad8150b82a55fff8717a91f24e664885cd01b66f49c0394f070fc858cb6e3f5850b73eea50c7a4c6256100a93d08fb4f13f45038e0d52a85ecb2124384707a850ed111467dee, proof: b'0c613c73ed67b932f568f8924bbfd25cdf295b5c'
2021-08-12 08:33:47 DEBUG (MainThread) [pyatv.support.http] Sending HTTP/1.1 message: b'POST /pair-setup-pin HTTP/1.1\r\nUser-Agent: pyatv/0.8.2\r\nContent-Length: 347\r\n\r\nbplist00\xd2\x01\x02\x03\x04RpkUproofO\x11\x01\x00vdS^G\xba\x945\xd1W:6=\xd3m\x86vp\xc3\xb8\xc0\xb5q\x9fyD\xb9\xf0%\xa5\x9f}\x1c\x04\xe5\x9b+\x05<\x07K{\xafK\x08`\xce\x91\xf9\x8f@\xc8\xfa\xa4[\x83T\x9d3\x11U\xa4\x15M*\xc4m\xf1\x93\xac\x00gJ\x8a\xa77\xb7SO\x84T|\xd1>\xbb\x95\x01\x82\xfd\x11\xa9!\nSF\xfa\xd49\x0f\x8c\xf3"iZtP\x95\xd8N\xe3\xef\xb3P\xc4\x91\x84\xbd\x9b?\xc0\x04\xcc\'\xf7\xe2\xe54\x90\x93\x10(V\x92(\xca\xcc\xe1c\xd2\x04\xbd\xba\x98+\xbc\x90t\xa9\x15C\xed\xb7\xd1\x86|\xdf\xf2\n\x887\xe1]\\K\x9f\x0e\x0b\xb7\x85\t\xa9 \xc4\x16#\xd5\xec\xbd\x0ex\xb41\xe9c\xea\xac\xad\x81P\xb8*U\xff\xf8qz\x91\xf2NfH\x85\xcd\x01\xb6oI\xc09O\x07\x0f\xc8X\xcbn?XP\xb7>\xeaP\xc7\xa4\xc6%a\x00\xa9=\x08\xfbO\x13\xf4P8\xe0\xd5*\x85\xec\xb2\x12C\x84pz\x85\x0e\xd1\x11F}\xeeO\x10\x14\x0ca<s\xedg\xb92\xf5h\xf8\x92K\xbf\xd2\\\xdf)[\\\x00\x08\x00\r\x00\x10\x00\x16\x01\x1a\x00\x00\x00\x00\x00\x00\x02\x01\x00\x00\x00\x00\x00\x00\x00\x05\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x011'
2021-08-12 08:33:47 DEBUG (MainThread) [pyatv.support.http] Received: b'HTTP/1.1 200 OK\r\nDate: Thu, 12 Aug 2021 12:33:47 GMT\r\nContent-Length: 75\r\nContent-Type: application/x-apple-binary-plist\r\nServer: AirTunes/550.10\r\n\r\nbplist00\xd1\x01\x02UproofO\x10\x14\xca\xfev\x97^L\xe5\xe5\xf0\xce\xb0g\xdaqy\x85\xc8\xb9\x99i\x08\x0b\x11\x00\x00\x00\x00\x00\x00\x01\x01\x00\x00\x00\x00\x00\x00\x00\x03\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00('
2021-08-12 08:33:47 DEBUG (MainThread) [pyatv.support.http] Got HTTP response: HttpResponse(protocol='HTTP', version='1.1', code=200, message='OK', headers={'date': 'Thu, 12 Aug 2021 12:33:47 GMT', 'content-length': '75', 'content-type': 'application/x-apple-binary-plist', 'server': 'AirTunes/550.10'}, body=b'bplist00\xd1\x01\x02UproofO\x10\x14\xca\xfev\x97^L\xe5\xe5\xf0\xce\xb0g\xdaqy\x85\xc8\xb9\x99i\x08\x0b\x11\x00\x00\x00\x00\x00\x00\x01\x01\x00\x00\x00\x00\x00\x00\x00\x03\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00('):
2021-08-12 08:33:47 DEBUG (MainThread) [pyatv.airplay.srp] Increase last byte from 189 to 190
2021-08-12 08:33:47 DEBUG (MainThread) [pyatv.airplay.srp] Pair-Setup-AES (IV=403558944b6bf01cb91564080331dfbe, Key=98fb1fb56b9f9dcb1a33f4c70a45419c)
2021-08-12 08:33:47 DEBUG (MainThread) [pyatv.airplay.srp] Pair-Setup EPK+Tag (EPK=4c3f26c8ee61ce2e067b4a509afe4bf2a2c403d32ac4a697845b894710f654f1, Tag=19a404a6eb3c7ee033b98053f2e36bac)
2021-08-12 08:33:47 DEBUG (MainThread) [pyatv.support.http] Sending HTTP/1.1 message: b'POST /pair-setup-pin HTTP/1.1\r\nUser-Agent: pyatv/0.8.2\r\nContent-Length: 116\r\n\r\nbplist00\xd2\x01\x02\x03\x04WauthTagSepkO\x10\x10\x19\xa4\x04\xa6\xeb<~\xe03\xb9\x80S\xf2\xe3k\xacO\x10 L?&\xc8\xeea\xce.\x06{JP\x9a\xfeK\xf2\xa2\xc4\x03\xd3*\xc4\xa6\x97\x84[\x89G\x10\xf6T\xf1\x08\r\x15\x19,\x00\x00\x00\x00\x00\x00\x01\x01\x00\x00\x00\x00\x00\x00\x00\x05\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00O'
2021-08-12 08:33:47 DEBUG (MainThread) [pyatv.support.http] Received: b'HTTP/1.1 200 OK\r\nDate: Thu, 12 Aug 2021 12:33:47 GMT\r\nContent-Length: 116\r\nContent-Type: application/x-apple-binary-plist\r\nServer: AirTunes/550.10\r\n\r\nbplist00\xd2\x01\x02\x03\x04SepkWauthTagO\x10 \x00\x99\x9aQ\x1e\x9aa\x92]H;K\x81\x92\x8e\xdc\xb1\x06GU\x91\x98d&4O^"E\x94\xe5\xf1O\x10\x10\xd8\x18$q\\N\xea\xcc\xb7D\xfdKv\x97S\x9d\x08\r\x11\x19<\x00\x00\x00\x00\x00\x00\x01\x01\x00\x00\x00\x00\x00\x00\x00\x05\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00O'
2021-08-12 08:33:47 DEBUG (MainThread) [pyatv.support.http] Got HTTP response: HttpResponse(protocol='HTTP', version='1.1', code=200, message='OK', headers={'date': 'Thu, 12 Aug 2021 12:33:47 GMT', 'content-length': '116', 'content-type': 'application/x-apple-binary-plist', 'server': 'AirTunes/550.10'}, body=b'bplist00\xd2\x01\x02\x03\x04SepkWauthTagO\x10 \x00\x99\x9aQ\x1e\x9aa\x92]H;K\x81\x92\x8e\xdc\xb1\x06GU\x91\x98d&4O^"E\x94\xe5\xf1O\x10\x10\xd8\x18$q\\N\xea\xcc\xb7D\xfdKv\x97S\x9d\x08\r\x11\x19<\x00\x00\x00\x00\x00\x00\x01\x01\x00\x00\x00\x00\x00\x00\x00\x05\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00O'):
2021-08-12 08:33:47 DEBUG (MainThread) [pyatv.support.http] Connection closed
2021-08-12 08:33:47 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=persistent_notification, service=dismiss, service_Data=xxx...) [homeassistant.components.media_player] Setting up media_player.apple_tv
2021-08-12 08:33:47 INFO (MainThread) [homeassistant.components.remote] Setting up remote.apple_tv
2021-08-12 08:33:47 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event device_registry_updated[L]: action=create, device_id=da2ca760839f3df51fdbe032f660784c>
2021-08-12 08:33:47 INFO (MainThread) [homeassistant.helpers.entity_registry] Registered new media_player.apple_tv entity: media_player.appletv
2021-08-12 08:33:47 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event entity_registry_updated[L]: action=create, entity_id=media_player.appletv>
2021-08-12 08:33:47 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=media_player.appletv, old_state=None, new_state=<state media_player.appletv=off; friendly_name=AppleTV, supported_features=317363 @ 2021-08-12T08:33:47.456747-04:00>>
2021-08-12 08:33:47 INFO (MainThread) [homeassistant.helpers.entity_registry] Registered new remote.apple_tv entity: remote.appletv
2021-08-12 08:33:47 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event entity_registry_updated[L]: action=create, entity_id=remote.appletv>
2021-08-12 08:33:47 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=remote.appletv, old_state=None, new_state=<state remote.appletv=off; friendly_name=AppleTV, supported_features=0 @ 2021-08-12T08:33:47.470749-04:00>>
2021-08-12 08:33:47 DEBUG (MainThread) [homeassistant.components.homekit.accessories] New_state: <state media_player.appletv=off; friendly_name=AppleTV, supported_features=317363 @ 2021-08-12T08:33:47.456747-04:00>
2021-08-12 08:33:47 DEBUG (MainThread) [homeassistant.components.homekit.type_media_players] media_player.appletv: Set current state for "on_off" to False
2021-08-12 08:33:47 DEBUG (MainThread) [pyhap.characteristic] set_value: On to False
2021-08-12 08:33:47 DEBUG (MainThread) [homeassistant.components.homekit.type_media_players] media_player.appletv: Set current state for "play_pause" to False
2021-08-12 08:33:47 DEBUG (MainThread) [homeassistant.components.homekit.type_media_players] media_player.appletv: Set current state for "play_stop" to False
2021-08-12 08:33:47 DEBUG (MainThread) [homeassistant.components.homekit.accessories] New_state: <state remote.appletv=off; friendly_name=AppleTV, supported_features=0 @ 2021-08-12T08:33:47.470749-04:00>
2021-08-12 08:33:47 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection] [140653328996000] Sending {"id": 40, "type": "event", "event": {"event_type": "device_registry_updated", "data": {"action": "create", "device_id": "da2ca760839f3df51fdbe032f660784c"}, "origin": "LOCAL", "time_fired": "2021-08-12T12:33:47.454246+00:00", "context": {"id": "5910120d92061237b993def236746e0d", "parent_id": null, "user_id": null}}}
2021-08-12 08:33:47 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection] [140653328996000] Sending {"id": 41, "type": "event", "event": {"event_type": "entity_registry_updated", "data": {"action": "create", "entity_id": "media_player.appletv"}, "origin": "LOCAL", "time_fired": "2021-08-12T12:33:47.455734+00:00", "context": {"id": "346c0cd0508ea4793591bc59d464a736", "parent_id": null, "user_id": null}}}
2021-08-12 08:33:47 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection] [140653328996000] Sending {"id": 29, "type": "event", "event": {"event_type": "state_changed", "data": {"entity_id": "media_player.appletv", "old_state": null, "new_state": {"entity_id": "media_player.appletv", "state": "off", "attributes": {"friendly_name": "AppleTV", "supported_features": 317363}, "last_changed": "2021-08-12T12:33:47.456747+00:00", "last_updated": "2021-08-12T12:33:47.456747+00:00", "context": {"id": "4a05692f25867f2a5f9c89c9eee1e268", "parent_id": null, "user_id": null}}}, "origin": "LOCAL", "time_fired": "2021-08-12T12:33:47.456747+00:00", "context": {"id": "4a05692f25867f2a5f9c89c9eee1e268", "parent_id": null, "user_id": null}}}
2021-08-12 08:33:47 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection] [140653328996000] Sending {"id": 41, "type": "event", "event": {"event_type": "entity_registry_updated", "data": {"action": "create", "entity_id": "remote.appletv"}, "origin": "LOCAL", "time_fired": "2021-08-12T12:33:47.458624+00:00", "context": {"id": "1ed46977baff0da4661b9f1190e1d128", "parent_id": null, "user_id": null}}}
2021-08-12 08:33:47 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection] [140653328996000] Sending {"id": 29, "type": "event", "event": {"event_type": "state_changed", "data": {"entity_id": "remote.appletv", "old_state": null, "new_state": {"entity_id": "remote.appletv", "state": "off", "attributes": {"friendly_name": "AppleTV", "supported_features": 0}, "last_changed": "2021-08-12T12:33:47.470749+00:00", "last_updated": "2021-08-12T12:33:47.470749+00:00", "context": {"id": "a6060c67bac21cebfe89a8c4a9847805", "parent_id": null, "user_id": null}}}, "origin": "LOCAL", "time_fired": "2021-08-12T12:33:47.470749+00:00", "context": {"id": "a6060c67bac21cebfe89a8c4a9847805", "parent_id": null, "user_id": null}}}
2021-08-12 08:33:47 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection] [140653544622496] Sending {"id": 37, "type": "event", "event": {"event_type": "device_registry_updated", "data": {"action": "create", "device_id": "da2ca760839f3df51fdbe032f660784c"}, "origin": "LOCAL", "time_fired": "2021-08-12T12:33:47.454246+00:00", "context": {"id": "5910120d92061237b993def236746e0d", "parent_id": null, "user_id": null}}}
2021-08-12 08:33:47 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection] [140653544622496] Sending {"id": 38, "type": "event", "event": {"event_type": "entity_registry_updated", "data": {"action": "create", "entity_id": "media_player.appletv"}, "origin": "LOCAL", "time_fired": "2021-08-12T12:33:47.455734+00:00", "context": {"id": "346c0cd0508ea4793591bc59d464a736", "parent_id": null, "user_id": null}}}
2021-08-12 08:33:47 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection] [140653544622496] Sending {"id": 26, "type": "event", "event": {"event_type": "state_changed", "data": {"entity_id": "media_player.appletv", "old_state": null, "new_state": {"entity_id": "media_player.appletv", "state": "off", "attributes": {"friendly_name": "AppleTV", "supported_features": 317363}, "last_changed": "2021-08-12T12:33:47.456747+00:00", "last_updated": "2021-08-12T12:33:47.456747+00:00", "context": {"id": "4a05692f25867f2a5f9c89c9eee1e268", "parent_id": null, "user_id": null}}}, "origin": "LOCAL", "time_fired": "2021-08-12T12:33:47.456747+00:00", "context": {"id": "4a05692f25867f2a5f9c89c9eee1e268", "parent_id": null, "user_id": null}}}
2021-08-12 08:33:47 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection] [140653544622496] Sending {"id": 38, "type": "event", "event": {"event_type": "entity_registry_updated", "data": {"action": "create", "entity_id": "remote.appletv"}, "origin": "LOCAL", "time_fired": "2021-08-12T12:33:47.458624+00:00", "context": {"id": "1ed46977baff0da4661b9f1190e1d128", "parent_id": null, "user_id": null}}}
2021-08-12 08:33:47 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection] [140653544622496] Sending {"id": 26, "type": "event", "event": {"event_type": "state_changed", "data": {"entity_id": "remote.appletv", "old_state": null, "new_state": {"entity_id": "remote.appletv", "state": "off", "attributes": {"friendly_name": "AppleTV", "supported_features": 0}, "last_changed": "2021-08-12T12:33:47.470749+00:00", "last_updated": "2021-08-12T12:33:47.470749+00:00", "context": {"id": "a6060c67bac21cebfe89a8c4a9847805", "parent_id": null, "user_id": null}}}, "origin": "LOCAL", "time_fired": "2021-08-12T12:33:47.470749+00:00", "context": {"id": "a6060c67bac21cebfe89a8c4a9847805", "parent_id": null, "user_id": null}}}
2021-08-12 08:33:47 DEBUG (MainThread) [homeassistant.components.google_assistant.report_state] Scheduling report state for media_player.appletv: {'online': True, 'on': False, 'activityState': 'INACTIVE', 'playbackState': 'STOPPED'}
2021-08-12 08:33:47 DEBUG (MainThread) [homeassistant.components.apple_tv] Starting connect loop
2021-08-12 08:33:47 DEBUG (MainThread) [homeassistant.components.apple_tv] Discovering device xxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxxxxx
2021-08-12 08:33:47 DEBUG (MainThread) [pyatv.support.knock] Knocking at ports [3689, 7000, 49152, 32498] on 192.168.xxx.xxx
2021-08-12 08:33:47 DEBUG (MainThread) [pyatv.support.scan] Auto-discovered AppleTV at 192.168.xxx.xxx:49153 via Protocol.MRP ({'modelname': 'Apple TV', 'allowpairing': 'YES', 'bluetoothaddress': "b'\\xc8\\xd0\\x83\\xd4J2'", 'macaddress': 'c8:d0:83:e8:ac:cf', 'name': 'AppleTV', 'uniqueidentifier': 'xxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxxxxx', 'systembuildversion': '18M60', 'localairplayreceiverpairingidentity': 'xxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxxxxx'})
2021-08-12 08:33:47 DEBUG (MainThread) [homeassistant.components.apple_tv] Connecting to device AppleTV
2021-08-12 08:33:47 DEBUG (MainThread) [pyatv] Adding protocol Protocol.MRP
2021-08-12 08:33:47 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection] [140653328996000] Received {'type': 'config/device_registry/list', 'id': 62}
2021-08-12 08:33:47 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection] [140653328996000] Received {'type': 'config/entity_registry/list', 'id': 63}
2021-08-12 08:33:47 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection] [140653544622496] Received {'type': 'config/device_registry/list', 'id': 81}
2021-08-12 08:33:47 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection] [140653544622496] Received {'type': 'config/entity_registry/list', 'id': 82}
2021-08-12 08:33:47 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection] [140653328996000] Sending {"id": 62, "type": "result", "success": true, "result": xxx}
2021-08-12 08:33:47 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection] [140653328996000] Sending {"id": 63, "type": "result", "success": true, "result": xxx}
2021-08-12 08:33:47 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection] [140653544622496] Sending {"id": 81, "type": "result", "success": true, "result": xxx}
2021-08-12 08:33:47 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection] [140653544622496] Sending {"id": 82, "type": "result", "success": true, "result": xxx}
2021-08-12 08:33:47 DEBUG (MainThread) [pyatv.mrp.connection] Connection made to device
2021-08-12 08:33:47 DEBUG (MainThread) [pyatv.support.net] Configured keep-alive on <asyncio.TransportSocket fd=15, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('192.168.xxx.xxx', 39046), raddr=('192.168.xxx.xxx', 49153)> (Linux)
2021-08-12 08:33:47 DEBUG (MainThread) [pyatv.mrp.connection] 192.168.xxx.xxx:39046<->192.168.xxx.xxx:49153  Connection established
2021-08-12 08:33:47 DEBUG (MainThread) [pyatv.mrp.connection] 192.168.xxx.xxx:39046<->192.168.xxx.xxx:49153 >> Send (Data=xxx...)
2021-08-12 08:33:47 DEBUG (MainThread) [pyatv.mrp.connection] 192.168.xxx.xxx:39046<->192.168.xxx.xxx:49153 >> Send: Protobuf: type: DEVICE_INFO_MESSAGE
identifier: "xxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxxxxx"
errorCode: NoError
[deviceInfoMessage] {
  uniqueIdentifier: "xxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxxxxx"
  name: "pyatv"
  localizedModelName: "iPhone"
  systemBuildVersion: "18A393"
  applicationBundleIdentifier: "com.apple.TVRemote"
  applicationBundleVersion: "344.28"
  protocolVersion: 1
  lastSupportedMessageType: 108
  supportsSystemPairing: true
  allowsPairing: true
  systemMediaApplication: "com.apple.TVMusic"
  supportsACL: true
  supportsSharedQueue: true
  supportsExtendedMotion: true
  sharedQueueVersion: 2
  deviceClass: iPhone
  logicalDeviceCount: 1
}
2021-08-12 08:33:47 DEBUG (MainThread) [pyatv.mrp.connection] 192.168.xxx.xxx:39046<->192.168.xxx.xxx:49153 << Receive (Data=xxx...)
2021-08-12 08:33:47 DEBUG (MainThread) [pyatv.mrp.connection] 192.168.xxx.xxx:39046<->192.168.xxx.xxx:49153 << Receive: Protobuf: type: DEVICE_INFO_MESSAGE
identifier: "xxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxxxxx"
errorCode: NoError
[deviceInfoMessage] {
  uniqueIdentifier: "xxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxxxxx"
  name: "AppleTV"
  localizedModelName: "Apple\302\240TV"
  systemBuildVersion: "18M60"
  applicationBundleIdentifier: "com.apple.mediaremoted"
  protocolVersion: 1
  lastSupportedMessageType: 108
  supportsSystemPairing: true
  allowsPairing: true
  systemMediaApplication: "com.apple.TVMusic"
  supportsACL: true
  supportsSharedQueue: true
  supportsExtendedMotion: true
  sharedQueueVersion: 3
  deviceUID: "xxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxxxxx"
  managedConfigDeviceID: "c8:d0:83:e8:ac:cf"
  deviceClass: AppleTV
  logicalDeviceCount: 1
  isProxyGroupPlayer: false
  groupUID: "xxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxxxxx"
  isGroupLeader: true
  isAirplayActive: true
  systemPodcastApplication: "com.apple.podcasts"
  enderDefaultGroupUID: "xxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxxxxx"
  airplayReceivers: "TVAirPlay"
  clusterType: 0
  isClusterAware: true
  modelID: "AppleTV6,2"
}
uniqueIdentifier: "xxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxxxxx"
2021-08-12 08:33:47 DEBUG (MainThread) [pyatv.mrp.connection] 192.168.xxx.xxx:39046<->192.168.xxx.xxx:49153 >> Send (Data=xxx...)
2021-08-12 08:33:47 DEBUG (MainThread) [pyatv.mrp.connection] 192.168.xxx.xxx:39046<->192.168.xxx.xxx:49153 >> Send: Protobuf: type: CRYPTO_PAIRING_MESSAGE
errorCode: NoError
[cryptoPairingMessage] {
  pairingData: "\006\001\001\003 \275.-\2005\236Y\023\177\233\242\346\221N\3635\246(\271J\233$\225\364\346\014Ka\021\2019V"
  status: 0
  isRetrying: false
  isUsingSystemPairing: false
  state: 0
}
2021-08-12 08:33:47 DEBUG (MainThread) [pyatv.mrp.connection] 192.168.xxx.xxx:39046<->192.168.xxx.xxx:49153 << Receive (Data=xxx...)
2021-08-12 08:33:47 DEBUG (MainThread) [pyatv.mrp.connection] 192.168.xxx.xxx:39046<->192.168.xxx.xxx:49153 << Receive: Protobuf: type: CRYPTO_PAIRING_MESSAGE
errorCode: NoError
[cryptoPairingMessage] {
  pairingData: "\005x?a\370\240\031*\243\224\353\205\320\317\316\245)\267M\330\266<\222\305]-r=T\303\352\312G\321\002]j\023m\230\321\246\322I$)\017...
  status: 0
  isRetrying: false
  isUsingSystemPairing: false
  state: 0
}
uniqueIdentifier: "xxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxxxxx"
2021-08-12 08:33:47 DEBUG (MainThread) [pyatv.mrp.auth] Device (Encrypted=xxx...)
2021-08-12 08:33:47 DEBUG (MainThread) [pyatv.mrp.connection] 192.168.xxx.xxx:39046<->192.168.xxx.xxx:49153 >> Send (Data=xxx...)
2021-08-12 08:33:47 DEBUG (MainThread) [pyatv.mrp.connection] 192.168.xxx.xxx:39046<->192.168.xxx.xxx:49153 >> Send: Protobuf: type: CRYPTO_PAIRING_MESSAGE
errorCode: NoError
[cryptoPairingMessage] {
  pairingData: "\006\001\003\005x#\374\2166\244\210$a\243\260Ro\034\216i\0024\246\346:\327\357\214\234\n\244\320\320ZD`%\275\334\255\036Mfjp\322\33...
  status: 0
  isRetrying: false
  isUsingSystemPairing: false
  state: 0
}
2021-08-12 08:33:47 DEBUG (MainThread) [pyatv.mrp.connection] 192.168.xxx.xxx:39046<->192.168.xxx.xxx:49153 << Receive (Data=xxx...)
2021-08-12 08:33:47 DEBUG (MainThread) [pyatv.mrp.connection] 192.168.xxx.xxx:39046<->192.168.xxx.xxx:49153 << Receive: Protobuf: type: CRYPTO_PAIRING_MESSAGE
errorCode: NoError
[cryptoPairingMessage] {
  pairingData: "\006\001\004"
  status: 0
  isRetrying: false
  isUsingSystemPairing: false
  state: 0
}
uniqueIdentifier: "xxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxxxxx"
2021-08-12 08:33:47 DEBUG (MainThread) [pyatv.support.hap_srp] Keys (Input=77bbef7ba60d44a6117bac20a7047d0463d934a861b363d157aa3a923f162d9e, Output=f0416af65df8ac0480b72090fa8cdc88bff76e7e109d48b1ac078fa57a158231)
2021-08-12 08:33:47 DEBUG (MainThread) [pyatv.mrp.connection] 192.168.xxx.xxx:39046<->192.168.xxx.xxx:49153 >> Send (Data=xxx...)
2021-08-12 08:33:47 DEBUG (MainThread) [pyatv.mrp.connection] 192.168.xxx.xxx:39046<->192.168.xxx.xxx:49153 >> Send (Encrypted=xxx...)
2021-08-12 08:33:47 DEBUG (MainThread) [pyatv.mrp.connection] 192.168.xxx.xxx:39046<->192.168.xxx.xxx:49153 >> Send: Protobuf: type: SET_CONNECTION_STATE_MESSAGE
errorCode: NoError
[setConnectionStateMessage] {
  state: Connected
}
2021-08-12 08:33:47 DEBUG (MainThread) [pyatv.mrp.connection] 192.168.xxx.xxx:39046<->192.168.xxx.xxx:49153 >> Send (Data=xxx...)
2021-08-12 08:33:47 DEBUG (MainThread) [pyatv.mrp.connection] 192.168.xxx.xxx:39046<->192.168.xxx.xxx:49153 >> Send (Encrypted=xxx...)
2021-08-12 08:33:47 DEBUG (MainThread) [pyatv.mrp.connection] 192.168.xxx.xxx:39046<->192.168.xxx.xxx:49153 >> Send: Protobuf: type: CLIENT_UPDATES_CONFIG_MESSAGE
identifier: "xxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxxxxx"
errorCode: NoError
[clientUpdatesConfigMessage] {
  artworkUpdates: true
  nowPlayingUpdates: false
  volumeUpdates: true
  keyboardUpdates: true
  outputDeviceUpdates: false
}
2021-08-12 08:33:47 DEBUG (MainThread) [pyatv.mrp.connection] 192.168.xxx.xxx:39046<->192.168.xxx.xxx:49153 << Receive (Data=xxx...)
2021-08-12 08:33:47 DEBUG (MainThread) [pyatv.mrp.connection] 192.168.xxx.xxx:39046<->192.168.xxx.xxx:49153 << Receive (Decrypted=xxx...)
2021-08-12 08:33:47 DEBUG (MainThread) [pyatv.mrp.connection] 192.168.xxx.xxx:39046<->192.168.xxx.xxx:49153 << Receive: Protobuf: type: UPDATE_OUTPUT_DEVICE_MESSAGE
errorCode: NoError
[updateOutputDeviceMessage] {
  outputDevices {
    name: "AppleTV"
    uniqueIdentifier: "xxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxxxxx"
    deviceType: Wired
    volumeCapabilities: 0
  }
  clusterAwareOutputDevices {
    name: "AppleTV"
    uniqueIdentifier: "xxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxxxxx"
    deviceType: Wired
    volumeCapabilities: 0
  }
}
uniqueIdentifier: "xxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxxxxx"
2021-08-12 08:33:47 DEBUG (MainThread) [pyatv.mrp.connection] 192.168.xxx.xxx:39046<->192.168.xxx.xxx:49153 << Receive (Decrypted=xxx...)
2021-08-12 08:33:47 DEBUG (MainThread) [pyatv.mrp.connection] 192.168.xxx.xxx:39046<->192.168.xxx.xxx:49153 << Receive: Protobuf: type: SET_DEFAULT_SUPPORTED_COMMANDS_MESSAGE
errorCode: NoError
[setDefaultSupportedCommandsMessage] {
  supportedCommands {
    supportedCommands {
      command: Play
      enabled: true
    }
    supportedCommands {
      command: PrepareForSetQueue
      enabled: true
    }
    supportedCommands {
      command: SetPlaybackQueue
      enabled: true
      supportedPlaybackQueueTypes: 7
      supportedPlaybackQueueTypes: 3
      supportedPlaybackQueueTypes: 6
      supportedPlaybackQueueTypes: 2
      supportedPlaybackQueueTypes: 5
      supportedPlaybackQueueTypes: 1
      supportedPlaybackQueueTypes: 8
      supportedCustomQueueIdentifiers: "com.apple.music.playbackqueue.radio"
      supportedCustomQueueIdentifiers: "com.apple.music.playbackqueue.tracklist"
      supportedCustomQueueIdentifiers: "com.apple.MediaPlaybackCore.playbackContextArchive-v1.opack"
      supportedCustomQueueIdentifiers: "com.apple.mediaplayer.playbackcontext"
    }
    supportedCommands {
      command: SetPlaybackSession
    }
    supportedCommands {
    }
  }
  displayID: "com.apple.TVMusic"
  playbackQueueCapabilities {
  }
  playerPath {
    client {
      bundleIdentifier: "com.apple.TVMusic"
    }
  }
}
uniqueIdentifier: "xxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxxxxx"
2021-08-12 08:33:47 DEBUG (MainThread) [pyatv.mrp.protocol] Dispatching message with type 72 (SetDefaultSupportedCommandsMessage) to Listener(func=<bound method PlayerStateManager._handle_set_default_supported_commands of <pyatv.mrp.player_state.PlayerStateManager object at 0x7fec70a14610>>, Data=xxx...)
2021-08-12 08:33:47 DEBUG (MainThread) [pyatv.mrp.connection] 192.168.xxx.xxx:39046<->192.168.xxx.xxx:49153 << Receive (Decrypted=xxx...)
2021-08-12 08:33:47 DEBUG (MainThread) [pyatv.mrp.connection] 192.168.xxx.xxx:39046<->192.168.xxx.xxx:49153 << Receive: Protobuf: type: SET_DEFAULT_SUPPORTED_COMMANDS_MESSAGE
errorCode: NoError
[setDefaultSupportedCommandsMessage] {
  supportedCommands {
    supportedCommands {
      command: Play
      enabled: true
    }
    supportedCommands {
      command: SetPlaybackQueue
      enabled: true
      supportedPlaybackQueueTypes: 3
      supportedPlaybackQueueTypes: 6
      supportedPlaybackQueueTypes: 2
      supportedPlaybackQueueTypes: 5
      supportedPlaybackQueueTypes: 1
    }
    supportedCommands {
      command: SetPlaybackSession
      enabled: true
      supportedPlaybackSessionTypes: "com.apple.podcasts.MTPlaybackQueueController.GenericQueue"
      currentPlaybackSessionTypes: "com.apple.podcasts.MTPlaybackQueueController.GenericQueue"
    }
  }
  displayID: "com.apple.podcasts"
  playbackQueueCapabilities {
  }
  playerPath {
    client {
      bundleIdentifier: "com.apple.podcasts"
    }
  }
}
uniqueIdentifier: "xxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxxxxx"
2021-08-12 08:33:47 DEBUG (MainThread) [pyatv.mrp.protocol] Dispatching message with type 72 (SetDefaultSupportedCommandsMessage) to Listener(func=<bound method PlayerStateManager._handle_set_default_supported_commands of <pyatv.mrp.player_state.PlayerStateManager object at 0x7fec70a14610>>, Data=xxx...)
2021-08-12 08:33:47 DEBUG (MainThread) [pyatv.mrp.connection] 192.168.xxx.xxx:39046<->192.168.xxx.xxx:49153 << Receive (Decrypted=xxx...)
2021-08-12 08:33:47 DEBUG (MainThread) [pyatv.mrp.connection] 192.168.xxx.xxx:39046<->192.168.xxx.xxx:49153 << Receive: Protobuf: type: ORIGIN_CLIENT_PROPERTIES_MESSAGE
errorCode: NoError
uniqueIdentifier: "xxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxxxxx"
[originClientPropertiesMessage] {
  lastPlayingTimestamp: 650432610.392544
}
2021-08-12 08:33:47 DEBUG (MainThread) [pyatv.mrp.connection] 192.168.xxx.xxx:39046<->192.168.xxx.xxx:49153 << Receive (Decrypted=xxx...)
2021-08-12 08:33:47 DEBUG (MainThread) [pyatv.mrp.connection] 192.168.xxx.xxx:39046<->192.168.xxx.xxx:49153 << Receive: Protobuf: type: SET_NOW_PLAYING_CLIENT_MESSAGE
errorCode: NoError
[setNowPlayingClientMessage] {
  client {
    processIdentifier: 145
    bundleIdentifier: "com.apple.TVAirPlay"
  }
}
uniqueIdentifier: "xxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxxxxx"
2021-08-12 08:33:47 DEBUG (MainThread) [pyatv.mrp.protocol] Dispatching message with type 46 (SetNowPlayingClientMessage) to Listener(func=<bound method PlayerStateManager._handle_set_now_playing_client of <pyatv.mrp.player_state.PlayerStateManager object at 0x7fec70a14610>>, Data=xxx...)
2021-08-12 08:33:47 DEBUG (MainThread) [pyatv.mrp.connection] 192.168.xxx.xxx:39046<->192.168.xxx.xxx:49153 << Receive (Decrypted=xxx...)
2021-08-12 08:33:47 DEBUG (MainThread) [pyatv.mrp.connection] 192.168.xxx.xxx:39046<->192.168.xxx.xxx:49153 << Receive: Protobuf: type: UPDATE_CLIENT_MESSAGE
errorCode: NoError
[updateClientMessage] {
  client {
    processIdentifier: 145
    bundleIdentifier: "com.apple.TVAirPlay"
    processUserIdentifier: 501
    displayName: "Safari"
    bundleIdentifierHierarchys: "com.apple.WebKit.WebContent"
    bundleIdentifierHierarchys: "com.apple.SafariViewService"
  }
}
uniqueIdentifier: "xxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxxxxx"
2021-08-12 08:33:47 DEBUG (MainThread) [pyatv.mrp.protocol] Dispatching message with type 55 (UpdateClientMessage) to Listener(func=<bound method PlayerStateManager._handle_update_client of <pyatv.mrp.player_state.PlayerStateManager object at 0x7fec70a14610>>, Data=xxx...)
2021-08-12 08:33:47 DEBUG (MainThread) [pyatv.mrp.connection] 192.168.xxx.xxx:39046<->192.168.xxx.xxx:49153 << Receive (Decrypted=xxx...)
2021-08-12 08:33:47 DEBUG (MainThread) [pyatv.mrp.connection] 192.168.xxx.xxx:39046<->192.168.xxx.xxx:49153 << Receive: Protobuf: type: SET_STATE_MESSAGE
errorCode: NoError
[setStateMessage] {
  playbackQueue {
    location: 0
    contentItems {
      identifier: "xxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxxxxx"
      metadata {
      }
    }
  }
  displayName: "Safari"
  playbackState: Stopped
  playbackQueueCapabilities {
    requestByRange: true
    requestByIdentifiers: true
  }
  playerPath {
    origin {
      displayName: "AppleTV"
      identifier: 1280262988
    }
    client {
      processIdentifier: 145
      bundleIdentifier: "com.apple.TVAirPlay"
    }
    player {
      identifier: "MediaRemote-DefaultPlayer"
      displayName: "Default Player"
    }
  }
  playbackStateTimestamp: 649374726.026785
}
uniqueIdentifier: "xxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxxxxx"
2021-08-12 08:33:47 DEBUG (MainThread) [pyatv.mrp.protocol] Dispatching message with type 4 (SetStateMessage) to Listener(func=<bound method PlayerStateManager._handle_set_state of <pyatv.mrp.player_state.PlayerStateManager object at 0x7fec70a14610>>, Data=xxx...)
2021-08-12 08:33:47 DEBUG (MainThread) [pyatv.mrp.connection] 192.168.xxx.xxx:39046<->192.168.xxx.xxx:49153 << Receive (Decrypted=xxx...)
2021-08-12 08:33:47 DEBUG (MainThread) [pyatv.mrp.connection] 192.168.xxx.xxx:39046<->192.168.xxx.xxx:49153 << Receive: Protobuf: type: PLAYER_CLIENT_PROPERTIES_MESSAGE
errorCode: NoError
uniqueIdentifier: "xxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxxxxx"
[playerClientPropertiesMessage] {
  playerPath {
    origin {
      displayName: "AppleTV"
      identifier: 1280262988
    }
    client {
      processIdentifier: 145
      bundleIdentifier: "com.apple.TVAirPlay"
      processUserIdentifier: 501
      displayName: "Safari"
      bundleIdentifierHierarchys: "com.apple.WebKit.WebContent"
      bundleIdentifierHierarchys: "com.apple.SafariViewService"
    }
    player {
      identifier: "MediaRemote-DefaultPlayer"
      displayName: "Default Player"
    }
  }
  lastPlayingTimestamp: 649374245.852242
}
2021-08-12 08:33:47 DEBUG (MainThread) [pyatv.mrp.connection] 192.168.xxx.xxx:39046<->192.168.xxx.xxx:49153 << Receive (Decrypted=xxx...)
2021-08-12 08:33:47 DEBUG (MainThread) [pyatv.mrp.connection] 192.168.xxx.xxx:39046<->192.168.xxx.xxx:49153 << Receive: Protobuf: type: UNKNOWN_MESSAGE
identifier: "xxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxxxxx"
errorCode: NoError
uniqueIdentifier: "xxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxxxxx"
2021-08-12 08:33:47 DEBUG (MainThread) [pyatv.mrp.player_state] Active client is now com.apple.TVAirPlay
2021-08-12 08:33:47 DEBUG (MainThread) [pyatv.mrp.connection] 192.168.xxx.xxx:39046<->192.168.xxx.xxx:49153 >> Send (Data=xxx...)
2021-08-12 08:33:47 DEBUG (MainThread) [pyatv.mrp.connection] 192.168.xxx.xxx:39046<->192.168.xxx.xxx:49153 >> Send (Encrypted=xxx...)
2021-08-12 08:33:47 DEBUG (MainThread) [pyatv.mrp.connection] 192.168.xxx.xxx:39046<->192.168.xxx.xxx:49153 >> Send: Protobuf: type: GET_KEYBOARD_SESSION_MESSAGE
identifier: "xxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxxxxx"
errorCode: NoError
2021-08-12 08:33:47 DEBUG (MainThread) [pyatv.mrp.connection] 192.168.xxx.xxx:39046<->192.168.xxx.xxx:49153 << Receive (Data=xxx...)
2021-08-12 08:33:47 DEBUG (MainThread) [pyatv.mrp.connection] 192.168.xxx.xxx:39046<->192.168.xxx.xxx:49153 << Receive (Decrypted=xxx...)
2021-08-12 08:33:47 DEBUG (MainThread) [pyatv.mrp.connection] 192.168.xxx.xxx:39046<->192.168.xxx.xxx:49153 << Receive: Protobuf: type: KEYBOARD_MESSAGE
identifier: "xxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxxxxx"
errorCode: NoError
[keyboardMessage] {
  state: 0
  attributes {
    inputTraits {
      autocapitalizationType: None
      keyboardType: Default
      returnKeyType: Default
      enablesReturnKeyAutomatically: false
      secureTextEntry: false
      validTextRangeLocation: 0
      validTextRangeLength: 0
    }
  }
}
uniqueIdentifier: "xxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxxxxx"
2021-08-12 08:33:47 DEBUG (MainThread) [homeassistant.components.apple_tv] Changing address to 192.168.xxx.xxx
2021-08-12 08:33:47 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event device_registry_updated[L]: action=update, device_id=da2ca760839f3df51fdbe032f660784c>
2021-08-12 08:33:47 DEBUG (MainThread) [homeassistant.components.apple_tv] Connect loop ended
2021-08-12 08:33:47 DEBUG (MainThread) [pyatv.mrp.protocol] Starting heartbeat loop
Garulf commented 3 years ago

Seeing this issue as well after updating to 2021.7.4 and the current release 2021.8.6. I have repaired my Apple TV and I get the same error. Works fine when downgraded to pyatv 0.7.7

This is using the both the media_extractor.play_media and media_player.play_media services.

2021-08-12 16:45:23 error (MainThread) [homeassistant.core] Error executing service: <ServiceCall media_player.play_media (c:6ccf0ee0192dc4337d0d57f516576c57): extra=, entity_id=['media_player.living_room_apple_tv'], media_type=video, media_id=https://video-weaver.jfk04.hls.ttvnw.net/v1/playlist/Co8EQ74qtIyv5KmQah1MuCL8lVnRtXir9OZi7xJ6xBs3xtz_aalffioBaJ-DP1cb9GqWgLDroAaDEKCv21QezA3bBVW4maPCZ8wKeIAd4V2PETXsqqis8bnbK4_f2i-ZHDW7B1KMOigHtxIAZW8vp5zT5mRcVw4K1oWB715iZZF1cnEYJzWj00Lwxo2hY5d6ZDUrGtdWIMndmPdkckWf0nlgbLPFn-MSchAo3wpQ9ADl3FjulzB3pl1kOsnn9zC-solG3ABDgzP21JCu8la576KPwrVI7RtlQu8cdal-WG1ApTg8QATnNLbVrNVbXrMI8tQLtXHZ5a_v1yYoodHLsI9ky1DGjeJefMp-BGeoSWlSE1_L-8xmyGFignrQeuBSC9j7bT9XpKeu6BfdeC0Zv7PGe7ShyiwlEOlyziVFSmmkLVg2KbXPtARK0-nPmiGYDcUL3aWP0jXlyU-doKCi0SvAS5_osVCgxL5uA0v51zHKTUerDEfUVm3_dS2OSfNDRIbRIxQa5M8nv2qKXFbiJJu-oQl-pGVPgHCwwABPUcYyUR5FeZySK66Pcu2uKMcVCtRrEJWoUQPjd83vAVsdKtQDghDagtKoqc1N4vB0RCx0kqmlT-8PVHKhxJTKiICMheoZdy7S5OZjUiDI9z9_hbaIZ3dGFDxe6M_p77oWEP5gpx2KvKAfi6vn0M-LJDU_O0YSEBSV70brgyIXL5FMmf8rl6oaDOd8SeuxH8nd41jQ8w.m3u8>
Traceback (most recent call last):
  File "/Volumes/HomeAssistant/.venv/lib/python3.9/site-packages/homeassistant/core.py", line 1507, in catch_exceptions
    await coro_or_task
  File "/Volumes/HomeAssistant/.venv/lib/python3.9/site-packages/homeassistant/core.py", line 1526, in _execute_service
    await handler.job.target(service_call)
  File "/Volumes/HomeAssistant/.venv/lib/python3.9/site-packages/homeassistant/helpers/entity_component.py", line 213, in handle_service
    await self.hass.helpers.service.entity_service_call(
  File "/Volumes/HomeAssistant/.venv/lib/python3.9/site-packages/homeassistant/helpers/service.py", line 658, in entity_service_call
    future.result()  # pop exception if have
  File "/Volumes/HomeAssistant/.venv/lib/python3.9/site-packages/homeassistant/helpers/entity.py", line 856, in async_request_call
    await coro
  File "/Volumes/HomeAssistant/.venv/lib/python3.9/site-packages/homeassistant/helpers/service.py", line 695, in _handle_entity_call
    await result
  File "/Volumes/HomeAssistant/.venv/lib/python3.9/site-packages/homeassistant/components/apple_tv/media_player.py", line 176, in async_play_media
    await self.atv.stream.play_url(media_id)
  File "/Volumes/HomeAssistant/.venv/lib/python3.9/site-packages/pyatv/support/facade.py", line 326, in play_url
    await self.relay("play_url")(url, **kwargs)
  File "/Volumes/HomeAssistant/.venv/lib/python3.9/site-packages/pyatv/support/relayer.py", line 75, in relay
    instance = self._find_instance(target, priority or self._priorities)
  File "/Volumes/HomeAssistant/.venv/lib/python3.9/site-packages/pyatv/support/relayer.py", line 97, in _find_instance
    raise exceptions.NotSupportedError(f"{target} is not supported")
pyatv.exceptions.NotSupportedError: play_url is not supported
arstropica commented 3 years ago

@Garulf That didn't do it for me. I had to roll back home assistant to v. 2021.6.6 to get it working again.

Garulf commented 3 years ago

@Garulf That didn't do it for me. I had to roll back home assistant to v. 2021.6.6 to get it working again.

How are you downgrading? You may have to change the pinned version in the apple_tv component.

/homeassistant/components/apple_tv/manifest.json

change "requirements" to pyatv==0.7.7

{
  "domain": "apple_tv",
  "name": "Apple TV",
  "config_flow": true,
  "documentation": "https://www.home-assistant.io/integrations/apple_tv",
  "requirements": ["pyatv==0.7.7"],
  "zeroconf": ["_mediaremotetv._tcp.local.", "_touch-able._tcp.local."],
  "after_dependencies": ["discovery"],
  "codeowners": ["@postlund"],
  "iot_class": "local_push"
}
arstropica commented 3 years ago

@Garulf At first, I used pip to downgrade pyatv to version 0.7.7. That didn't seem to fix the issue, so I used the command line to downgrade home assistant to 2021.6.6 and that fixed the issue.

Garulf commented 3 years ago

Any update on this?

postlund commented 3 years ago

No update yet, I'm putting all my time into figuring out how to replace MRP once tvOS 15 is released as everything will break once it is. I will try to look at other issues when I have that part under control, but it's not easy so might take some time.

Garulf commented 3 years ago

No update yet, I'm putting all my time into figuring out how to replace MRP once tvOS 15 is released as everything will break once it is. I will try to look at other issues when I have that part under control, but it's not easy so might take some time.

Okay, thanks for replying. At the very least v0.7.7 works fine.

github-actions[bot] commented 3 years ago

There hasn't been any activity on this issue recently. Due to the high number of incoming GitHub notifications, we have to clean some of the old issues, as many of them have already been resolved with the latest updates. Please make sure to update to the latest Home Assistant version and check if that solves the issue. Let us know if that works for you by adding a comment 👍 This issue has now been marked as stale and will be closed if no further activity occurs. Thank you for your contributions.