search

postlund / pyatv

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

Status shows unknown after powering off apple tv #589

Closed jasr1 closed 3 years ago

jasr1 commented 4 years ago

Describe the bug

When I turn off the Apple TV from the remote, the status ends up switching from playing/paused/idle etc to "Unknown", instead of "Off" or "idle".

To Reproduce

Turn off Apple TV from the remote.

Expected behavior

The status to be "Off" or "idle" when the Apple TV is off.

System Setup (please complete the following information):

Additional context

Apple TV is connected to the internet via ethernet cable. I have restarted Home Assistant and the issue still occurs.

postlund commented 4 years ago

This sounds like the component ends up in a re-connect loop, which it shouldn't. It would help me a lot if you provide some logs, I don't see this behavior myself.

jasr1 commented 4 years ago

Sure, I can definitely get you the logs. Where do I find them?

postlund commented 4 years ago

Preferably like this:

logger:
  default: warning
  logs:
    pyatv: debug
    custom_components.apple_tv: debug

It will set default log level to warning to avoid getting swamped with debug data from other components.

jasr1 commented 4 years ago

Awesome, here are the logs:

Another issue seems to have arisen (I am not sure if this is related), but when I restarted my Home Assistant instance, upon start up the Apple TV showed it was in the "Paused" state, even though the Apple TV is completely turned off. 

2020-04-17 00:08:50 DEBUG (MainThread) [custom_components.apple_tv] Disconnecting from device
2020-04-17 00:08:50 DEBUG (MainThread) [custom_components.apple_tv] Updating state: connected=False, disconnected=False
2020-04-17 00:08:50 DEBUG (MainThread) [pyatv.mrp.connection] Disconnected from device: None
2020-04-17 00:08:50 DEBUG (MainThread) [custom_components.apple_tv] Updating state: connected=False, disconnected=True
2020-04-17 00:08:50 DEBUG (MainThread) [custom_components.apple_tv] Not starting connect loop (True, False)
2020-04-17 00:08:55 DEBUG (MainThread) [custom_components.apple_tv] Starting connect loop
2020-04-17 00:08:55 DEBUG (MainThread) [custom_components.apple_tv] Updating state: connected=False, disconnected=False
2020-04-17 00:08:55 DEBUG (MainThread) [pyatv.support.udns] Sending DNS request to 192.168.8.184 (Data=35ff012000040000000000000b5f6170706c6574762d7632045f746370056c6f63616c0000ff80010b5f746f7563682d61626c65045f746370056c6f63616c0000ff80010e5f6d6564696172656d6f74657476045f746370056c6f63616c0000ff8001085f616972706c6179045f746370056c6f63616c0000ff8001)
2020-04-17 00:09:00 DEBUG (MainThread) [custom_components.apple_tv] Failed to find device 93B23502-4B77-4795-ADC4-D0016032545E with address 192.168.8.184, trying to scan
2020-04-17 00:09:00 DEBUG (MainThread) [pyatv] Discovering devices for 5 seconds
2020-04-17 00:09:01 DEBUG (MainThread) [pyatv] Auto-discovered Bedroom at 192.168.8.65:7000 (Protocol.AirPlay)
2020-04-17 00:09:05 DEBUG (MainThread) [custom_components.apple_tv] Updating state: connected=False, disconnected=False
2020-04-17 00:09:05 DEBUG (MainThread) [custom_components.apple_tv] Failed to find device 93B23502-4B77-4795-ADC4-D0016032545E, trying later
2020-04-17 00:09:05 DEBUG (MainThread) [custom_components.apple_tv] Reconnecting in 1 seconds
2020-04-17 00:09:06 DEBUG (MainThread) [custom_components.apple_tv] Updating state: connected=False, disconnected=False
2020-04-17 00:09:06 DEBUG (MainThread) [pyatv.support.udns] Sending DNS request to 192.168.8.184 (Data=35ff012000040000000000000b5f6170706c6574762d7632045f746370056c6f63616c0000ff80010b5f746f7563682d61626c65045f746370056c6f63616c0000ff80010e5f6d6564696172656d6f74657476045f746370056c6f63616c0000ff8001085f616972706c6179045f746370056c6f63616c0000ff8001)
2020-04-17 00:09:11 DEBUG (MainThread) [custom_components.apple_tv] Failed to find device 93B23502-4B77-4795-ADC4-D0016032545E with address 192.168.8.184, trying to scan
2020-04-17 00:09:11 DEBUG (MainThread) [pyatv] Discovering devices for 5 seconds
2020-04-17 00:09:12 DEBUG (MainThread) [pyatv] Auto-discovered Bedroom at 192.168.8.65:7000 (Protocol.AirPlay)
2020-04-17 00:09:16 DEBUG (MainThread) [custom_components.apple_tv] Updating state: connected=False, disconnected=False
2020-04-17 00:09:16 DEBUG (MainThread) [custom_components.apple_tv] Failed to find device 93B23502-4B77-4795-ADC4-D0016032545E, trying later
2020-04-17 00:09:16 DEBUG (MainThread) [custom_components.apple_tv] Reconnecting in 3 seconds
2020-04-17 00:09:19 DEBUG (MainThread) [custom_components.apple_tv] Updating state: connected=False, disconnected=False
2020-04-17 00:09:19 DEBUG (MainThread) [pyatv.support.udns] Sending DNS request to 192.168.8.184 (Data=35ff012000040000000000000b5f6170706c6574762d7632045f746370056c6f63616c0000ff80010b5f746f7563682d61626c65045f746370056c6f63616c0000ff80010e5f6d6564696172656d6f74657476045f746370056c6f63616c0000ff8001085f616972706c6179045f746370056c6f63616c0000ff8001)
2020-04-17 00:09:24 DEBUG (MainThread) [custom_components.apple_tv] Failed to find device 93B23502-4B77-4795-ADC4-D0016032545E with address 192.168.8.184, trying to scan
2020-04-17 00:09:24 DEBUG (MainThread) [pyatv] Discovering devices for 5 seconds
2020-04-17 00:09:25 DEBUG (MainThread) [pyatv] Auto-discovered Bedroom at 192.168.8.65:7000 (Protocol.AirPlay)
2020-04-17 00:09:29 DEBUG (MainThread) [custom_components.apple_tv] Updating state: connected=False, disconnected=False

PS - the device the component ends up auto-discovering titled "Bedroom" is my airplay-enable Sonos speaker.

postlund commented 4 years ago

Another issue seems to have arisen (I am not sure if this is related), but when I restarted my Home Assistant instance, upon start up the Apple TV showed it was in the "Paused" state, even though the Apple TV is completely turned off.

Powered off is a fuzzy concept here because the device can appear to be turned off (no white light or image output), but still have power and an IP connection. In that case it can report what ever it feels like. My Apple TV sometimes reports that the music app is active and a song is paused, even though it is "off". Best would be if you check the Remote app on your phone and see what that is reporting.

2020-04-17 00:08:50 DEBUG (MainThread) [custom_components.apple_tv] Disconnecting from device
2020-04-17 00:08:50 DEBUG (MainThread) [custom_components.apple_tv] Updating state: connected=False, disconnected=False
2020-04-17 00:08:50 DEBUG (MainThread) [pyatv.mrp.connection] Disconnected from device: None
2020-04-17 00:08:50 DEBUG (MainThread) [custom_components.apple_tv] Updating state: connected=False, disconnected=True
2020-04-17 00:08:50 DEBUG (MainThread) [custom_components.apple_tv] Not starting connect loop (True, False)
2020-04-17 00:08:55 DEBUG (MainThread) [custom_components.apple_tv] Starting connect loop
2020-04-17 00:08:55 DEBUG (MainThread) [custom_components.apple_tv] Updating state: connected=False, disconnected=False
2020-04-17 00:08:55 DEBUG (MainThread) [pyatv.support.udns] Sending DNS request to 192.168.8.184 (Data=35ff012000040000000000000b5f6170706c6574762d7632045f746370056c6f63616c0000ff80010b5f746f7563682d61626c65045f746370056c6f63616c0000ff80010e5f6d6564696172656d6f74657476045f746370056c6f63616c0000ff8001085f616972706c6179045f746370056c6f63616c0000ff8001)
2020-04-17 00:09:00 DEBUG (MainThread) [custom_components.apple_tv] Failed to find device 93B23502-4B77-4795-ADC4-D0016032545E with address 192.168.8.184, trying to scan
2020-04-17 00:09:00 DEBUG (MainThread) [pyatv] Discovering devices for 5 seconds
2020-04-17 00:09:01 DEBUG (MainThread) [pyatv] Auto-discovered Bedroom at 192.168.8.65:7000 (Protocol.AirPlay)
2020-04-17 00:09:05 DEBUG (MainThread) [custom_components.apple_tv] Updating state: connected=False, disconnected=False
2020-04-17 00:09:05 DEBUG (MainThread) [custom_components.apple_tv] Failed to find device 93B23502-4B77-4795-ADC4-D0016032545E, trying later
2020-04-17 00:09:05 DEBUG (MainThread) [custom_components.apple_tv] Reconnecting in 1 seconds
2020-04-17 00:09:06 DEBUG (MainThread) [custom_components.apple_tv] Updating state: connected=False, disconnected=False
2020-04-17 00:09:06 DEBUG (MainThread) [pyatv.support.udns] Sending DNS request to 192.168.8.184 (Data=35ff012000040000000000000b5f6170706c6574762d7632045f746370056c6f63616c0000ff80010b5f746f7563682d61626c65045f746370056c6f63616c0000ff80010e5f6d6564696172656d6f74657476045f746370056c6f63616c0000ff8001085f616972706c6179045f746370056c6f63616c0000ff8001)
2020-04-17 00:09:11 DEBUG (MainThread) [custom_components.apple_tv] Failed to find device 93B23502-4B77-4795-ADC4-D0016032545E with address 192.168.8.184, trying to scan
2020-04-17 00:09:11 DEBUG (MainThread) [pyatv] Discovering devices for 5 seconds
2020-04-17 00:09:12 DEBUG (MainThread) [pyatv] Auto-discovered Bedroom at 192.168.8.65:7000 (Protocol.AirPlay)
2020-04-17 00:09:16 DEBUG (MainThread) [custom_components.apple_tv] Updating state: connected=False, disconnected=False
2020-04-17 00:09:16 DEBUG (MainThread) [custom_components.apple_tv] Failed to find device 93B23502-4B77-4795-ADC4-D0016032545E, trying later
2020-04-17 00:09:16 DEBUG (MainThread) [custom_components.apple_tv] Reconnecting in 3 seconds
2020-04-17 00:09:19 DEBUG (MainThread) [custom_components.apple_tv] Updating state: connected=False, disconnected=False
2020-04-17 00:09:19 DEBUG (MainThread) [pyatv.support.udns] Sending DNS request to 192.168.8.184 (Data=35ff012000040000000000000b5f6170706c6574762d7632045f746370056c6f63616c0000ff80010b5f746f7563682d61626c65045f746370056c6f63616c0000ff80010e5f6d6564696172656d6f74657476045f746370056c6f63616c0000ff8001085f616972706c6179045f746370056c6f63616c0000ff8001)
2020-04-17 00:09:24 DEBUG (MainThread) [custom_components.apple_tv] Failed to find device 93B23502-4B77-4795-ADC4-D0016032545E with address 192.168.8.184, trying to scan
2020-04-17 00:09:24 DEBUG (MainThread) [pyatv] Discovering devices for 5 seconds
2020-04-17 00:09:25 DEBUG (MainThread) [pyatv] Auto-discovered Bedroom at 192.168.8.65:7000 (Protocol.AirPlay)
2020-04-17 00:09:29 DEBUG (MainThread) [custom_components.apple_tv] Updating state: connected=False, disconnected=False

