Pyatv: Hassio suddenly doesn’t recognize Apple tv

[dadeboni]

What's on your heart?
Hassio every couple days stops recognizing the state of Apple TV. A restart of hassio fixes the issue. Is this a bug?

[postlund]

It might be, but I need some logs in order to say anything. Do you see anything in the logs at all?

[Kugelfang666]

I had the same problem. Out of nowhere it started to constantly (every few minutes) drop the connection. Switching the Apple TV „off“ and back „on“ from within Lovelace made it work again for a few minutes. Finally, removal an reauthenticating the Apple TV solved this for me

[postlund]

@Kugelfang666 Do you have any log entries from when this happened?

[Kugelfang666]

no, unfortunately I restarted HA afterwards but I'll make sure to get the log in case this happens again

[postlund]

That would be perfect, will be hard to debug without any logs.

[Kugelfang666]

ok this just happened again but I cannot find anything relevant in the log file. The Apple TV still shows up in the GUI but its not responsive and it does not reflect the status of the device any longer. It ist frozen in the last state when in lost connection. Any idea on how I can provide you with more details?

[dadeboni]

Did you add the debug logger in your config file? I just added it this morning so if I notice the issue tonight I’ll see if I can find anything relevant.

[Kugelfang666]

no I did not, how do I do that?

[dadeboni]

Debug logs

If you run into problems, please (please, please) make sure you include debug
logs. It is really hard to debug without them. You enable them like this:

logger:
  logs:
    pyatv: debug

Forgive me if the spacing is messed up I am typing this on mobile

[postlund]

I fixed the formatting. But yeah, enabling debug logs will help.

[postlund]

@Kugelfang666 @dadeboni Have any of you been able to reproduce this with latest version of the component? Made a bunch of bug fixes. If you have, can you try to provide some logs?

I'm getting close to finishing 0.4.0, so I'm trying to sort out all open bugs related to the milestone. Don't feel any pressure, it's not that urgent. But would help to get some input soon-ish if possible.

[dadeboni]

@postlund i upgraded to the latest version of the beta and knock on wood, I haven’t had an issue since.

_{Sent with GitHawk}

[postlund]

@dadeboni Great! Let's give it a few more days and see what happens.

[matt8707]

Installed: c5b5d48

I have this issue on and off as well. I enabled logs and the log file quickly grew to about 15mb. Of course during this no problems arose until I removed logging...

If I run in to it again, should I just dump the full logs here, no matter the size?

Maybe off topic. But I may be seeing performance issues with the artwork. Youtube seems to run fine but when I run Infuse the whole UI freezes until the artwork is displayed. Sometimes over 5 seconds.

[postlund]

@matt8707 You can just dump parts of the log if you want (or share via some other upload site, Google drive, etc). One problem is that artwork is dumped to log (in hex) as well as received data chunks. So it tends to be quite heavy.

Do you see the UI freeze even without the logs enabled?

[matt8707]

Yes, even without logging enabled.

I don’t really know what to strip out so I may as well post a gdrive link sometime this week.

[postlund]

Ok, good to know!

Sure, that will be good. Having everything hopefully simplifies things.

[postlund]

So, I've had a look at the log and the conclusion I have is that artwork is the culprit. It is fetched from device everytime the frontend wants to render it (which is quite often it seems). Some times it re-renders while waiting for the previous artwork, so there might be multiple requests lingering too. Chances are that this is quite heavy. What I need to do is this:

1. Add a local cache for fetched artwork. Ideally this cache would be persistent on disk (since there is a unique identifier for artwork), but I don't have a concept of persistent data in pyatv yet. So that will be an improvement later.
2. Limit fetching to one worker at the time. If someone requests artwork while someone else already fetching it, the first one should wait and just fetch artwork from cache when its done.
3. I shall also update media_image_hash in the component to actually use the image hash as well. When writing this I actually do see the main problem here. When starting to play something, MRP does a lot of things (changing state multiple times for various reasons) that triggers push updates which in turn trigger state changes in Home Assistant. Since this image hash currently depends on "what is playing", chances are that the hash chanages between multiple values until everything is done. This would be the reason for fetching artwork multiple times.

I will focus on 1 and 3 since they are easier and give most benefits.

Another thing I noticed in the log was some weird print outs. A field in one of the messages was repeated over and over, which should not be possible. Most likely a protobuf buf.

[postlund]

I have added a simple LRU cache in #404. Just have to test a bit with a real device to see that it works as expected. Will also have to fix 3 to match this, otherwise little benefits.

[postlund]

@matt8707 I have pushed an update to the component now, it should hopefully fix your issue.

@dadeboni Do you still see your initial issue? Maybe you can try the latest update and see if it is solved?

[postlund]

@matt8707 @dadeboni An even newer version of the component is out now, please try it out when you have a free slot!

[postlund]

This is the last issue tagged for 0.4.0 release and I intend to push a PR for the Home Assistant component today. Would be really good if I could get some progress here, otherwise I will close it and you can open a new issue in case problem still exists.

[dadeboni]

@postlund I have not had a single issue since the upgrade. Unless the other user has had problems, we can mark it as closed.

[postlund]

@dadeboni Awesome! I will close this issue then since I have side-channel contact (via mail) with @matt8707.