Plop, plop. Apple TV integration keeps taking a dump

_Mike · February 10, 2021, 9:23pm

I have three Apple TVs. Every single one of them gives the below errors. And every single one of them regularly asks me to reconfigure the integration. But if I restart HA or reload the integration, everything works fine. Anyone else experiencing this?

Logger: pyatv.mrp.protocol
Source: /usr/local/lib/python3.8/site-packages/pyatv/mrp/protocol.py:37
First occurred: 4:02:36 PM (1 occurrences)
Last logged: 4:02:36 PM

heartbeat 912 failed
Traceback (most recent call last):
File “/usr/local/lib/python3.8/site-packages/pyatv/mrp/protocol.py”, line 32, in heartbeat_loop
await protocol.send_and_receive(message)
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 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

Logger: homeassistant
Source: components/apple_tv/init.py:183
First occurred: 1:42:23 PM (1 occurrences)
Last logged: 1:42:23 PM

Error doing job: Exception in callback _SelectorSocketTransport._call_connection_lost(TimeoutError(…on timed out’))
Traceback (most recent call last):
File “/usr/local/lib/python3.8/asyncio/events.py”, line 81, in _run
self._context.run(self._callback, *self._args)
File “/usr/local/lib/python3.8/asyncio/selector_events.py”, line 970, in _call_connection_lost
super()._call_connection_lost(exc)
File “/usr/local/lib/python3.8/asyncio/selector_events.py”, line 728, in _call_connection_lost
self._protocol.connection_lost(exc)
File “/usr/local/lib/python3.8/site-packages/pyatv/mrp/connection.py”, line 58, in connection_lost
self.atv.listener.connection_lost(exc)
File “/usr/src/homeassistant/homeassistant/components/apple_tv/init.py”, line 183, in connection_lost
_LOGGER.warning(‘Connection lost to Apple TV “%s”’, self.atv.name)
AttributeError: ‘MrpAppleTV’ object has no attribute ‘name’

postlund · February 10, 2021, 10:22pm

Heartbeat errors might happen every once in a while, I might try to make that less subtle with at least a retry in the future. The other problem is a bug which is fixed on dev, so it will be available in the next release.

_Mike · February 10, 2021, 10:33pm

Awesome! Thanks for the quick response!

fgonza2 · February 23, 2021, 7:13pm

Hi i can’t install the new apple TV integration it asks me for a code and everytime i enter one it says “aborted” i can go in there forever. The code doesn’t being with zeroes. tvOS 14.4 any ideas?

_Mike · February 23, 2021, 8:03pm

It sounds like these issues are going to resolved in the next release.

fgonza2 · February 23, 2021, 8:34pm

i hope so, are they somewhere in a list?

_Mike · March 7, 2021, 1:43am

Hi @postlund! I am on core-2021.3.2 and am still receiving alerts multiple times a day that my Apple TVs are either discovered or need to be reconfigured. Just wondering if you think the fix will come as part of a minor/dot release, or a future full release? Thanks!

postlund · March 7, 2021, 5:43am

It would be great if you can attach some logs that I can look at, I don’t any upcoming changes for now.

_Mike · March 7, 2021, 12:45pm

Thanks @postlund! I had some logs in my original post in this thread. And here is more info…

You can see in the screen shot that it is suggesting to add “new” Apple TVs when they are already configured.

Here are some logs I received last night:

Logger: homeassistant.components.apple_tv
Source: components/apple_tv/__init__.py:329
Integration: Apple TV ([documentation](https://www.home-assistant.io/integrations/apple_tv), [issues](https://github.com/home-assistant/home-assistant/issues?q=is%3Aissue+is%3Aopen+label%3A%22integration%3A+apple_tv%22))
First occurred: 12:37:49 AM (1 occurrences)
Last logged: 12:37:49 AM

Failed to connect

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 81, in start await self.connection.connect() File "/usr/local/lib/python3.8/asyncio/base_events.py", line 1025, in create_connection raise exceptions[0] File "/usr/local/lib/python3.8/asyncio/base_events.py", line 1010, in create_connection sock = await self._connect_sock( File "/usr/local/lib/python3.8/asyncio/base_events.py", line 924, in _connect_sock await self.sock_connect(sock, address) File "/usr/local/lib/python3.8/asyncio/selector_events.py", line 496, in sock_connect return await fut File "/usr/local/lib/python3.8/asyncio/selector_events.py", line 528, in _sock_connect_cb raise OSError(err, f'Connect call failed {address}') ConnectionRefusedError: [Errno 111] Connect call failed ('192.168.1.190', 49152)

Logger: pyatv.mrp.protocol
Source: /usr/local/lib/python3.8/site-packages/pyatv/mrp/protocol.py:37
First occurred: March 6, 2021, 9:04:39 PM (633 occurrences)
Last logged: 1:16:34 AM

heartbeat 548 failed
heartbeat 545 failed
heartbeat 101 failed
heartbeat 90 failed
heartbeat 97 failed
Traceback (most recent call last):
  File "/usr/local/lib/python3.8/site-packages/pyatv/mrp/protocol.py", line 32, in heartbeat_loop
    await protocol.send_and_receive(message)
  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 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

Logger: homeassistant.util.logging
Source: util/logging.py:99
First occurred: March 6, 2021, 9:04:40 PM (636 occurrences)
Last logged: 1:16:34 AM

Exception in _async_disconnected when dispatching 'apple_tv_disconnected_29264427-8A66-491B-AF80-F819E555BD8A': () Traceback (most recent call last): File "/usr/src/homeassistant/homeassistant/components/apple_tv/__init__.py", line 116, in _async_disconnected self.async_device_disconnected() File "/usr/src/homeassistant/homeassistant/components/apple_tv/media_player.py", line 92, in async_device_disconnected self.atv.push_updater.stop() AttributeError: 'NoneType' object has no attribute 'push_updater'

postlund · March 7, 2021, 6:39pm

Did you by any chance use the beta component and switch to the built in version? It might work better to remove the integrations and add them again. If that’s not the case, the I will have to look further into the problem.

_Mike · March 7, 2021, 6:51pm

No, I have only used the built-in version. I have been doing some thinking and testing today. I noticed a couple of things -

When I restart HA, everything works correctly. No errors, and no suggestions to re-add the integration.
When I restart an Apple TV, I get the heartbeat error.

I haven’t noticed a direct correlation between restarting the Apple TV and the other errors or suggestions to re-add the integration, but I wonder if that could be related?

poraschaudhary · March 9, 2021, 5:11am

Same thing here as well… “New device found” notification for an Apple TV which is already configured.
The problem was introduced in core-2021.3.2 and now continuing in core-2021.3.3.

postlund · March 9, 2021, 8:59pm

Which generations of Apple TV’s are we talking about here? I see a potential problem with pre-tvOS, so it shouldn’t affect Apple TV 4 and later. But I’m probably wrong.

What would be super helpful for troubleshooting this is the output of atvremote scan (you can run it from any computer on the same network as the Apple TV) and the unique_id field from the corresponding devices in .storage/core.config_entries. That way I can try to figure out what is happening.

atvremote is part of pyatv:

_Mike · March 9, 2021, 9:37pm

I have 1 Apple TV 4K model and 2 TVOS Apple TV HD models. The problem is happening on all of them, seemingly randomly.

I’m not super familiar with python, but I’ll try to run that scan later today. Is there anything that might be helpful from the HA logs if I set the logging level to debug?

_Mike · March 10, 2021, 1:29am

I THINK these issues might be related to restarting the Apple TV. My Harmony remotes are configured to restart the Apple TVs when I turn off the TV. @poraschaudhary Any chance you are also restarting your Apple TVs as well?

Meanwhile, I don’t know if this is any more helpful than the logs I already sent, but I did turn on debug and waited for it to fail. Here is what I have…

2021-03-09 17:55:41 DEBUG (MainThread) [homeassistant.components.apple_tv] Starting connect loop
2021-03-09 17:55:41 DEBUG (MainThread) [homeassistant.components.apple_tv] Discovering device 7739B0F3-BA3C-437A-810F-B591798D03F8
2021-03-09 17:55:41 DEBUG (MainThread) [homeassistant.components.apple_tv] Starting connect loop
2021-03-09 17:55:41 DEBUG (MainThread) [homeassistant.components.apple_tv] Discovering device 6DB93158-ED44-4352-8B8A-3C4AE1991F08
2021-03-09 17:55:41 DEBUG (MainThread) [homeassistant.components.apple_tv] Starting connect loop
2021-03-09 17:55:41 DEBUG (MainThread) [homeassistant.components.apple_tv] Discovering device 29264427-8A66-491B-AF80-F819E555BD8A
2021-03-09 17:55:41 DEBUG (MainThread) [homeassistant.components.apple_tv] Connecting to device Family Room
2021-03-09 17:55:41 DEBUG (MainThread) [homeassistant.components.apple_tv] Connecting to device Master Bedroom
2021-03-09 17:55:41 DEBUG (MainThread) [homeassistant.components.apple_tv] Connecting to device Loft
2021-03-09 17:55:45 DEBUG (MainThread) [homeassistant.components.apple_tv] Changing address to 192.168.1.173
2021-03-09 17:55:45 DEBUG (MainThread) [homeassistant.components.apple_tv] Connect loop ended
2021-03-09 17:55:45 DEBUG (MainThread) [homeassistant.components.apple_tv] Changing address to 192.168.1.156
2021-03-09 17:55:45 DEBUG (MainThread) [homeassistant.components.apple_tv] Connect loop ended
2021-03-09 17:55:45 DEBUG (MainThread) [homeassistant.components.apple_tv] Changing address to 192.168.1.190
2021-03-09 17:55:45 DEBUG (MainThread) [homeassistant.components.apple_tv] Connect loop ended
2021-03-09 19:44:27 ERROR (MainThread) [pyatv.mrp.protocol] heartbeat 216 failed
Traceback (most recent call last):
File “/usr/local/lib/python3.8/site-packages/pyatv/mrp/protocol.py”, line 32, in heartbeat_loop
await protocol.send_and_receive(message)
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 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
2021-03-09 19:44:27 DEBUG (MainThread) [homeassistant.components.apple_tv] Starting connect loop
2021-03-09 19:44:27 DEBUG (MainThread) [homeassistant.components.apple_tv] Discovering device 7739B0F3-BA3C-437A-810F-B591798D03F8
2021-03-09 19:44:32 DEBUG (MainThread) [homeassistant.components.apple_tv] Failed to find device 7739B0F3-BA3C-437A-810F-B591798D03F8 with address 192.168.1.173, trying to scan
2021-03-09 19:44:35 DEBUG (MainThread) [homeassistant.components.apple_tv] Connecting to device Family Room
2021-03-09 19:44:40 ERROR (MainThread) [homeassistant.components.apple_tv] Failed to connect
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 92, in start
self.device_info = await self.send_and_receive(msg)
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 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
2021-03-09 19:44:40 DEBUG (MainThread) [homeassistant.components.apple_tv] Reconnecting in 0 seconds
2021-03-09 19:44:40 DEBUG (MainThread) [homeassistant.components.apple_tv] Discovering device 7739B0F3-BA3C-437A-810F-B591798D03F8
2021-03-09 19:44:40 DEBUG (MainThread) [homeassistant.components.apple_tv] Connecting to device Family Room
2021-03-09 19:44:49 DEBUG (MainThread) [homeassistant.components.apple_tv] Authentication error, reconfigure integration
2021-03-09 19:44:49 DEBUG (MainThread) [homeassistant.components.apple_tv] Connect loop ended
2021-03-09 19:44:49 DEBUG (MainThread) [homeassistant.components.apple_tv] Disconnecting from device

postlund · March 12, 2021, 9:42pm

The logs are kind of mixed, so it’s hard to see what’s happening. But the initial bug should be fixed in the latest release or so. There’s another similar bug that I fixed today, it will be part of a future release (I’ve pushed it to the beta component repo, so it can easily be tested that way though). The multiple device problem however is another story. Maybe you can create an issue in the pyatv repo regarding that so we can start systematic analysis? I kinda feel this thread is hard to follow.

_Mike · March 12, 2021, 9:59pm

Thanks @postlund. I’ll wait for your latest changes to be released and give them a try. If any of my issues are still occurring after that, I will create an issue in the pyatv repo. Thanks again for your help!

shim895 · March 23, 2021, 7:55pm

Following because mine has been dumping my two devices also (both 4th generation).

_Mike · March 23, 2021, 8:14pm

Does it happen after a restart?

shim895 · March 23, 2021, 9:01pm

It’s very difficult to pinpoint when exactly they get dropped… it’s definitely NOT when I restart HA or reboot my host. It could be when my Apple TV’s get restarted, but I never explicitly do that. Is there some setting I can look at in the iOS that will prevent them from ever restarting?