Yep, definitely a connect loop due to sleep here. I'm working on a "fix" for this, but it is again very tricky. I think I will have to do a proper write-up about power management and figure out a good approach to that. But lets leave it at "it's not as easy as it seems".

PS - the device the component ends up auto-discovering titled "Bedroom" is my airplay-enable Sonos speaker.

It will be visible in the debug logs but it should hopefully not appear in the dialog where you add devices I hope? That was something I fixed in 0.5.0.

postlund commented 4 years ago

I just pushed a new update that should hopefully make this better. Hopefully the device should end up in idle state.

jasr1 commented 4 years ago

Hey, just updated the integration but now I am getting an error that makes the state 'Unavailable'. Here are the logs:

2020-04-28 08:43:27 ERROR (MainThread) [homeassistant.setup] Setup failed for apple_tv: unknown error Traceback (most recent call last): File "/usr/src/homeassistant/homeassistant/setup.py", line 137, in _async_setup_component component = integration.get_component() File "/usr/src/homeassistant/homeassistant/loader.py", line 268, in get_component cache[self.domain] = importlib.import_module(self.pkg_path) File "/usr/local/lib/python3.7/importlib/__init__.py", line 127, in import_module return _bootstrap._gcd_import(name[level:], package, level) File "<frozen importlib._bootstrap>", line 1006, in _gcd_import File "<frozen importlib._bootstrap>", line 983, in _find_and_load File "<frozen importlib._bootstrap>", line 967, in _find_and_load_unlocked File "<frozen importlib._bootstrap>", line 677, in _load_unlocked File "<frozen importlib._bootstrap_external>", line 728, in exec_module File "<frozen importlib._bootstrap>", line 219, in _call_with_frames_removed File "/config/custom_components/apple_tv/__init__.py", line 8, in <module> from pyatv import connect, exceptions, scan File "/usr/local/lib/python3.7/site-packages/pyatv/__init__.py", line 20, in <module> from pyatv.mrp import MrpAppleTV File "/usr/local/lib/python3.7/site-packages/pyatv/mrp/__init__.py", line 25, in <module> from pyatv.mrp import messages, protobuf File "/usr/local/lib/python3.7/site-packages/pyatv/mrp/messages.py", line 140, in <module> identifier, send_error=protobuf.SendCommandResultMessage.SendError.NoError AttributeError: 'EnumTypeWrapper' object has no attribute 'NoError'

postlund commented 4 years ago

Same as in #623, just pushed a fix for it.

jasr1 commented 4 years ago

Thanks, just updated and the re-connect loop is not happening!

However, there is one issue that has arisen (I do not know if it is related to this issue or not). After a restart, the Apple TV state remains idle even if there is something playing or paused on the device. To get the proper state, I have to turn off the Apple TV (from HA), and then turn it back on. Unfortunately, nothing shows up in the logs about this. Any other way I can help you resolve this issue?

postlund commented 4 years ago

Yeah, this is an issue other people see as well. I don't really know what the problem is or how to solve it. But if you can provide some logs, that would be great. Log diversity might be a good thing here.

postlund commented 4 years ago

Can you possibly try with the latest update I just pushed to the component?

swenox commented 4 years ago

I have the same problem running the latest version. Apple tv is often unavailable and HA is stuck in a reconnect loop. No "key press" working from HA. From my iphone remote everything works fine.

postlund commented 4 years ago

@swenox Can you provide some logs from the re-connect loop? I suspect something "bad" happens which leads to a disconnect. But then scanning fails so the connection is never restored because of that.

swenox commented 4 years ago

@postlund I will try to get a log as soon as i have figured out how to. :)

postlund commented 4 years ago

@swenox Right here 😉

swenox commented 4 years ago

@postlund Here is a log. Is this what youre looking for? 😊 

2020-07-28 22:40:15 ERROR (MainThread) [custom_components.apple_tv] Failed to connect
Traceback (most recent call last):
  File "/config/custom_components/apple_tv/__init__.py", line 227, in _connect_loop
    await self._connect(conf)
  File "/config/custom_components/apple_tv/__init__.py", line 317, in _connect
    self.atv = await connect(conf, self.hass.loop, session=session)
  File "/usr/local/lib/python3.8/site-packages/pyatv/__init__.py", line 76, in connect
    await atv.connect()
  File "/usr/local/lib/python3.8/site-packages/pyatv/mrp/__init__.py", line 704, in connect
    await self._protocol.start()
  File "/usr/local/lib/python3.8/site-packages/pyatv/mrp/protocol.py", line 66, in start
    self.device_info = await self.send_and_receive(msg)
  File "/usr/local/lib/python3.8/site-packages/pyatv/mrp/protocol.py", line 138, in send_and_receive
    return await self._receive(identifier, timeout)
  File "/usr/local/lib/python3.8/site-packages/pyatv/mrp/protocol.py", line 146, in _receive
    await asyncio.wait_for(semaphore.acquire(), timeout)
  File "/usr/local/lib/python3.8/asyncio/tasks.py", line 490, in wait_for
    raise exceptions.TimeoutError()
asyncio.exceptions.TimeoutError
2020-07-28 22:40:33 WARNING (MainThread) [homeassistant.loader] You are using a custom integration for simpleicons which has not been tested by Home Assistant. This component might cause stability problems, be sure to disable it if you experience issues with Home Assistant.
2020-07-28 22:41:18 ERROR (MainThread) [custom_components.apple_tv] Failed to connect
Traceback (most recent call last):
  File "/config/custom_components/apple_tv/__init__.py", line 227, in _connect_loop
    await self._connect(conf)
  File "/config/custom_components/apple_tv/__init__.py", line 317, in _connect
    self.atv = await connect(conf, self.hass.loop, session=session)
  File "/usr/local/lib/python3.8/site-packages/pyatv/__init__.py", line 76, in connect
    await atv.connect()
  File "/usr/local/lib/python3.8/site-packages/pyatv/mrp/__init__.py", line 704, in connect
    await self._protocol.start()
  File "/usr/local/lib/python3.8/site-packages/pyatv/mrp/protocol.py", line 66, in start
    self.device_info = await self.send_and_receive(msg)
  File "/usr/local/lib/python3.8/site-packages/pyatv/mrp/protocol.py", line 138, in send_and_receive
    return await self._receive(identifier, timeout)
  File "/usr/local/lib/python3.8/site-packages/pyatv/mrp/protocol.py", line 146, in _receive
    await asyncio.wait_for(semaphore.acquire(), timeout)
  File "/usr/local/lib/python3.8/asyncio/tasks.py", line 490, in wait_for
    raise exceptions.TimeoutError()
asyncio.exceptions.TimeoutError
2020-07-28 22:41:54 ERROR (MainThread) [custom_components.apple_tv] Failed to connect
Traceback (most recent call last):
  File "/config/custom_components/apple_tv/__init__.py", line 227, in _connect_loop
    await self._connect(conf)
  File "/config/custom_components/apple_tv/__init__.py", line 317, in _connect
    self.atv = await connect(conf, self.hass.loop, session=session)
  File "/usr/local/lib/python3.8/site-packages/pyatv/__init__.py", line 76, in connect
    await atv.connect()
  File "/usr/local/lib/python3.8/site-packages/pyatv/mrp/__init__.py", line 704, in connect
    await self._protocol.start()
  File "/usr/local/lib/python3.8/site-packages/pyatv/mrp/protocol.py", line 66, in start
    self.device_info = await self.send_and_receive(msg)
  File "/usr/local/lib/python3.8/site-packages/pyatv/mrp/protocol.py", line 138, in send_and_receive
    return await self._receive(identifier, timeout)
  File "/usr/local/lib/python3.8/site-packages/pyatv/mrp/protocol.py", line 146, in _receive
    await asyncio.wait_for(semaphore.acquire(), timeout)
  File "/usr/local/lib/python3.8/asyncio/tasks.py", line 490, in wait_for
    raise exceptions.TimeoutError()
asyncio.exceptions.TimeoutError
2020-07-28 22:42:50 ERROR (MainThread) [custom_components.apple_tv] Failed to connect
Traceback (most recent call last):
  File "/config/custom_components/apple_tv/__init__.py", line 227, in _connect_loop
    await self._connect(conf)
  File "/config/custom_components/apple_tv/__init__.py", line 317, in _connect
    self.atv = await connect(conf, self.hass.loop, session=session)
  File "/usr/local/lib/python3.8/site-packages/pyatv/__init__.py", line 76, in connect
    await atv.connect()
  File "/usr/local/lib/python3.8/site-packages/pyatv/mrp/__init__.py", line 704, in connect
    await self._protocol.start()
  File "/usr/local/lib/python3.8/site-packages/pyatv/mrp/protocol.py", line 66, in start
    self.device_info = await self.send_and_receive(msg)
  File "/usr/local/lib/python3.8/site-packages/pyatv/mrp/protocol.py", line 138, in send_and_receive
    return await self._receive(identifier, timeout)
  File "/usr/local/lib/python3.8/site-packages/pyatv/mrp/protocol.py", line 146, in _receive
    await asyncio.wait_for(semaphore.acquire(), timeout)
  File "/usr/local/lib/python3.8/asyncio/tasks.py", line 490, in wait_for
    raise exceptions.TimeoutError()
asyncio.exceptions.TimeoutError
2020-07-28 22:46:57 ERROR (MainThread) [custom_components.apple_tv] Failed to connect
Traceback (most recent call last):
  File "/config/custom_components/apple_tv/__init__.py", line 227, in _connect_loop
    await self._connect(conf)
  File "/config/custom_components/apple_tv/__init__.py", line 317, in _connect
    self.atv = await connect(conf, self.hass.loop, session=session)
  File "/usr/local/lib/python3.8/site-packages/pyatv/__init__.py", line 76, in connect
    await atv.connect()
  File "/usr/local/lib/python3.8/site-packages/pyatv/mrp/__init__.py", line 704, in connect
    await self._protocol.start()
  File "/usr/local/lib/python3.8/site-packages/pyatv/mrp/protocol.py", line 66, in start
    self.device_info = await self.send_and_receive(msg)
  File "/usr/local/lib/python3.8/site-packages/pyatv/mrp/protocol.py", line 138, in send_and_receive
    return await self._receive(identifier, timeout)
  File "/usr/local/lib/python3.8/site-packages/pyatv/mrp/protocol.py", line 146, in _receive
    await asyncio.wait_for(semaphore.acquire(), timeout)
  File "/usr/local/lib/python3.8/asyncio/tasks.py", line 490, in wait_for
    raise exceptions.TimeoutError()
asyncio.exceptions.TimeoutError
postlund commented 4 years ago

@swenox Sorry about the delay. But yes, that's what I'm after. Very peculiar issue I must say. Can you start by testing with the latest updated component and see if the same re-connect loop happens?

swenox commented 4 years ago

