AppleTV integration stops working after a while since last update (09/02/2024)

[albaintor]

My AppleTV integration worked perfectly before the last firmware update (1.7.4)

First after the update, the integration didn't work anymore (commands didn't respond) so I reinitialized it (recreate the apple TV integration) and it started to work
But after a while the integration stops working. It happened twice today. In the logfile there is an incoherent message after each button pressed :

2024-03-09 11:24:05.216159 +00:00	intg-appletv	INFO	DEBUG:driver:Device is off, sending turn on command

But in fact the apple TV is really ON (I can see the apple dashboard on TV).
To reproduce the problem :

1. (fresh reboot) start apple tv activity
2. Press buttons (arrow keys...) => commands are processed correctly
3. Shutdown the activity
4. Wait for a while
5. Start apple activity again : commands are not processed anymore

Here is the full log file :
UCR2_logs_2024-03-09.zip

[albaintor]

One precision : only a reboot of the remote resolves the problem as it seems to get stuck in that state (switch activity and get back to apple TV does not resolve the problem)

[albaintor]

EDIT : after about 10 minutes, the AppleTV commands worked again (without rebooting). I don't know what exactly unlocked the device : I switched activities (Apple => android => apple) but it didn't work, I went into integration configuration (without doing any modifications), I made a backup, and suddenly the Apple TV commands started to be processed

Here is a second logfile which has some overlap with the previous ones submitted with the commands processed correctly (no more "driver:Device is off, sending turn on command" message after that.
Some other hints for investigation line 696 of this second log file indicating that turn_on command failed :

ERROR:tv:[Salon Apple TV] Error Command _hidC failed occurred in method turn_on(

The latest "driver:Device is off, sending turn on command" is on line 628, then the next commands are processed. What happened between ? => there are several disconnection messages (due to the backup ?)
Anyway the AppleTV disconnects too "driver:Apple TV disconnected: F0:B3:EC:12:20:20" so that may explain why it works again like after a reboot where all drivers are reinitialized....
UCR2_logs_2024-03-09-second log with working commands again.zip

[albaintor]

Finally I have a complete log sequence here => please use this logfile which is shorter and narrows down the problem

1. Started Apple TV activity => commands are not processed during timing 12:01:46. => 12:03:44
2. At timing 12:05:35 (so 5 minutes after all these errors), the remote raises an "intg-appletv INFO ERROR:tv:[Salon Apple TV] Lost connection" and recreates the connection
3. Commands are processed correctly then

UCR2_logs_2024-03-09 (1).txt

[zehnm]

The Device is off, sending turn on command should only happen if the device is in standby with the white status led turned off.
But since you see the dashboard on your TV, there must be something wrong. I'll check your log file and double check the off-state detection.

[albaintor]

Hi Markus,
I don't know if it has an effect but in the code some methods in tv.py expect to return a ucapi.StatusCodes which is not the case :

Including the turn_on() method called by the UCAPI and returned then to the core. But this message indeed appears when the state is off "configured_entity.attributes[media_player.Attributes.STATE] == media_player.States.OFF" which is not the case.

[albaintor]

I may have the explanation but not 100% sure : when the state is OFF, you send a device turn_on command but returns to the caller without updating the state. So next time a button is pressed, it will get into the same case.

I think you should :

1. Call device.turn_on() if the state is OFF
2. Update the state to ON if previous call works correctly
3. Then process the requested command (because it is lost actually)

async def media_player_cmd_handler(
    entity: MediaPlayer, cmd_id: str, params: dict[str, Any] | None
) -> ucapi.StatusCodes:
...
# If the entity is OFF (device is in standby), we turn it on regardless of the actual command
    if configured_entity.attributes[media_player.Attributes.STATE] == media_player.States.OFF:
        _LOG.debug("Device is off, sending turn on command")
        return await device.turn_on()

I may have misunderstood as it is unclear to me how the state attribute is updated. Anyway as turn_on / turn_off won't return any state, it may be a conjunction of those 2 factors (no state returned by device.turn_on/off and no update of the state itself)

[albaintor]

I have submitted a pull request (not tested yet though, in progress...) #16

[zehnm]

I don't know if it has an effect but in the code some methods in tv.py expect to return a ucapi.StatusCodes which is not the case :

The return status code is handled with the @async_handle_atvlib_errors decorator: https://github.com/unfoldedcircle/integration-appletv/blob/v0.13.3/intg-appletv/tv.py#L62-L124

[henrikwidlund]

I'm having this issue, or a similar one as well. Only way for me to get it working again is to remove the device from the integration and add it again.

[albaintor]

I don't know if it has an effect but in the code some methods in tv.py expect to return a ucapi.StatusCodes which is not the case :

The return status code is handled with the @async_handle_atvlib_errors decorator: https://github.com/unfoldedcircle/integration-appletv/blob/v0.13.3/intg-appletv/tv.py#L62-L124

Ok so one part in my pull request is useless : the returned code is not read by the wrapper, only if exception occurs.
My modifications are still valid regarding the expected return code in the interface.

However the other part of my pull request is useful I think : it will let continue to process the command if turn_on() doesn't raise any exception. So that you won't loose the command. But I am not sure this will resolve the original problem (state remains OFF)

# If the entity is OFF (device is in standby), we turn it on regardless of the actual command
    if configured_entity.attributes[media_player.Attributes.STATE] == media_player.States.OFF:
        _LOG.debug("Device is off, sending turn on command")
        res = await device.turn_on()
        # Returns error code if turn_on fails
        if res != ucapi.StatusCodes.OK:
            return res

[zehnm]

The issue is with the entity state not being updated and then always thinks it's still off. Interestingly I haven't seen this issue while testing the integration during a few movie nights. But "works on my machine" is not an excuse :-) There's clearly something wrong with power state updates or state handling!
I'll try to release a quick fix asap with an actual check of the power state, then investigate the power state handling.

[albaintor]

This is strange, because I haven't changed my setup and AppleTV worked perfectly in the previous firmware, so maybe you could check after the changes that were made to narrow searches down. On my side this is 100% reproducible : each activity launch with apple tv (without rebooting the remote), the commands won't answer, and then after a few minutes it works again (reconnection seen in the logs). I have the impression though that the start sequence is processed because the apple tv wakes up

[zehnm]

The culprit is the following check (which is new in the release):

integration-appletv/intg-appletv/driver.py

Lines 158 to 160 in a7b5e82

	if configured_entity.attributes[media_player.Attributes.STATE] == media_player.States.OFF:
	_LOG.debug("Device is off, sending turn on command")
	return await device.turn_on()

with configured_entity.attributes[media_player.Attributes.STATE] holding an invalid state.
After the remote wakes up from sleep, the connection is re-established with the correct state.