There is a mediaSubtype field that could potentially include that info, but I have only seen it set a few times with “wrong” value (which I guess means that the app provides the wrong value). It might be possible to request additional information and draw some conclusions from that, but I will have to investigate. Feel free to write an issue about it as a reminder to me!
I will do that. And let’s hope this will work maybe
Just stubbed across this custom component - thanks!
At last I have my 4 Apple TVs working again in HA.
Not played around too much, but they seem to behave as expected.
mb
Yes, i hopp so too
created a feature request #383
hey @postlund I was finally able to install the custom component and the integration works! Thx for all the work.
Just wondering about the power management ( on / off ), if any news on that is on the horizon?
Great to hear I submitted a PR for inclusion of it into Home Assistant yesterday, so it will soon be included by default.
I don’t actively work on that, but another user has shown interest in trying to implement experimental support for it (see https://github.com/postlund/pyatv/issues/454). It will however be based on “pressing buttons” to put the device to sleep, so it will likely not be 100% reliable. But probably good enough. The issue where restarting Home Assistant wakes devices up if CEC is used will still be present. No solution in sight for that.
Hey @postlund ,
thank you very much for all the work you put in to create the custom component and it being so close to be included into HA.
After switching to HA some time ago I came across the Apple TV integration and since I am already on tvOS 13, the official integration did of course not find my Apple TV. After some research I found your custom component and with it, I was able to integrate my Apple TV and HA.
The problem is that the integration works for a time and then randomly stops working. I have been trying to pin down the issue, reading quite a lot in your repo and here, but cannot figure it out myself.
Looking at the debug logs, the connection “breaks” a lot of times after seeing this (but I am not sure if this is the only case):
2020-03-09 21:02:06 DEBUG (MainThread) [custom_components.apple_tv] Updating state: connected=True, disconnected=False
2020-03-09 21:02:06 DEBUG (MainThread) [custom_components.apple_tv] Changing address to 192.168.178.90
2020-03-09 21:02:06 DEBUG (MainThread) [custom_components.apple_tv] Connect loop ended
Before that, everything works perfectly - sending commands to the Apple TV and receiving all the updates - I can follow everything in the debug logs and on HA.
After it stops working, the Apple TV shows up as idling in HA, the remote is “on”. I don’t see any action in the debug logs anymore, nothing is received and also commands that are supposed to be sent to Apple TV are not logged.
I have not used HASS to integrate the component as I am running standard HA via docker.
Any idea how I can dig deeper to find out the root cause?
Thank you very much in advance!
Stefan
This problem I never seen since first try outs it work correct here.
Hi @SteWi!
Thanks for testing And yes, this is a somewhat known issue that a few people seems to experience. I have not yet found the cause for it. I’m starting to suspect some kind of race-condition or something. Would be very interesting to see more with debug logs for pyatv
enabled as well (pyatv: debug
in logger
).
How often do you see the log print outs above? Do you see any state changes with disconnected=True
? The mentioned logs are actually exactly what you should see when everything works as expected and a new connection has established. When opening a new connection (turning on either the media player or remote entity), a new background task is launched. This task will try to establish a new connection repeatedly until it succeeds, adding some sleep between each attempt and applying exponential backoff to not hammer too much. Once a connection has been established, the task is gracefully terminated. This is what the last log means: Connect loop ended
. It refers to the loop that tries to connect inside the task.
One interesting idea to test is to reboot the Apple TV when you are in this situation, to see if connection_closed
is called.
So, the big question is what pyatv
is up to in the background. If any problem occurs, this should be reported back to the component (connection_lost
/connection_closed
), but if you don’t see any disconnects, that doesn’t happen.
Hey @postlund,
wow - thanks for getting back so quickly
I have just restarted HA and this is the complete log from apple_tv and pyatv. Unfortunately, the log is quite huge and I wasn’t able to attach it to this post. As far as I can tell, I can only add images to the post and no other files - that’s why I uploaded it to my Drive: https://drive.google.com/open?id=1VDSSbkWIi6LoT8uiE7oSZy4tyag6BRNP
The log basically ends with the exact same entry after a clean restart. The Apple TV is marked as idle in HA and no info about any playing app (I tried Netflix, Prime) is shown in HA nor the logs.
As suggested by you, I restarted the Apple TV - again, nothing changes in the logs after restart and starting of playing.
I hope this helps!
Thanks for looking into this.
@SteWi Gotta go fast I think a blue hedgehog once said
Hmm, I don’t really see anything strange in the log. After the first successful connection attempt, the device decides to disconnect after about 18s:
2020-03-09 21:58:53 DEBUG (MainThread) [custom_components.apple_tv] Updating state: connected=True, disconnected=False
2020-03-09 21:58:53 DEBUG (MainThread) [custom_components.apple_tv] Changing address to 192.168.178.90
2020-03-09 21:58:53 DEBUG (MainThread) [custom_components.apple_tv] Connect loop ended
2020-03-09 21:59:11 DEBUG (MainThread) [pyatv.mrp.connection] << Receive (Data=3fa558e6dfaedc79144b7d1fec7969ad78d3f88089eacfdf9f3bfed4b88ac7620c1c3b788be2144602a0dfd99968f8dd53fae9350b339bf27291c5d13e5ea647)
2020-03-09 21:59:11 DEBUG (MainThread) [pyatv.mrp.connection] << Receive (Decrypted=0826122433324634413739432d303944452d344531322d423842372d4241463135373234303938382073d202020803)
2020-03-09 21:59:11 DEBUG (MainThread) [pyatv.mrp.connection] << Receive: Protobuf: type: SET_CONNECTION_STATE_MESSAGE
identifier: "32F4A79C-09DE-4E12-B8B7-BAF157240988"
priority: 115
[setConnectionStateMessage] {
state: Disconnected
}
2020-03-09 21:59:18 DEBUG (MainThread) [pyatv.mrp.connection] Disconnected from device: None
2020-03-09 21:59:18 DEBUG (MainThread) [custom_components.apple_tv] Updating state: connected=False, disconnected=True
The connection is re-established again and get stuck where you mention. I will have to think about this a bit more.
@postlund thanks for your feedback. Let me know if I can do anything else for helping debug this!
//update - I installed the component through HACS now (had added it manually before) and it is the same picture.
Just to keep this updated - I am running HA 0.107.4 with the latest component version and still the same odd behavior.
That’s strange, I was hoping it was solved by now. I’ll have to dig deeper yet again.
One interesting thing is the field called “priority” in my previous log, it is actually an error code (something I’ve had wrong in my definitions for a long time). Unfortunately I haven’t been able to decode these fully yet, so I don’t know what it means. But it could shed a little bit of light at least, if it could be decoded.
So, hmm, I’m getting a bit crazy about the behavior here and I really want to understand what is going on. It would be really great if you could reproduce this with full logs enabled (like you have before) and also note down what action you are taking and when (timestamp). Unless I know that you for instance rebooted the device at 12:02:45, then I have no idea how correlate to the logs (since the logs seems to be incomplete). Same goes for playing something in apps for instance. Would be really, really great if we could smoke this out for good!
Just to re-iterate the previous log. What I can see is that the device sets the “disconnected” state, wich maybe correlates to when you restarted the device? If that is the case, then it is a good thing. Based on the other entries in the log, the device never sends setNowPlayingClient
, which indicates that no media player is playing anything. There is metadata available for both Netflix and Prime Video, matching what you were watching.
Hey @postlund,
thanks for further looking into this - really appreciate it.
Here is the logfile: https://drive.google.com/open?id=1sYXBz3EFUEQrCHa0xRFgpVa-epMMj0pl
These are my notes:
Logs
13:31:22 - Remove Integration
13:31:40 - Add integration (Apple TV is showing Netflix right now)
13:34:44 - Continue Netflix
13:35:57 - Playback paused
13:36:29 - Using Logitech Harmony, Activity stopped (Apple TV light is still on, TV is off)
13:38:10 - Using Logitech Harmony, Activity started
13:39:30 - Prime Video TV series started and immediately paused
13:40:20 - returned to Apple TV Home screen
13:40:43 - Using Logitech Harmony, Activity stopped (Apple TV light is still on, TV is off)
14:10:51 - Apple TV turned off
14:22:00 Activity started, Apple TV turned on (still showing idle in HA)
14:22:30 Netflix started and running (still showing idle in HA)
It seems the component is not “recovering” after the Apple TV shuts itself off.
This is what HA sees:
Between the two “idle” states is “unknown”
Hope this helps!
Let me know if you need anything else.
@SteWi Thanks for the really good presentation of the logs, awesome!
Looking a the logs, it looks like it when the Apple TV is turned off at 14:10:51, it acts accordingly. pyatv is notified of the shutdown restarts the connect loop to establish a new connection. This is the natural flow as the integration will try to maintain a connection at all time as long as it is “on”.
The connection succeeds by the look of it, but then the log is completely empty. Nothing more happens and I really don’t understand why. Does Home Assistant continue to function properly after this?
Yes, everything is working fine as before as far as I can tell.
If I restart Home Assistant while the Apple TV is off the same behavior is happening, the log basically ending with the same as before.
//edit - should I maybe add additional logs to see whether something is going on outside of pyatv?
//edit 2 - I added warn level logging and when I start the Apple TV after it was shut down, I see the following in logs:
ERROR (MainThread) [homeassistant.core] Error doing job: Unclosed client session
I was mentioned here (https://github.com/home-assistant/core/issues/30081) that this might be related to the component?