@postlund I will try to update. I have been ignoring this issue for a while now and today i checked and HA havent seen my apple tv in 3 weeks. (It's on every day) I'll get back to you with results after the update.

swenox commented 4 years ago

@postlund Im now running the latest version of HA and appletv addon and it's still not working. Status is mostly unknown and HA cant find the apple tv even when it's on and playing something. This is really strange.

MarcHagen commented 3 years ago

Just "dumping" my debug here. Maybe it's usefull. tvOS 14.3

Log output ```batch homeassistant.log 2021-01-01 22:11:22 DEBUG (MainThread) [custom_components.apple_tv] Starting connect loop 2021-01-01 22:11:22 DEBUG (MainThread) [custom_components.apple_tv] Updating state: connected=False, disconnected=False 2021-01-01 22:11:22 DEBUG (SyncWorker_2) [pyatv.support.knock] Knocking at port 3689 on 10.10.1.9 2021-01-01 22:11:22 DEBUG (SyncWorker_4) [pyatv.support.knock] Knocking at port 7000 on 10.10.1.9 2021-01-01 22:11:22 DEBUG (SyncWorker_0) [pyatv.support.knock] Knocking at port 49152 on 10.10.1.9 2021-01-01 22:11:22 DEBUG (SyncWorker_3) [pyatv.support.knock] Knocking at port 32498 on 10.10.1.9 2021-01-01 22:11:22 DEBUG (MainThread) [pyatv.support.mdns] Cleaning up after UDNS request 2021-01-01 22:11:22 DEBUG (MainThread) [pyatv.support.mdns] Cleaning up after UDNS request 2021-01-01 22:11:22 DEBUG (MainThread) [pyatv.support.mdns] Cleaning up after UDNS request 2021-01-01 22:11:22 DEBUG (MainThread) [pyatv.support.scan] Auto-discovered Woonkamer at 10.10.1.9:49153 (Protocol.MRP) 2021-01-01 22:11:22 DEBUG (MainThread) [pyatv.support.scan] Auto-discovered Woonkamer at 10.10.1.9:7000 (Protocol.AirPlay) 2021-01-01 22:11:22 DEBUG (MainThread) [custom_components.apple_tv] Updating state: connected=False, disconnected=False 2021-01-01 22:11:22 DEBUG (MainThread) [pyatv.airplay] Loaded AirPlay credentials: : 2021-01-01 22:11:22 DEBUG (MainThread) [pyatv.mrp.connection] Connection made to device 2021-01-01 22:11:22 DEBUG (MainThread) [pyatv.support.net] Configured keep-alive on (Linux) 2021-01-01 22:11:22 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:43168<->10.10.1.9:49153 Connection established 2021-01-01 22:11:22 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:43168<->10.10.1.9:49153 >> Send (Data=080f122434313434463138462d364644432d344337432d414439392d3237383836413143384139422000a20183010a2435666131383837632d353236632d343331382d616463632d633334613731663836396531120570796174761a066950686f6e6522063138413339332a12636f6d2e6170706c652e545652656d6f746532063334342e32383801404d480150016211636f6d2e6170706c652e54564d75736963680170017801880102a80101b00101) 2021-01-01 22:11:22 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:43168<->10.10.1.9:49153 >> Send: Protobuf: type: DEVICE_INFO_MESSAGE identifier: "4144F18F-6FDC-4C7C-AD99-27886A1C8A9B" errorCode: NoError [deviceInfoMessage] { uniqueIdentifier: "5fa1887c-526c-4318-adcc-c34a71f869e1" name: "pyatv" localizedModelName: "iPhone" systemBuildVersion: "18A393" applicationBundleIdentifier: "com.apple.TVRemote" applicationBundleVersion: "344.28" protocolVersion: 1 lastSupportedMessageType: 77 supportsSystemPairing: true allowsPairing: true systemMediaApplication: "com.apple.TVMusic" supportsACL: true supportsSharedQueue: true supportsExtendedMotion: true sharedQueueVersion: 2 deviceClass: iPhone logicalDeviceCount: 1 } 2021-01-01 22:11:22 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:43168<->10.10.1.9:49153 << Receive (Data=a103080f122434313434463138462d364644432d344337432d414439392d3237383836413143384139422000a201cc020a2431343732334241372d373545442d344642352d383638302d4131343533393735373843431209576f6f6e6b616d65721a094170706c65c2a05456220631384b3536312a16636f6d2e6170706c652e6d6564696172656d6f7465643801406c480150016211636f6d2e6170706c652e54564d757369636801700178018801029a012431343732334241372d373545442d344642352d383638302d413134353339373537384343a2011136633a34613a38353a32363a64393a6462a80104b00100c00100d20124363744373831463...) 2021-01-01 22:11:22 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:43168<->10.10.1.9:49153 << Receive: Protobuf: type: DEVICE_INFO_MESSAGE identifier: "4144F18F-6FDC-4C7C-AD99-27886A1C8A9B" errorCode: NoError [deviceInfoMessage] { uniqueIdentifier: "14723BA7-75ED-4FB5-8680-A145397578CC" name: "Woonkamer" localizedModelName: "Apple\302\240TV" systemBuildVersion: "18K561" applicationBundleIdentifier: "com.apple.mediaremoted" protocolVersion: 1 lastSupportedMessageType: 108 supportsSystemPairing: true allowsPairing: true systemMediaApplication: "com.apple.TVMusic" supportsACL: true supportsSharedQueue: true supportsExtendedMotion: true sharedQueueVersion: 2 deviceUID: "14723BA7-75ED-4FB5-8680-A145397578CC" managedConfigDeviceID: "6c:4a:85:26:d9:db" deviceClass: AppleTV logicalDeviceCount: 0 isProxyGroupPlayer: false groupUID: "67D781F8-D87E-4606-BF91-54BDF698FB5E" isGroupLeader: true isAirplayActive: false systemPodcastApplication: "com.apple.podcasts" enderDefaultGroupUID: "67D781F8-D87E-4606-BF91-54BDF698FB5E" airplayReceivers: "TVAirPlay" 37: 0 38: 1 39: "AppleTV6,2" } 85: "B9ABFC94-5297-45DF-A1AD-1D85849F1B62" 2021-01-01 22:11:22 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:43168<->10.10.1.9:49153 >> Send (Data=08222000ba022f0a250601010320877a6c8e0d9d4f8684284da92fa81d1f4206df92d9d7e22e5486dfab29a9d8511000180020002800) 2021-01-01 22:11:22 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:43168<->10.10.1.9:49153 >> Send: Protobuf: type: CRYPTO_PAIRING_MESSAGE errorCode: NoError [cryptoPairingMessage] { pairingData: "\006\001\001\003 \207zl\216\r\235O\206\204(M\251/\250\035\037B\006\337\222\331\327\342.T\206\337\253)\251\330Q" status: 0 isRetrying: false isUsingSystemPairing: false state: 0 } 2021-01-01 22:11:22 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:43168<->10.10.1.9:49153 << Receive (Data=d90108222000ba02aa010a9f01057818703a26e5604839cce1bcc903549013a624a3b1af2b305389dff35210dac46a6580681247b9581570161a49f756ce67b4ed0f676e90bd962fb1446c733c0d8214bac18f941a4262ab8b5e781556fffb423d67db24548ff1da87f1b959d187c955d56d84cbbaaa2c5400ea8da250db80892c88b60b5d25e806010203207ecc444ab6f90c32e757904805b465771932a14d0f07dbf263b97680c38b825e1000180020002800aa052443464538443744302d363235442d343531352d394131392d323245454238464339344331) 2021-01-01 22:11:22 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:43168<->10.10.1.9:49153 << Receive: Protobuf: type: CRYPTO_PAIRING_MESSAGE errorCode: NoError [cryptoPairingMessage] { pairingData: "\005x\030p:&\345`H9\314\341\274\311\003T\220\023\246$\243\261\257+0S\211\337\363R\020\332\304je\200h\022G\271X\025p\026\032I\367V\3... status: 0 isRetrying: false isUsingSystemPairing: false state: 0 } 85: "CFE8D7D0-625D-4515-9A19-22EEB8FC94C1" 2021-01-01 22:11:22 DEBUG (MainThread) [pyatv.mrp.auth] Device (Encrypted=18703a26e5604839cce1bcc903549013a624a3b1af2b305389dff35210dac46a6580681247b9581570161a49f756ce67b4ed0f676e90bd962fb1446c733c0d8214bac18f941a4262ab8b5e781556fffb423d67db24548ff1da87f1b959d187c955d56d84cbbaaa2c5400ea8da250db80892c88b60b5d25e8, Public=cee7c5a7471183819b71c56d770446279d02ebd0530e0a4ebaae657ae3d2175f) 2021-01-01 22:11:22 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:43168<->10.10.1.9:49153 >> Send (Data=08222000ba0287010a7d060103057887fa0f88aaa741d90354ed743fcf67560461ecedb5b98d5edfabc905198d7b9e4a35b8c901f4eda8704793cb992547066cef6711ab03000e1577fdd271cd165f8093435188c6d2f319107f90bf794c47bcaba793ba32d8f16adc4d58ef16151c69e441720abe48a25ecec738a0b729d76550f29fae2a34dc1000180020002800) 2021-01-01 22:11:22 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:43168<->10.10.1.9:49153 >> Send: Protobuf: type: CRYPTO_PAIRING_MESSAGE errorCode: NoError [cryptoPairingMessage] { pairingData: "\006\001\003\005x\207\372\017\210\252\247A\331\003T\355t?\317gV\004a\354\355\265\271\215^\337\253\311\005\031\215{\236J5\270\311\00... status: 0 isRetrying: false isUsingSystemPairing: false state: 0 } 2021-01-01 22:11:22 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:43168<->10.10.1.9:49153 << Receive (Data=3e08222000ba02100a060701020601041000180020002800aa052446334144463843322d453232372d344541392d383538462d413437434642324241413633) 2021-01-01 22:11:22 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:43168<->10.10.1.9:49153 << Receive: Protobuf: type: CRYPTO_PAIRING_MESSAGE errorCode: NoError [cryptoPairingMessage] { pairingData: "\007\001\002\006\001\004" status: 0 isRetrying: false isUsingSystemPairing: false state: 0 } 85: "F3ADF8C2-E227-4EA9-858F-A47CFB2BAA63" 2021-01-01 22:11:22 DEBUG (MainThread) [pyatv.mrp.srp] Keys (Input=0676ecd33cff0a72f3410eb3691ca3369ca31878cdbbc4a1ae8527110010a114, Output=6d8136b8e528ee938b21afbd471c26774987a04d1e82dfa8578b70cca1e92e96) 2021-01-01 22:11:22 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:43168<->10.10.1.9:49153 >> Send (Data=08262000d202020802) 2021-01-01 22:11:22 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:43168<->10.10.1.9:49153 >> Send (Encrypted=220b700121b53dd98180c0769360b877a9d20204af64799d10) 2021-01-01 22:11:22 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:43168<->10.10.1.9:49153 >> Send: Protobuf: type: SET_CONNECTION_STATE_MESSAGE errorCode: NoError [setConnectionStateMessage] { state: Connected } 2021-01-01 22:11:22 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:43168<->10.10.1.9:49153 >> Send (Data=0810122438424638303633312d323641312d343734362d414633352d3843313838324638373135442000aa010a08011000180120012800) 2021-01-01 22:11:22 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:43168<->10.10.1.9:49153 >> Send (Encrypted=bb8b4934b0a37a59251e8bbbe3fc323afb051cc3f7edde3199a79588ee505fae601e159ec488357dca1c200e7df407251b1ada02f8cc76f0492ed7dac4b2fda7015c3122ff8584) 2021-01-01 22:11:22 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:43168<->10.10.1.9:49153 >> Send: Protobuf: type: CLIENT_UPDATES_CONFIG_MESSAGE identifier: "8BF80631-26A1-4746-AF35-8C1882F8715D" errorCode: NoError [clientUpdatesConfigMessage] { artworkUpdates: true nowPlayingUpdates: false volumeUpdates: true keyboardUpdates: true outputDeviceUpdates: false } 2021-01-01 22:11:22 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:43168<->10.10.1.9:49153 Disconnected from device: [Errno 104] Connection reset by peer 2021-01-01 22:11:27 ERROR (MainThread) [custom_components.apple_tv] Failed to connect Traceback (most recent call last): File "/config/custom_components/apple_tv/__init__.py", line 227, in _connect_loop await self._connect(conf) File "/config/custom_components/apple_tv/__init__.py", line 317, in _connect self.atv = await connect(conf, self.hass.loop, session=session) File "/usr/local/lib/python3.8/site-packages/pyatv/__init__.py", line 76, in connect await atv.connect() File "/usr/local/lib/python3.8/site-packages/pyatv/mrp/__init__.py", line 704, in connect await self._protocol.start() File "/usr/local/lib/python3.8/site-packages/pyatv/mrp/protocol.py", line 81, in start await self.send_and_receive(messages.client_updates_config()) File "/usr/local/lib/python3.8/site-packages/pyatv/mrp/protocol.py", line 138, in send_and_receive return await self._receive(identifier, timeout) File "/usr/local/lib/python3.8/site-packages/pyatv/mrp/protocol.py", line 146, in _receive await asyncio.wait_for(semaphore.acquire(), timeout) File "/usr/local/lib/python3.8/asyncio/tasks.py", line 498, in wait_for raise exceptions.TimeoutError() asyncio.exceptions.TimeoutError 2021-01-01 22:11:27 DEBUG (MainThread) [custom_components.apple_tv] Reconnecting in 1 seconds ```
HA Info ## System Health version | 2020.12.2 -- | -- installation_type | Home Assistant OS dev | false hassio | true docker | true virtualenv | false python_version | 3.8.6 os_name | Linux os_version | 5.4.84 arch | x86_64 timezone | Europe/Amsterdam
Home Assistant Community Store GitHub API | ok -- | -- Github API Calls Remaining | 4712 Installed Version | 1.9.0 Stage | running Available Repositories | 711 Installed Repositories | 19
Home Assistant Supervisor host_os | Home Assistant OS 5.9 -- | -- update_channel | stable supervisor_version | 2020.12.7 docker_version | 19.03.13 disk_total | 19.0 GB disk_used | 10.6 GB healthy | true supported | true board | ova supervisor_api | ok version_api | ok installed_addons | Terminal & SSH (8.10.0), TasmoAdmin (0.13.1), ESPHome (1.15.3), Telegraf (0.5.4), Mosquitto broker (5.1), File editor (5.2.0), Check Home Assistant configuration (3.6.0), SSH & Web Terminal (7.8.0)
Lovelace dashboards | 2 -- | -- mode | storage views | 6 resources | 13

Edit: make it smaller :)

