The is very interesting. Can you run atvremote manually, e.g. atvremote --debug ... playing, while having something playing and see what you get?
Good thing I debugged in the past quite a lot, otherwise it would have taken ages for me to realize to run this within the HA docker container 
Here is the log, hope this is the correct one: https://drive.google.com/file/d/19OraNhxivHxJUcRS5RC59Jlja1RQ02sl/view?usp=sharing
The eror above with the unclosed client session appears quite frequently it seems. But I am not sure whether it is connected to the component at all.
//edit - all while running a Netflix show.
That’s great, very quick response 
It looks good to me from what I can tell, if you remove the three … it should tell you what is actually playing, no?
Where did you see the “unclosed client session” message? I can’t find i.t
I ran it without … : https://drive.google.com/open?id=1sMkDQZcuiLjK3hnsV9vDzKlbFFErxaH_
looks like it shows Netflix playing.
So in general it is working, but HA doesn’t know about it. The “unclosed client session” only appears in home-assistant.log - I don’t know whether the ATV component is responsible though, could also be something else.
This is an issue that I was aware of, but it should have been fixed a long time ago. You mean you still see it?
Yes - I see it in my logs sometimes, but I am not sure whether it is caused by the ATV component or e.g. my Harmony Hub connection not being stable…
it only appears sometimes, but doesn’t necessarily correlate to when the ATV component is not working anymore. I at least can’t see a pattern.
I just reproduced the issue once more - it is definitely caused by the Apple TV shutting down. Afterwards, HA doesn’t understand that it wakes up.
I can of course not be 100% sure, but I did have another look at the code and I cannot see where I would leak the session. Theoretically it could only be when streaming with AirPlay, do you use that functionality?
Ok, so if you have HA and Apple TV up and running correctly and then shut off the Apple TV (hold home + suspend), then HA never recovers even after restart of Home Assistant? But atvremote still works?
I have not used Airplay while debugging.
Ok, so if you have HA and Apple TV up and running correctly and then shut off the Apple TV (hold home + suspend), then HA never recovers even after restart of Home Assistant? But atvremote still works?
Exactly - so once you see
2020-03-31 14:37:01 DEBUG (MainThread) [custom_components.apple_tv] Updating state: connected=True, disconnected=False
2020-03-31 14:37:01 DEBUG (MainThread) [custom_components.apple_tv] Changing address to 192.168.178.90
2020-03-31 14:37:01 DEBUG (MainThread) [custom_components.apple_tv] Connect loop ended
after the Apple TV shuts off, HA is not updated anymore and one needs to remove the integration and add it again to get it working.
atvremote shows results when run in the HA docker container.
And just to be abundantly clear: restarting the Apple TV and/or Home Assistant in any combinations won’t make the integration recover? You must remove it and add it again?
Not exactly, this is what I tested:
- Integration seems broken
- Restart HA, Apple TV OFF - last thing in logs:
2020-03-31 17:17:18 DEBUG (MainThread) [custom_components.apple_tv] Updating state: connected=True, disconnected=False
2020-03-31 17:17:18 DEBUG (MainThread) [custom_components.apple_tv] Changing address to 192.168.178.90
2020-03-31 17:17:18 DEBUG (MainThread) [custom_components.apple_tv] Connect loop ended
- Start Apple TV --> Logs don’t change
- Start Netflix series --> Logs don’t change, entity still idle.
- Restart Apple TV --> Logs change, end with message from above, but as soon as I start Netflix, logs change again entity is marked as playing.
So a restart of the Apple TV fixed it
- Turning off Apple TV, logs end with:
2020-03-31 17:24:13 DEBUG (MainThread) [custom_components.apple_tv] Updating state: connected=True, disconnected=False
2020-03-31 17:24:13 DEBUG (MainThread) [custom_components.apple_tv] Changing address to 192.168.178.90
2020-03-31 17:24:13 DEBUG (MainThread) [custom_components.apple_tv] Connect loop ended
- Start of Apple TV immediately after: works fine
Honestly, I am out of ideas, it seems that shutting down the Apple TV doesn’t always break it, only sometimes (no matter whether it is manual or automatically), maybe it is also the time in between shutting down and turning on again…
At this point I would really like to look at the network traffic to see what is going on. Final resort would be to attach a debugger and see if that can provide any insights. But if you could run this (on the the same host as Home Assistant) and send me the log it would be great:
$ tcpdump -w traffic.pcap "host 1.2.3.4"
Replace 1.2.3.4 with IP adress of your Apple TV.
Thanks for not giving up.
Here you can find the pcap file: https://drive.google.com/open?id=1B6T77ipwmkh7XU23nQc2MQlrN1-1psRA
The integration seems currently “broken”. atrvremote is showing results though.
Let me know if this helps or if I can support in any other way.
I will never totally give up until it is solved Saw a similar thing in another issue where the Apple TV decided to just close the connection, it kinda looks like that here as well:
It would be interesting to know why it is doing that and why pyatv doesn’t seem to be notified about this. Here I currently don’t have many ideas I’m afraid. Best case would of course be that the connection is never closed, but not recovering from it is not good.
@SteWi I added some extra logging and a periodic task that sends a message to the Apple TV and awaits response. Hopefully this can help us track this down. It is released as 0.5.1a0, so if you change manifest.json to point to that version and restart, then hopefully you should see spammy logs like these every ten seconds:
2020-04-09 12:22:22 DEBUG: Sending periodic ping (transport: <_SelectorSocketTransport fd=8 read=polling write=<idle, bufsize=0>>)
2020-04-09 12:22:22 DEBUG: >> Send (Data=0826122462656566306438622d616238612d343137362d626362392d6464306436336136306261352000d202020802)
2020-04-09 12:22:22 DEBUG: >> Send: Protobuf: type: SET_CONNECTION_STATE_MESSAGE
identifier: "beef0d8b-ab8a-4176-bcb9-dd0d63a60ba5"
errorCode: 0
[setConnectionStateMessage] {
state: Connected
}
2020-04-09 12:22:22 DEBUG: << Receive (Data=2a0800122462656566306438622d616238612d343137362d626362392d6464306436336136306261352001)
2020-04-09 12:22:22 DEBUG: << Receive: Protobuf: type: UNKNOWN_MESSAGE
identifier: "beef0d8b-ab8a-4176-bcb9-dd0d63a60ba5"
errorCode: 1
2020-04-09 12:22:22 DEBUG: Got answer to ping, sleeping...
Might be excessive with every ten seconds, lets see if we have to change that.
Hey @postlund,
I did the change and this is really weird from my point of view - maybe not from yours though. Here is what I did and how the logs reflect that:
- Changed manifest.json
- Started tailing the home-assistant.log
- Restart HA
- Start Apple TV
The log just stops once I started the Apple TV - basically the last line you see in the log, it hasn’t “recovered” since - no matter what I played or whether I shut off the Apple TV … maybe my Apple TV is just broken and breaks everything once it starts or goes to sleep …
Log file: https://drive.google.com/open?id=1JAM2C1EbLSEo2SabU9hKwwXRtwogCqNf
This is really, really weird. Looking at this part (last in file):
2020-04-09 14:27:04 DEBUG (MainThread) [pyatv.mrp.protocol] Starting periodic ping
2020-04-09 14:27:04 DEBUG (MainThread) [pyatv.mrp.protocol] Sending periodic ping (transport: <_SelectorSocketTransport fd=37 read=polling write=<idle, bufsize=0>>)
2020-04-09 14:27:04 DEBUG (MainThread) [pyatv.mrp.connection] >> Send (Data=0826122430653636613263322d396434652d346665662d386133312d3665333261343039373539652000d202020802)
2020-04-09 14:27:04 DEBUG (MainThread) [pyatv.mrp.connection] >> Send (Encrypted=ae80a99b4c1cd2430a996963ec6d33bc3132899a875da8fc6422651d2ac4feb16625b4e1a115ff2d29ab19800d8ce74d0b7099655cde256cba988ec5c59722)
2020-04-09 14:27:04 DEBUG (MainThread) [pyatv.mrp.connection] >> Send: Protobuf: type: SET_CONNECTION_STATE_MESSAGE
identifier: "0e66a2c2-9d4e-4fef-8a31-6e32a409759e"
errorCode: 0
[setConnectionStateMessage] {
state: Connected
}
2020-04-09 14:27:04 DEBUG (MainThread) [pyatv.mrp.connection] << Receive (Data=3ac723aef46005e26504b0b4a8e879569b4511bfc77c618c659ae70941542cf8f4ae6f11399438db888dc6e41932545c8c489bff7db31215ed9065)
2020-04-09 14:27:04 DEBUG (MainThread) [pyatv.mrp.connection] << Receive (Decrypted=0800122430653636613263322d396434652d346665662d386133312d3665333261343039373539652001)
2020-04-09 14:27:04 DEBUG (MainThread) [pyatv.mrp.connection] << Receive: Protobuf: type: UNKNOWN_MESSAGE
identifier: "0e66a2c2-9d4e-4fef-8a31-6e32a409759e"
errorCode: 1
2020-04-09 14:27:04 DEBUG (MainThread) [pyatv.mrp.protocol] Got answer to ping, sleeping...
2020-04-09 14:27:10 DEBUG (MainThread) [pyatv.mrp.protocol] Sending periodic ping (transport: None)
So, here the connection hast just been established and initial “flow” finished. The “ping” task is started and one ping (setConnectionStateMessage) is sent and answer is received. When sending the next ping, the underlying “transport” is for some reason None. You see that in the last line. This has happened without any apparent reason. pyatv only sets this to None being disconnected. And oh, when writing this I can see that the correct ping is sent a bit further down in the file. So, my new theory is that there are dangling connection instances that are never really removed. That could explain the strange behavior and I will have to look into this. Great finding at least!
One more thing I’m curious about is that no exceptions are printed to the log here. You should get an exception case when transport is None and one timeout and the end (because no answer is received). So perhaps there are another exception hidden somewhere that we don’t see, that is the main reason for all of this. Something additional I can look in to!
Hey @postlund,
have you had time to further look into this? Anything I else I can do to support?
Cheers
Stefan
@SteWi Not yet unfortunately. I’m not sure what’s happening and I have a hard time reproducing myself, so quite lost. I’m all ears for ideas on troubleshooting.
Hi @postlund i don’t know when this is happen, but with latest TVOS when you use stop and go back to overview (Netflix) the state in HA stay at “paused” instead of idle.