postlund commented 3 years ago

It would be great if anyone of you in this issue could retry with latest version of Home Assistant and let me know what happens. No need for the custom component anymore.

MarcHagen commented 3 years ago

@postlund

It would be great if anyone of you in this issue could retry with latest version of Home Assistant and let me know what happens. No need for the custom component anymore.

Still issues...

HA Info ## System Health version | core-2021.2.3 -- | -- installation_type | Home Assistant OS dev | false hassio | true docker | true virtualenv | false python_version | 3.8.7 os_name | Linux os_version | 5.4.99 arch | x86_64 timezone | Europe/Amsterdam
Home Assistant Community Store GitHub API | ok -- | -- Github API Calls Remaining | 4983 Installed Version | 1.11.3 Stage | running Available Repositories | 757 Installed Repositories | 18
Home Assistant Supervisor host_os | Home Assistant OS 5.12 -- | -- update_channel | stable supervisor_version | supervisor-2021.02.11 docker_version | 19.03.13 disk_total | 19.0 GB disk_used | 11.3 GB healthy | true supported | true board | ova supervisor_api | ok version_api | ok installed_addons | TasmoAdmin (0.14.0), ESPHome (1.16.2), Telegraf (0.5.6), Mosquitto broker (5.1.1), File editor (5.2.0), Check Home Assistant configuration (3.6.0), SSH & Web Terminal (8.0.3)
Lovelace dashboards | 2 -- | -- resources | 13 views | 7 mode | storage
Log output ```log 2021-03-02 23:23:40 DEBUG (MainThread) [pyatv.support.knock] Knocking at ports [3689, 7000, 49152, 32498] on 10.10.1.9 2021-03-02 23:23:40 DEBUG (MainThread) [pyatv.support.scan] Auto-discovered Woonkamer at 10.10.1.9:7000 (Protocol.AirPlay) 2021-03-02 23:23:40 DEBUG (MainThread) [pyatv.support.scan] Auto-discovered Woonkamer at 10.10.1.9:49244 (Protocol.MRP) 2021-03-02 23:23:40 DEBUG (MainThread) [pyatv.airplay] Loaded AirPlay credentials: 92BB9CFD8CA43653:46F646EC37A9094057620DE2A9439CCEEAEEC0796BE33A77946E503F4A481A10 2021-03-02 23:23:40 DEBUG (MainThread) [pyatv.mrp.connection] Connection made to device 2021-03-02 23:23:40 DEBUG (MainThread) [pyatv.support.net] Configured keep-alive on (Linux) 2021-03-02 23:23:40 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:49966<->10.10.1.9:49244 Connection established 2021-03-02 23:23:40 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:49966<->10.10.1.9:49244 >> Send (Data=080f122438364643374434312d463439422d344341352d393933422d4232383841323333333834372000a20183010a2435666131383837632d353236632d343331382d616463632d633334613731663836396531120570796174761a066950686f6e6522063138413339332a12636f6d2e6170706c652e545652656d6f746532063334342e32383801406c480150016211636f6d2e6170706c652e54564d75736963680170017801880102a80101b00101) 2021-03-02 23:23:40 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:49966<->10.10.1.9:49244 >> Send: Protobuf: type: DEVICE_INFO_MESSAGE identifier: "86FC7D41-F49B-4CA5-993B-B288A2333847" errorCode: NoError [deviceInfoMessage] { uniqueIdentifier: "5fa1887c-526c-4318-adcc-c34a71f869e1" 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-03-02 23:23:40 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:49966<->10.10.1.9:49244 << Receive (Data=aa03080f122438364643374434312d463439422d344341352d393933422d4232383841323333333834372000a201d5020a2431343732334241372d373545442d344642352d383638302d4131343533393735373843431209576f6f6e6b616d65721a094170706c65c2a05456220631384b3830322a16636f6d2e6170706c652e6d6564696172656d6f7465643801406c480150016211636f6d2e6170706c652e54564d757369636801700178018201066c4a852621d98801029a012431343732334241372d373545442d344642352d383638302d413134353339373537384343a2011136633a34613a38353a32363a64393a6462a80104b00101c00100d20...) 2021-03-02 23:23:40 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:49966<->10.10.1.9:49244 << Receive: Protobuf: type: DEVICE_INFO_MESSAGE identifier: "86FC7D41-F49B-4CA5-993B-B288A2333847" errorCode: NoError [deviceInfoMessage] { uniqueIdentifier: "14723BA7-75ED-4FB5-8680-A145397578CC" name: "Woonkamer" localizedModelName: "Apple\302\240TV" systemBuildVersion: "18K802" applicationBundleIdentifier: "com.apple.mediaremoted" protocolVersion: 1 lastSupportedMessageType: 108 supportsSystemPairing: true allowsPairing: true systemMediaApplication: "com.apple.TVMusic" supportsACL: true supportsSharedQueue: true supportsExtendedMotion: true bluetoothAddress: "lJ\205&!\331" sharedQueueVersion: 2 deviceUID: "14723BA7-75ED-4FB5-8680-A145397578CC" managedConfigDeviceID: "6c:4a:85:26:d9:db" deviceClass: AppleTV logicalDeviceCount: 1 isProxyGroupPlayer: false groupUID: "57504D0D-38C3-4EE9-A409-EC5450A83AD4" isGroupLeader: true isAirplayActive: false systemPodcastApplication: "com.apple.podcasts" enderDefaultGroupUID: "57504D0D-38C3-4EE9-A409-EC5450A83AD4" airplayReceivers: "TVAirPlay" clusterType: 0 isClusterAware: true modelID: "AppleTV6,2" } uniqueIdentifier: "BCC86DD3-ACB3-49CC-9369-1E8B93733A5F" 2021-03-02 23:23:40 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:49966<->10.10.1.9:49244 >> Send (Data=08222000ba022f0a250601010320b99fc28d33903c99621cfca995feb061180cc8e4c0b268e42b5f10cabf2ce43c1000180020002800) 2021-03-02 23:23:40 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:49966<->10.10.1.9:49244 >> Send: Protobuf: type: CRYPTO_PAIRING_MESSAGE errorCode: NoError [cryptoPairingMessage] { pairingData: "\006\001\001\003 \271\237\302\2153\220<\231b\034\374\251\225\376\260a\030\014\310\344\300\262h\344+_\020\312\277,\344<" status: 0 isRetrying: false isUsingSystemPairing: false state: 0 } 2021-03-02 23:23:40 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:49966<->10.10.1.9:49244 << Receive (Data=d90108222000ba02aa010a9f01057841eb1fad8c1a2f4615be1e49c3a1fed2b22a89206d7122803f6d0df948244a6d45563a5aaf6526648df58c20af8435cd0baea73ab2c3bb7a89875456cda506e71e2bf68c36578f36247a2e862f98f029a2dfdbedaa9766eceb11e6c264e4c0f0f65da5e25ae0a77f555d610669a30172f1150706754fbdec0601020320c8e839ffa87ec878bc44fa55f94283dad2484d0a3e4cbcec1df9d1adda6277731000180020002800aa052446354632423433462d383545382d343230462d413835452d323441413144323432413636) 2021-03-02 23:23:40 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:49966<->10.10.1.9:49244 << Receive: Protobuf: type: CRYPTO_PAIRING_MESSAGE errorCode: NoError [cryptoPairingMessage] { pairingData: "\005xA\353\037\255\214\032/F\025\276\036I\303\241\376\322\262*\211 mq\"\200?m\r\371H$JmEV:Z\257e&d\215\365\214 \257\2045\315\013\25... status: 0 isRetrying: false isUsingSystemPairing: false state: 0 } uniqueIdentifier: "F5F2B43F-85E8-420F-A85E-24AA1D242A66" 2021-03-02 23:23:40 DEBUG (MainThread) [pyatv.mrp.auth] Device (Encrypted=41eb1fad8c1a2f4615be1e49c3a1fed2b22a89206d7122803f6d0df948244a6d45563a5aaf6526648df58c20af8435cd0baea73ab2c3bb7a89875456cda506e71e2bf68c36578f36247a2e862f98f029a2dfdbedaa9766eceb11e6c264e4c0f0f65da5e25ae0a77f555d610669a30172f1150706754fbdec, Public=cee7c5a7471183819b71c56d770446279d02ebd0530e0a4ebaae657ae3d2175f) 2021-03-02 23:23:40 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:49966<->10.10.1.9:49244 >> Send (Data=08222000ba0287010a7d06010305788e6bbfd9167f16be03d577a813a1b8f4ecee6c71caebece0a1d766d65a17a6b82944bd9d88a1512a63712039348fbcfd8abfc3f09969f0d87acbaef75e4762743555e7a290579c837da306b3d3404dfcd18237aebb7a4045b25f0dfa9c560bb6b6c8aa7c99b8c0c68ce707e6f0c2cd6fe0a60683e3fd91441000180020002800) 2021-03-02 23:23:40 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:49966<->10.10.1.9:49244 >> Send: Protobuf: type: CRYPTO_PAIRING_MESSAGE errorCode: NoError [cryptoPairingMessage] { pairingData: "\006\001\003\005x\216k\277\331\026\177\026\276\003\325w\250\023\241\270\364\354\356lq\312\353\354\340\241\327f\326Z\027\246\270)D\2... status: 0 isRetrying: false isUsingSystemPairing: false state: 0 } 2021-03-02 23:23:40 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:49966<->10.10.1.9:49244 << Receive (Data=3e08222000ba02100a060701020601041000180020002800aa052434464446334235362d333734452d344131302d394644352d323537363844304145363339) 2021-03-02 23:23:40 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:49966<->10.10.1.9:49244 << Receive: Protobuf: type: CRYPTO_PAIRING_MESSAGE errorCode: NoError [cryptoPairingMessage] { pairingData: "\007\001\002\006\001\004" status: 0 isRetrying: false isUsingSystemPairing: false state: 0 } uniqueIdentifier: "4FDF3B56-374E-4A10-9FD5-25768D0AE639" 2021-03-02 23:23:40 DEBUG (MainThread) [pyatv.mrp.srp] Keys (Input=d8bb7f76831ed6a4ed3256a7be559b704ac4b154485a21845dda7dc4fc9c1c7c, Output=49565c2b0b2dd55bdc863974d5e99f5c10212a5d798d2ffda9ae9b805704ed86) 2021-03-02 23:23:40 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:49966<->10.10.1.9:49244 >> Send (Data=08262000d202020802) 2021-03-02 23:23:40 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:49966<->10.10.1.9:49244 >> Send (Encrypted=d9bb16403539597304a4d0f1d7eee1952d6ce793dc229ef395) 2021-03-02 23:23:40 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:49966<->10.10.1.9:49244 >> Send: Protobuf: type: SET_CONNECTION_STATE_MESSAGE errorCode: NoError [setConnectionStateMessage] { state: Connected } 2021-03-02 23:23:40 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:49966<->10.10.1.9:49244 >> Send (Data=0810122443383234393230462d343131392d343036442d394230352d3643304236314343393544312000aa010a08011000180120012800) 2021-03-02 23:23:40 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:49966<->10.10.1.9:49244 >> Send (Encrypted=bbbe113a50c8e3e2325e5c4c77a172b389127cbb51329bbd94c6c7c697b92c75a5fb23da7b1ddcd46b36504508876ff6891bbfbb678fc91f75913a67a043779874cbb6819d6efc) 2021-03-02 23:23:40 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:49966<->10.10.1.9:49244 >> Send: Protobuf: type: CLIENT_UPDATES_CONFIG_MESSAGE identifier: "C824920F-4119-406D-9B05-6C0B61CC95D1" errorCode: NoError [clientUpdatesConfigMessage] { artworkUpdates: true nowPlayingUpdates: false volumeUpdates: true keyboardUpdates: true outputDeviceUpdates: false } 2021-03-02 23:23:40 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:49966<->10.10.1.9:49244 Received EOF from server 2021-03-02 23:23:40 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:49966<->10.10.1.9:49244 Disconnected from device: None 2021-03-02 23:23:40 WARNING (MainThread) [pyatv.mrp.protocol] There were 1 outstanding requests 2021-03-02 23:23:40 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:49966<->10.10.1.9:49244 Closing connection 2021-03-02 23:23:45 ERROR (MainThread) [homeassistant.components.apple_tv] Failed to connect Traceback (most recent call last): File "/usr/local/lib/python3.8/site-packages/pyatv/mrp/protocol.py", line 177, in _receive await asyncio.wait_for(semaphore.acquire(), timeout) File "/usr/local/lib/python3.8/asyncio/tasks.py", line 501, in wait_for raise exceptions.TimeoutError() asyncio.exceptions.TimeoutError During handling of the above exception, another exception occurred: Traceback (most recent call last): File "/usr/src/homeassistant/homeassistant/components/apple_tv/__init__.py", line 242, in _connect_loop await self._connect(conf) File "/usr/src/homeassistant/homeassistant/components/apple_tv/__init__.py", line 326, in _connect self.atv = await connect(conf, self.hass.loop, session=session) File "/usr/local/lib/python3.8/site-packages/pyatv/__init__.py", line 76, in connect await atv.connect() File "/usr/local/lib/python3.8/site-packages/pyatv/mrp/__init__.py", line 701, in connect await self._protocol.start() File "/usr/local/lib/python3.8/site-packages/pyatv/mrp/protocol.py", line 107, in start await self.send_and_receive(messages.client_updates_config()) File "/usr/local/lib/python3.8/site-packages/pyatv/mrp/protocol.py", line 169, in send_and_receive return await self._receive(identifier, timeout) File "/usr/local/lib/python3.8/site-packages/pyatv/mrp/protocol.py", line 180, in _receive del self._outstanding[identifier] KeyError: 'C824920F-4119-406D-9B05-6C0B61CC95D1' ```
github-actions[bot] commented 3 years ago

Generated html log for for comment #789274266 is here.

MarcHagen commented 3 years ago

Still same with Home Assistant 2021.3.2

HA Info ## System Health version | core-2021.3.2 -- | -- installation_type | Home Assistant OS dev | false hassio | true docker | true virtualenv | false python_version | 3.8.7 os_name | Linux os_version | 5.4.99 arch | x86_64 timezone | Europe/Amsterdam
Home Assistant Community Store GitHub API | ok -- | -- Github API Calls Remaining | 4591 Installed Version | 1.11.3 Stage | running Available Repositories | 757 Installed Repositories | 18
Home Assistant Supervisor host_os | Home Assistant OS 5.12 -- | -- update_channel | stable supervisor_version | supervisor-2021.03.4 docker_version | 19.03.13 disk_total | 19.0 GB disk_used | 11.3 GB healthy | true supported | true board | ova supervisor_api | ok version_api | ok installed_addons | TasmoAdmin (0.14.0), ESPHome (1.16.2), Telegraf (0.5.6), Mosquitto broker (5.1.1), File editor (5.2.0), Check Home Assistant configuration (3.6.0), SSH & Web Terminal (8.0.3)
Lovelace dashboards | 2 -- | -- resources | 13 views | 7 mode | storage
Log output ```log 2021-03-07 20:05:47 DEBUG (MainThread) [pyatv.support.knock] Knocking at ports [3689, 7000, 49152, 32498] on 10.10.1.9 2021-03-07 20:05:47 DEBUG (MainThread) [pyatv.support.scan] Auto-discovered Woonkamer at 10.10.1.9:7000 (Protocol.AirPlay) 2021-03-07 20:05:47 DEBUG (MainThread) [pyatv.support.scan] Auto-discovered Woonkamer at 10.10.1.9:49244 (Protocol.MRP) 2021-03-07 20:05:47 DEBUG (MainThread) [pyatv.airplay] Loaded AirPlay credentials: 92BB9CFD8CA43653:46F646EC37A9094057620DE2A9439CCEEAEEC0796BE33A77946E503F4A481A10 2021-03-07 20:05:47 DEBUG (MainThread) [pyatv.mrp.connection] Connection made to device 2021-03-07 20:05:47 DEBUG (MainThread) [pyatv.support.net] Configured keep-alive on (Linux) 2021-03-07 20:05:47 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:55932<->10.10.1.9:49244 Connection established 2021-03-07 20:05:47 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:55932<->10.10.1.9:49244 >> Send (Data=080f122446363944423445322d333630452d343046302d394146462d4539363635453341433231442000a20183010a2435666131383837632d353236632d343331382d616463632d633334613731663836396531120570796174761a066950686f6e6522063138413339332a12636f6d2e6170706c652e545652656d6f746532063334342e32383801406c480150016211636f6d2e6170706c652e54564d75736963680170017801880102a80101b00101) 2021-03-07 20:05:47 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:55932<->10.10.1.9:49244 >> Send: Protobuf: type: DEVICE_INFO_MESSAGE identifier: "F69DB4E2-360E-40F0-9AFF-E9665E3AC21D" errorCode: NoError [deviceInfoMessage] { uniqueIdentifier: "5fa1887c-526c-4318-adcc-c34a71f869e1" 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-03-07 20:05:47 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:55932<->10.10.1.9:49244 << Receive (Data=a103080f122446363944423445322d333630452d343046302d394146462d4539363635453341433231442000a201cc020a2431343732334241372d373545442d344642352d383638302d4131343533393735373843431209576f6f6e6b616d65721a094170706c65c2a05456220631384b3830322a16636f6d2e6170706c652e6d6564696172656d6f7465643801406c480150016211636f6d2e6170706c652e54564d757369636801700178018801029a012431343732334241372d373545442d344642352d383638302d413134353339373537384343a2011136633a34613a38353a32363a64393a6462a80104b00101c00100d20124353735303444304...) 2021-03-07 20:05:47 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:55932<->10.10.1.9:49244 << Receive: Protobuf: type: DEVICE_INFO_MESSAGE identifier: "F69DB4E2-360E-40F0-9AFF-E9665E3AC21D" errorCode: NoError [deviceInfoMessage] { uniqueIdentifier: "14723BA7-75ED-4FB5-8680-A145397578CC" name: "Woonkamer" localizedModelName: "Apple\302\240TV" systemBuildVersion: "18K802" applicationBundleIdentifier: "com.apple.mediaremoted" protocolVersion: 1 lastSupportedMessageType: 108 supportsSystemPairing: true allowsPairing: true systemMediaApplication: "com.apple.TVMusic" supportsACL: true supportsSharedQueue: true supportsExtendedMotion: true sharedQueueVersion: 2 deviceUID: "14723BA7-75ED-4FB5-8680-A145397578CC" managedConfigDeviceID: "6c:4a:85:26:d9:db" deviceClass: AppleTV logicalDeviceCount: 1 isProxyGroupPlayer: false groupUID: "57504D0D-38C3-4EE9-A409-EC5450A83AD4" isGroupLeader: true isAirplayActive: false systemPodcastApplication: "com.apple.podcasts" enderDefaultGroupUID: "57504D0D-38C3-4EE9-A409-EC5450A83AD4" airplayReceivers: "TVAirPlay" clusterType: 0 isClusterAware: true modelID: "AppleTV6,2" } uniqueIdentifier: "CF8DBCDE-AE19-41EF-845D-19E81797C3B5" 2021-03-07 20:05:47 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:55932<->10.10.1.9:49244 >> Send (Data=08222000ba022f0a25060101032074328770e32f5f4be9c66d1d388f1ae00646b67bb4167946682eb0e3bc010b6b1000180020002800) 2021-03-07 20:05:47 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:55932<->10.10.1.9:49244 >> Send: Protobuf: type: CRYPTO_PAIRING_MESSAGE errorCode: NoError [cryptoPairingMessage] { pairingData: "\006\001\001\003 t2\207p\343/_K\351\306m\0358\217\032\340\006F\266{\264\026yFh.\260\343\274\001\013k" status: 0 isRetrying: false isUsingSystemPairing: false state: 0 } 2021-03-07 20:05:47 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:55932<->10.10.1.9:49244 << Receive (Data=d90108222000ba02aa010a9f010578c5832005d606d05fb6b20841afb6e521a4bd62dfc48611b99131b7eada8278d324461cacfae633d32488c5ea9dc6b0ac16e231880b898c6085a179efcf9e06b4ab385f0ab937bb24558595cba8459f544b74afe7ad182b28d24acea42a67521cbd015aa4ceab4d5fb9dd26e6b5123b77493e1f531c285d340601020320475f4030f5c9afab4eda5f4e59532830453b122a5fa25a7b9c68f6877f1dfd741000180020002800aa052431313835344339352d343231382d343930332d414134462d313045344633414146393438) 2021-03-07 20:05:47 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:55932<->10.10.1.9:49244 << Receive: Protobuf: type: CRYPTO_PAIRING_MESSAGE errorCode: NoError [cryptoPairingMessage] { pairingData: "\005x\305\203 \005\326\006\320_\266\262\010A\257\266\345!\244\275b\337\304\206\021\271\2211\267\352\332\202x\323$F\034\254\372\3463... status: 0 isRetrying: false isUsingSystemPairing: false state: 0 } uniqueIdentifier: "11854C95-4218-4903-AA4F-10E4F3AAF948" 2021-03-07 20:05:47 DEBUG (MainThread) [pyatv.mrp.auth] Device (Encrypted=c5832005d606d05fb6b20841afb6e521a4bd62dfc48611b99131b7eada8278d324461cacfae633d32488c5ea9dc6b0ac16e231880b898c6085a179efcf9e06b4ab385f0ab937bb24558595cba8459f544b74afe7ad182b28d24acea42a67521cbd015aa4ceab4d5fb9dd26e6b5123b77493e1f531c285d34, Public=cee7c5a7471183819b71c56d770446279d02ebd0530e0a4ebaae657ae3d2175f) 2021-03-07 20:05:47 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:55932<->10.10.1.9:49244 >> Send (Data=08222000ba0287010a7d0601030578ef2642133593b922152498d0919ee788cb7ff87753847e679af949cafa4cc6c982064ebfcb7c9e3d48d7b26c27d1e90381a379815e913590a654b546af6b2cd07adadf650abee981e04e526abf0290eee9673a2ee3f1ecce4ccf23f9d85a2efc101e1af09fc6a00ef6a6539d1d2ef21ce46d96f286058e441000180020002800) 2021-03-07 20:05:47 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:55932<->10.10.1.9:49244 >> Send: Protobuf: type: CRYPTO_PAIRING_MESSAGE errorCode: NoError [cryptoPairingMessage] { pairingData: "\006\001\003\005x\357&B\0235\223\271\"\025$\230\320\221\236\347\210\313\177\370wS\204~g\232\371I\312\372L\306\311\202\006N\277\313|... status: 0 isRetrying: false isUsingSystemPairing: false state: 0 } 2021-03-07 20:05:47 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:55932<->10.10.1.9:49244 << Receive (Data=3e08222000ba02100a060701020601041000180020002800aa052444314634394634412d464232462d344141342d383441362d384543313732364237353341) 2021-03-07 20:05:47 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:55932<->10.10.1.9:49244 << Receive: Protobuf: type: CRYPTO_PAIRING_MESSAGE errorCode: NoError [cryptoPairingMessage] { pairingData: "\007\001\002\006\001\004" status: 0 isRetrying: false isUsingSystemPairing: false state: 0 } uniqueIdentifier: "D1F49F4A-FB2F-4AA4-84A6-8EC1726B753A" 2021-03-07 20:05:47 DEBUG (MainThread) [pyatv.mrp.srp] Keys (Input=acd3b1474dcc31fab450b2ab4724a031fa347593e9408abab988d44978988656, Output=c703c8ae58fc13383cc94a72696c701cdf2c4c4dce319bd13893403451e9ca56) 2021-03-07 20:05:47 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:55932<->10.10.1.9:49244 >> Send (Data=08262000d202020802) 2021-03-07 20:05:47 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:55932<->10.10.1.9:49244 >> Send (Encrypted=0deb822f81e1bf6b26c6bc5e37328ed16b672965ea9916eb97) 2021-03-07 20:05:47 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:55932<->10.10.1.9:49244 >> Send: Protobuf: type: SET_CONNECTION_STATE_MESSAGE errorCode: NoError [setConnectionStateMessage] { state: Connected } 2021-03-07 20:05:47 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:55932<->10.10.1.9:49244 >> Send (Data=0810122430454434344642382d353937422d343130312d414446372d4635323437344630374234422000aa010a08011000180120012800) 2021-03-07 20:05:47 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:55932<->10.10.1.9:49244 >> Send (Encrypted=37742576c3b0783962a22679e018d927c07cc75d1aadbe827e097b31c8b86bb0eb86a9b8a28589c7c3aecbec2e00e58abddbb0b2b0aa1da5d357f0a8995c8a23f59f96bb7f5178) 2021-03-07 20:05:47 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:55932<->10.10.1.9:49244 >> Send: Protobuf: type: CLIENT_UPDATES_CONFIG_MESSAGE identifier: "0ED44FB8-597B-4101-ADF7-F52474F07B4B" errorCode: NoError [clientUpdatesConfigMessage] { artworkUpdates: true nowPlayingUpdates: false volumeUpdates: true keyboardUpdates: true outputDeviceUpdates: false } 2021-03-07 20:05:47 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:55932<->10.10.1.9:49244 Disconnected from device: [Errno 104] Connection reset by peer 2021-03-07 20:05:47 WARNING (MainThread) [pyatv.mrp.protocol] There were 1 outstanding requests 2021-03-07 20:05:47 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:55932<->10.10.1.9:49244 Closing connection 2021-03-07 20:05:53 ERROR (MainThread) [homeassistant.components.apple_tv] Failed to connect Traceback (most recent call last): File "/usr/local/lib/python3.8/site-packages/pyatv/mrp/protocol.py", line 177, in _receive await asyncio.wait_for(semaphore.acquire(), timeout) File "/usr/local/lib/python3.8/asyncio/tasks.py", line 501, in wait_for raise exceptions.TimeoutError() asyncio.exceptions.TimeoutError During handling of the above exception, another exception occurred: Traceback (most recent call last): File "/usr/src/homeassistant/homeassistant/components/apple_tv/__init__.py", line 245, in _connect_loop await self._connect(conf) File "/usr/src/homeassistant/homeassistant/components/apple_tv/__init__.py", line 329, in _connect self.atv = await connect(conf, self.hass.loop, session=session) File "/usr/local/lib/python3.8/site-packages/pyatv/__init__.py", line 76, in connect await atv.connect() File "/usr/local/lib/python3.8/site-packages/pyatv/mrp/__init__.py", line 701, in connect await self._protocol.start() File "/usr/local/lib/python3.8/site-packages/pyatv/mrp/protocol.py", line 107, in start await self.send_and_receive(messages.client_updates_config()) File "/usr/local/lib/python3.8/site-packages/pyatv/mrp/protocol.py", line 169, in send_and_receive return await self._receive(identifier, timeout) File "/usr/local/lib/python3.8/site-packages/pyatv/mrp/protocol.py", line 180, in _receive del self._outstanding[identifier] KeyError: '0ED44FB8-597B-4101-ADF7-F52474F07B4B' 2021-03-07 20:05:54 DEBUG (MainThread) [pyatv.support.knock] Knocking at ports [3689, 7000, 49152, 32498] on 10.10.1.9 2021-03-07 20:05:54 DEBUG (MainThread) [pyatv.support.scan] Auto-discovered Woonkamer at 10.10.1.9:7000 (Protocol.AirPlay) 2021-03-07 20:05:54 DEBUG (MainThread) [pyatv.support.scan] Auto-discovered Woonkamer at 10.10.1.9:49244 (Protocol.MRP) 2021-03-07 20:05:54 DEBUG (MainThread) [pyatv.airplay] Loaded AirPlay credentials: 92BB9CFD8CA43653:46F646EC37A9094057620DE2A9439CCEEAEEC0796BE33A77946E503F4A481A10 2021-03-07 20:05:54 DEBUG (MainThread) [pyatv.mrp.connection] Connection made to device 2021-03-07 20:05:54 DEBUG (MainThread) [pyatv.support.net] Configured keep-alive on (Linux) 2021-03-07 20:05:54 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:56020<->10.10.1.9:49244 Connection established 2021-03-07 20:05:54 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:56020<->10.10.1.9:49244 >> Send (Data=080f122438414332333431412d443936362d343046422d383341412d3732363641414335303434322000a20183010a2435666131383837632d353236632d343331382d616463632d633334613731663836396531120570796174761a066950686f6e6522063138413339332a12636f6d2e6170706c652e545652656d6f746532063334342e32383801406c480150016211636f6d2e6170706c652e54564d75736963680170017801880102a80101b00101) 2021-03-07 20:05:54 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:56020<->10.10.1.9:49244 >> Send: Protobuf: type: DEVICE_INFO_MESSAGE identifier: "8AC2341A-D966-40FB-83AA-7266AAC50442" errorCode: NoError [deviceInfoMessage] { uniqueIdentifier: "5fa1887c-526c-4318-adcc-c34a71f869e1" 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-03-07 20:05:54 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:56020<->10.10.1.9:49244 << Receive (Data=a103080f122438414332333431412d443936362d343046422d383341412d3732363641414335303434322000a201cc020a2431343732334241372d373545442d344642352d383638302d4131343533393735373843431209576f6f6e6b616d65721a094170706c65c2a05456220631384b3830322a16636f6d2e6170706c652e6d6564696172656d6f7465643801406c480150016211636f6d2e6170706c652e54564d757369636801700178018801029a012431343732334241372d373545442d344642352d383638302d413134353339373537384343a2011136633a34613a38353a32363a64393a6462a80104b00101c00100d20124353735303444304...) 2021-03-07 20:05:54 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:56020<->10.10.1.9:49244 << Receive: Protobuf: type: DEVICE_INFO_MESSAGE identifier: "8AC2341A-D966-40FB-83AA-7266AAC50442" errorCode: NoError [deviceInfoMessage] { uniqueIdentifier: "14723BA7-75ED-4FB5-8680-A145397578CC" name: "Woonkamer" localizedModelName: "Apple\302\240TV" systemBuildVersion: "18K802" applicationBundleIdentifier: "com.apple.mediaremoted" protocolVersion: 1 lastSupportedMessageType: 108 supportsSystemPairing: true allowsPairing: true systemMediaApplication: "com.apple.TVMusic" supportsACL: true supportsSharedQueue: true supportsExtendedMotion: true sharedQueueVersion: 2 deviceUID: "14723BA7-75ED-4FB5-8680-A145397578CC" managedConfigDeviceID: "6c:4a:85:26:d9:db" deviceClass: AppleTV logicalDeviceCount: 1 isProxyGroupPlayer: false groupUID: "57504D0D-38C3-4EE9-A409-EC5450A83AD4" isGroupLeader: true isAirplayActive: false systemPodcastApplication: "com.apple.podcasts" enderDefaultGroupUID: "57504D0D-38C3-4EE9-A409-EC5450A83AD4" airplayReceivers: "TVAirPlay" clusterType: 0 isClusterAware: true modelID: "AppleTV6,2" } uniqueIdentifier: "B33A8054-7085-4B68-BEEB-490612BAAD0C" 2021-03-07 20:05:54 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:56020<->10.10.1.9:49244 >> Send (Data=08222000ba022f0a25060101032032936176ffb17f48428d1e3387668a517a919075991ff49f014c1c1ab65ef13f1000180020002800) 2021-03-07 20:05:54 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:56020<->10.10.1.9:49244 >> Send: Protobuf: type: CRYPTO_PAIRING_MESSAGE errorCode: NoError [cryptoPairingMessage] { pairingData: "\006\001\001\003 2\223av\377\261\177HB\215\0363\207f\212Qz\221\220u\231\037\364\237\001L\034\032\266^\361?" status: 0 isRetrying: false isUsingSystemPairing: false state: 0 } 2021-03-07 20:05:54 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:56020<->10.10.1.9:49244 << Receive (Data=d90108222000ba02aa010a9f0105783f4b5aa214a0e6f72553f33e45fde0959cf1da5bbf838996b41662e76d521f6c79e3ecd849b51f7a363727a318b794d9be0b68179b440634964e6a1c9fc23b495193df17bdf8a2eb3d2aa03c1beb59ebb2575c3142845f45608f7006c6d660aeeb975e1d8248a91c6e4e86e4fa40f158e00523e9236cffe606010203201503081f9c84f01f6321b86608d9ebaf0060c3815d74f4574e4e4bd5226596601000180020002800aa052434354638434139342d433046302d343846332d383532322d434236353233353335373641) 2021-03-07 20:05:54 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:56020<->10.10.1.9:49244 << Receive: Protobuf: type: CRYPTO_PAIRING_MESSAGE errorCode: NoError [cryptoPairingMessage] { pairingData: "\005x?KZ\242\024\240\346\367%S\363>E\375\340\225\234\361\332[\277\203\211\226\264\026b\347mR\037ly\343\354\330I\265\037z67\'\243\03... status: 0 isRetrying: false isUsingSystemPairing: false state: 0 } uniqueIdentifier: "45F8CA94-C0F0-48F3-8522-CB652353576A" 2021-03-07 20:05:54 DEBUG (MainThread) [pyatv.mrp.auth] Device (Encrypted=3f4b5aa214a0e6f72553f33e45fde0959cf1da5bbf838996b41662e76d521f6c79e3ecd849b51f7a363727a318b794d9be0b68179b440634964e6a1c9fc23b495193df17bdf8a2eb3d2aa03c1beb59ebb2575c3142845f45608f7006c6d660aeeb975e1d8248a91c6e4e86e4fa40f158e00523e9236cffe6, Public=cee7c5a7471183819b71c56d770446279d02ebd0530e0a4ebaae657ae3d2175f) 2021-03-07 20:05:54 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:56020<->10.10.1.9:49244 >> Send (Data=08222000ba0287010a7d0601030578b5be55e5c2808c978d2bc9de555153e8bd028a85b2d575695f40d9b4e3b6e58c96ae3138ca0755dfbe635da9a0bc15704c77db169b2080b576df3dbea215190b2e96b1f100a94a3a0f3fc52c4d6a44d1ec62c64b06537ceb943f3ad7793f467d5962279bfa7b9402ac0f5a3f887c203a6f8155ef311369d01000180020002800) 2021-03-07 20:05:54 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:56020<->10.10.1.9:49244 >> Send: Protobuf: type: CRYPTO_PAIRING_MESSAGE errorCode: NoError [cryptoPairingMessage] { pairingData: "\006\001\003\005x\265\276U\345\302\200\214\227\215+\311\336UQS\350\275\002\212\205\262\325ui_@\331\264\343\266\345\214\226\25618\31... status: 0 isRetrying: false isUsingSystemPairing: false state: 0 } 2021-03-07 20:05:54 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:56020<->10.10.1.9:49244 << Receive (Data=3e08222000ba02100a060701020601041000180020002800aa052443443137353234312d324442312d344332332d423839322d303944383331363639363042) 2021-03-07 20:05:54 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:56020<->10.10.1.9:49244 << Receive: Protobuf: type: CRYPTO_PAIRING_MESSAGE errorCode: NoError [cryptoPairingMessage] { pairingData: "\007\001\002\006\001\004" status: 0 isRetrying: false isUsingSystemPairing: false state: 0 } uniqueIdentifier: "CD175241-2DB1-4C23-B892-09D83166960B" 2021-03-07 20:05:54 DEBUG (MainThread) [pyatv.mrp.srp] Keys (Input=8c138a89ca1288910a8c2f815cd40e4693787b6eaae04253cf83c1d82aba2aa3, Output=126faa57b788967b6a44c267dccf22d74509a169fd94ee06a66fd12f1eafd438) 2021-03-07 20:05:54 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:56020<->10.10.1.9:49244 >> Send (Data=08262000d202020802) 2021-03-07 20:05:54 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:56020<->10.10.1.9:49244 >> Send (Encrypted=514745b70f757853705c905122c4ea160064b3ba54d1bc1493) 2021-03-07 20:05:54 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:56020<->10.10.1.9:49244 >> Send: Protobuf: type: SET_CONNECTION_STATE_MESSAGE errorCode: NoError [setConnectionStateMessage] { state: Connected } 2021-03-07 20:05:54 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:56020<->10.10.1.9:49244 >> Send (Data=0810122436333237364644462d334146322d344333332d393235442d3242453234334644413330412000aa010a08011000180120012800) 2021-03-07 20:05:54 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:56020<->10.10.1.9:49244 >> Send (Encrypted=173b442256eb284a6d96ce3e26f11bad4768cdf3cdea0ced387d9c1bfe73c3dc2afc79fa51bec076aeff974bbb8792d0f9bcacf539f3f09dada8260511571fcfd9bef843885173) 2021-03-07 20:05:54 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:56020<->10.10.1.9:49244 >> Send: Protobuf: type: CLIENT_UPDATES_CONFIG_MESSAGE identifier: "63276FDF-3AF2-4C33-925D-2BE243FDA30A" errorCode: NoError [clientUpdatesConfigMessage] { artworkUpdates: true nowPlayingUpdates: false volumeUpdates: true keyboardUpdates: true outputDeviceUpdates: false } 2021-03-07 20:05:54 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:56020<->10.10.1.9:49244 Disconnected from device: [Errno 104] Connection reset by peer 2021-03-07 20:05:54 WARNING (MainThread) [pyatv.mrp.protocol] There were 1 outstanding requests 2021-03-07 20:05:54 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:56020<->10.10.1.9:49244 Closing connection 2021-03-07 20:05:59 ERROR (MainThread) [homeassistant.components.apple_tv] Failed to connect Traceback (most recent call last): File "/usr/local/lib/python3.8/site-packages/pyatv/mrp/protocol.py", line 177, in _receive await asyncio.wait_for(semaphore.acquire(), timeout) File "/usr/local/lib/python3.8/asyncio/tasks.py", line 501, in wait_for raise exceptions.TimeoutError() asyncio.exceptions.TimeoutError During handling of the above exception, another exception occurred: Traceback (most recent call last): File "/usr/src/homeassistant/homeassistant/components/apple_tv/__init__.py", line 245, in _connect_loop await self._connect(conf) File "/usr/src/homeassistant/homeassistant/components/apple_tv/__init__.py", line 329, in _connect self.atv = await connect(conf, self.hass.loop, session=session) File "/usr/local/lib/python3.8/site-packages/pyatv/__init__.py", line 76, in connect await atv.connect() File "/usr/local/lib/python3.8/site-packages/pyatv/mrp/__init__.py", line 701, in connect await self._protocol.start() File "/usr/local/lib/python3.8/site-packages/pyatv/mrp/protocol.py", line 107, in start await self.send_and_receive(messages.client_updates_config()) File "/usr/local/lib/python3.8/site-packages/pyatv/mrp/protocol.py", line 169, in send_and_receive return await self._receive(identifier, timeout) File "/usr/local/lib/python3.8/site-packages/pyatv/mrp/protocol.py", line 180, in _receive del self._outstanding[identifier] KeyError: '63276FDF-3AF2-4C33-925D-2BE243FDA30A' 2021-03-07 20:06:01 DEBUG (MainThread) [pyatv.support.knock] Knocking at ports [3689, 7000, 49152, 32498] on 10.10.1.9 2021-03-07 20:06:01 DEBUG (MainThread) [pyatv.support.scan] Auto-discovered Woonkamer at 10.10.1.9:7000 (Protocol.AirPlay) 2021-03-07 20:06:01 DEBUG (MainThread) [pyatv.support.scan] Auto-discovered Woonkamer at 10.10.1.9:49244 (Protocol.MRP) 2021-03-07 20:06:01 DEBUG (MainThread) [pyatv.airplay] Loaded AirPlay credentials: 92BB9CFD8CA43653:46F646EC37A9094057620DE2A9439CCEEAEEC0796BE33A77946E503F4A481A10 2021-03-07 20:06:01 DEBUG (MainThread) [pyatv.mrp.connection] Connection made to device 2021-03-07 20:06:01 DEBUG (MainThread) [pyatv.support.net] Configured keep-alive on (Linux) 2021-03-07 20:06:01 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:56040<->10.10.1.9:49244 Connection established 2021-03-07 20:06:01 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:56040<->10.10.1.9:49244 >> Send (Data=080f122431433932424144462d463332442d344434302d423034452d4643314144464234394537302000a20183010a2435666131383837632d353236632d343331382d616463632d633334613731663836396531120570796174761a066950686f6e6522063138413339332a12636f6d2e6170706c652e545652656d6f746532063334342e32383801406c480150016211636f6d2e6170706c652e54564d75736963680170017801880102a80101b00101) 2021-03-07 20:06:01 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:56040<->10.10.1.9:49244 >> Send: Protobuf: type: DEVICE_INFO_MESSAGE identifier: "1C92BADF-F32D-4D40-B04E-FC1ADFB49E70" errorCode: NoError [deviceInfoMessage] { uniqueIdentifier: "5fa1887c-526c-4318-adcc-c34a71f869e1" 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-03-07 20:06:01 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:56040<->10.10.1.9:49244 << Receive (Data=a103080f122431433932424144462d463332442d344434302d423034452d4643314144464234394537302000a201cc020a2431343732334241372d373545442d344642352d383638302d4131343533393735373843431209576f6f6e6b616d65721a094170706c65c2a05456220631384b3830322a16636f6d2e6170706c652e6d6564696172656d6f7465643801406c480150016211636f6d2e6170706c652e54564d757369636801700178018801029a012431343732334241372d373545442d344642352d383638302d413134353339373537384343a2011136633a34613a38353a32363a64393a6462a80104b00101c00100d20124353735303444304...) 2021-03-07 20:06:01 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:56040<->10.10.1.9:49244 << Receive: Protobuf: type: DEVICE_INFO_MESSAGE identifier: "1C92BADF-F32D-4D40-B04E-FC1ADFB49E70" errorCode: NoError [deviceInfoMessage] { uniqueIdentifier: "14723BA7-75ED-4FB5-8680-A145397578CC" name: "Woonkamer" localizedModelName: "Apple\302\240TV" systemBuildVersion: "18K802" applicationBundleIdentifier: "com.apple.mediaremoted" protocolVersion: 1 lastSupportedMessageType: 108 supportsSystemPairing: true allowsPairing: true systemMediaApplication: "com.apple.TVMusic" supportsACL: true supportsSharedQueue: true supportsExtendedMotion: true sharedQueueVersion: 2 deviceUID: "14723BA7-75ED-4FB5-8680-A145397578CC" managedConfigDeviceID: "6c:4a:85:26:d9:db" deviceClass: AppleTV logicalDeviceCount: 1 isProxyGroupPlayer: false groupUID: "57504D0D-38C3-4EE9-A409-EC5450A83AD4" isGroupLeader: true isAirplayActive: false systemPodcastApplication: "com.apple.podcasts" enderDefaultGroupUID: "57504D0D-38C3-4EE9-A409-EC5450A83AD4" airplayReceivers: "TVAirPlay" clusterType: 0 isClusterAware: true modelID: "AppleTV6,2" } uniqueIdentifier: "881DB8E1-8A53-46B4-9665-CBF79388BEA4" 2021-03-07 20:06:01 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:56040<->10.10.1.9:49244 >> Send (Data=08222000ba022f0a2506010103206b30f3664b2969106fbec2c01088be36d9a72726648da0c8da86278e69071c101000180020002800) 2021-03-07 20:06:01 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:56040<->10.10.1.9:49244 >> Send: Protobuf: type: CRYPTO_PAIRING_MESSAGE errorCode: NoError [cryptoPairingMessage] { pairingData: "\006\001\001\003 k0\363fK)i\020o\276\302\300\020\210\2766\331\247\'&d\215\240\310\332\206\'\216i\007\034\020" status: 0 isRetrying: false isUsingSystemPairing: false state: 0 } 2021-03-07 20:06:01 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:56040<->10.10.1.9:49244 << Receive (Data=d90108222000ba02aa010a9f010578d51a929ed1f77ce29f723f95721d1823aadbd2ddbc8aea00bfa21b4ebdeab2f2159a085278993a4d24df159d6d0c6492abf05dd3d157a4859ceed5fc40c66c8bd24b6954a58f4af4c4a7d5f5a9dd17d9ba18111ec0fb3725343a98bc52d816dfe4cb3d53f0f761e500c3a6bfb31e3ef49005ad61a63ad39a06010203206e3fe8b65cf3dc328b0ba4cf8c6fe076d24ed37f5596b154a5bedeb5c49ad2251000180020002800aa052444454533423634362d324137422d344638442d414245392d463642354444343735413934) 2021-03-07 20:06:01 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:56040<->10.10.1.9:49244 << Receive: Protobuf: type: CRYPTO_PAIRING_MESSAGE errorCode: NoError [cryptoPairingMessage] { pairingData: "\005x\325\032\222\236\321\367|\342\237r?\225r\035\030#\252\333\322\335\274\212\352\000\277\242\033N\275\352\262\362\025\232\010Rx\2... status: 0 isRetrying: false isUsingSystemPairing: false state: 0 } uniqueIdentifier: "DEE3B646-2A7B-4F8D-ABE9-F6B5DD475A94" 2021-03-07 20:06:01 DEBUG (MainThread) [pyatv.mrp.auth] Device (Encrypted=d51a929ed1f77ce29f723f95721d1823aadbd2ddbc8aea00bfa21b4ebdeab2f2159a085278993a4d24df159d6d0c6492abf05dd3d157a4859ceed5fc40c66c8bd24b6954a58f4af4c4a7d5f5a9dd17d9ba18111ec0fb3725343a98bc52d816dfe4cb3d53f0f761e500c3a6bfb31e3ef49005ad61a63ad39a, Public=cee7c5a7471183819b71c56d770446279d02ebd0530e0a4ebaae657ae3d2175f) 2021-03-07 20:06:01 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:56040<->10.10.1.9:49244 >> Send (Data=08222000ba0287010a7d0601030578aa4ca946c435445f8c8b01b76d2739cf5ec3e371b10d2e0d08315d625bad11181156f7743fdcf04c9f429f65e9e21622f5793cc237b60345404b2a921d3854f2722f8e384709249813b6981e6690c7a94b7c9c849ce58997c30d69e600b7fbab58b2b4cece5bb6442e9b503d4f6c7fbc8abe860b3c853fcf1000180020002800) 2021-03-07 20:06:01 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:56040<->10.10.1.9:49244 >> Send: Protobuf: type: CRYPTO_PAIRING_MESSAGE errorCode: NoError [cryptoPairingMessage] { pairingData: "\006\001\003\005x\252L\251F\3045D_\214\213\001\267m\'9\317^\303\343q\261\r.\r\0101]b[\255\021\030\021V\367t?\334\360L\237B\237e\351... status: 0 isRetrying: false isUsingSystemPairing: false state: 0 } 2021-03-07 20:06:01 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:56040<->10.10.1.9:49244 << Receive (Data=3e08222000ba02100a060701020601041000180020002800aa052439463735423930302d433641452d343741372d414541352d453439303346313730454245) 2021-03-07 20:06:01 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:56040<->10.10.1.9:49244 << Receive: Protobuf: type: CRYPTO_PAIRING_MESSAGE errorCode: NoError [cryptoPairingMessage] { pairingData: "\007\001\002\006\001\004" status: 0 isRetrying: false isUsingSystemPairing: false state: 0 } uniqueIdentifier: "9F75B900-C6AE-47A7-AEA5-E4903F170EBE" 2021-03-07 20:06:01 DEBUG (MainThread) [pyatv.mrp.srp] Keys (Input=7df0cd63e8791be864b465ab0b8083d115d7848857b487094bcad00e23da05f6, Output=7cf306f79ab93de74ad55d404a4c40d24efa29151b396d2ae64ccc8990d51d4d) 2021-03-07 20:06:01 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:56040<->10.10.1.9:49244 >> Send (Data=08262000d202020802) 2021-03-07 20:06:01 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:56040<->10.10.1.9:49244 >> Send (Encrypted=f2078a8345cf33c6e8d1cbdb2b768a072d3a45fe6e820c411e) 2021-03-07 20:06:01 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:56040<->10.10.1.9:49244 >> Send: Protobuf: type: SET_CONNECTION_STATE_MESSAGE errorCode: NoError [setConnectionStateMessage] { state: Connected } 2021-03-07 20:06:01 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:56040<->10.10.1.9:49244 >> Send (Data=0810122435334334464332392d464246362d343636462d383544332d4446373135453444364232382000aa010a08011000180120012800) 2021-03-07 20:06:01 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:56040<->10.10.1.9:49244 >> Send (Encrypted=920a1ca745485320c9324585bac7ad3af0a02fecba51a55f861748a0ecbd2dcdb54dbb3846c6421d267fff8be7bacf65f1b5d5d7a46418e56b188e1fc390a6969e264e795c9a45) 2021-03-07 20:06:01 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:56040<->10.10.1.9:49244 >> Send: Protobuf: type: CLIENT_UPDATES_CONFIG_MESSAGE identifier: "53C4FC29-FBF6-466F-85D3-DF715E4D6B28" errorCode: NoError [clientUpdatesConfigMessage] { artworkUpdates: true nowPlayingUpdates: false volumeUpdates: true keyboardUpdates: true outputDeviceUpdates: false } 2021-03-07 20:06:01 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:56040<->10.10.1.9:49244 Received EOF from server 2021-03-07 20:06:01 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:56040<->10.10.1.9:49244 Disconnected from device: [Errno 107] Socket not connected 2021-03-07 20:06:01 WARNING (MainThread) [pyatv.mrp.protocol] There were 1 outstanding requests 2021-03-07 20:06:01 DEBUG (MainThread) [pyatv.mrp.connection] 10.10.0.33:56040<->10.10.1.9:49244 Closing connection 2021-03-07 20:06:06 ERROR (MainThread) [homeassistant.components.apple_tv] Failed to connect Traceback (most recent call last): File "/usr/local/lib/python3.8/site-packages/pyatv/mrp/protocol.py", line 177, in _receive await asyncio.wait_for(semaphore.acquire(), timeout) File "/usr/local/lib/python3.8/asyncio/tasks.py", line 501, in wait_for raise exceptions.TimeoutError() asyncio.exceptions.TimeoutError During handling of the above exception, another exception occurred: Traceback (most recent call last): File "/usr/src/homeassistant/homeassistant/components/apple_tv/__init__.py", line 245, in _connect_loop await self._connect(conf) File "/usr/src/homeassistant/homeassistant/components/apple_tv/__init__.py", line 329, in _connect self.atv = await connect(conf, self.hass.loop, session=session) File "/usr/local/lib/python3.8/site-packages/pyatv/__init__.py", line 76, in connect await atv.connect() File "/usr/local/lib/python3.8/site-packages/pyatv/mrp/__init__.py", line 701, in connect await self._protocol.start() File "/usr/local/lib/python3.8/site-packages/pyatv/mrp/protocol.py", line 107, in start await self.send_and_receive(messages.client_updates_config()) File "/usr/local/lib/python3.8/site-packages/pyatv/mrp/protocol.py", line 169, in send_and_receive return await self._receive(identifier, timeout) File "/usr/local/lib/python3.8/site-packages/pyatv/mrp/protocol.py", line 180, in _receive del self._outstanding[identifier] KeyError: '53C4FC29-FBF6-466F-85D3-DF715E4D6B28' ```
postlund commented 3 years ago

@MarcHagen Can you provide some logs as well?

github-actions[bot] commented 3 years ago

Generated html log for for comment #792330994 is here.

postlund commented 3 years ago

@MarcHagen I don't quite get why the device decides to close the connection. Encryption is set up just fine and then, when the first message is sent after that: connection reset. Can you try running atvremote from another host and see if that works?

postlund commented 3 years ago

@MarcHagen Also, what is the exact use case here? What are you doing?

MarcHagen commented 3 years ago

@postlund oke, i have to admit, i feel pretty stupid. So apparently somewhere in updating of hass the pair keys where invalid/gone/not working. I had removed the integration/entity, rebooted hass, added paired it again and now it works. I had tried this before in the 2021.2 something version but that didn't work. So sorry if this caused you(of someone else) some inconvenience.

@MarcHagen Also, what is the exact use case here? What are you doing?

I use some automations within HA to control my apple tv. To a "netflix and chill" setting, turning on every media device. Also to do some "force" shutdowns when were going to bed, or away. And it sometimes get used just as a photoslider/videoslider/videowall. HA sends the remote command to the ATV to open a app and start a show.

postlund commented 3 years ago

@MarcHagen 👍

I feel that this issue has kinda moved away too far from the initial problem, making it hard to keep track. Gonna close this now. If any issues still persists, please search amongst already open issues and add a comment in one of those or create a new issue if none of the open matches. Thanks!