Pyatv: After homeassistant restart pyatv/atv addon remote service no longer works.

[vandalon]

Describe the bug
After HA restart the remote service no longer works. I can not send commands and the remote service is set to off and I am unable to turn it on again until I reboot my apple tv.

To Reproduce

• Setup pyatv within homeassistant, confirm the remote service is working.
• Restart HA.
• See the remote entity change to off and when trying to turn it on again, it will go back to off
• restart ATV
• try turning on the remote entity (it could take a few seconds after reboot)
• everything should be working again.

Expected behavior
Remote entity should turn back to on after restart of HA.

System Setup (please complete the following information):

• OS: HassOS 3.11
  
  
  
  • Python: 3.7.6
  
  
  • pyatv: 0.4.0a16
  
  

Additional info
Logs:

2020-02-18 20:53:58 DEBUG (MainThread) [custom_components.apple_tv] Starting connect loop
2020-02-18 20:53:58 DEBUG (MainThread) [custom_components.apple_tv] Updating state: connected=False, disconnected=False
2020-02-18 20:54:00 DEBUG (MainThread) [custom_components.apple_tv] Updating state: connected=False, disconnected=False
2020-02-18 20:54:01 DEBUG (MainThread) [custom_components.apple_tv] Updating state: connected=True, disconnected=False
2020-02-18 20:54:01 DEBUG (MainThread) [custom_components.apple_tv] Changing address to 192.168.1.50
2020-02-18 20:54:01 DEBUG (MainThread) [custom_components.apple_tv] Connect loop ended
2020-02-18 20:54:51 DEBUG (MainThread) [custom_components.apple_tv] Not starting connect loop (False, True)
2020-02-18 20:59:11 DEBUG (MainThread) [custom_components.apple_tv] Not starting connect loop (False, True)
2020-02-18 21:01:07 DEBUG (MainThread) [custom_components.apple_tv] Not starting connect loop (False, True)

[vandalon]

It seems that the apple tv thinks te remote is still connected when this happens. (remote app pyatv is connected).

[postlund]

What is the media player saying? Based on what I see, the component is trying to establish a connection and that might take a while if there are problems finding the device. Can you enable the pyatv logs as well? The state on the remote will only turn on once the connection has been established.

[vandalon]

media player keeps working it's purely the remote part that stops working.
I waited for more then 24 hours but it will not start working again unless a restart atv.
I have pyatv debugging enabled. I will post some logs while testing soon.

[si458]

just a through, can u check the pyatv version AFTER you have restarted HA?

i have noticed on my pi setup,
i have to install pyatv 0.4.0a16 to get the latest support for my tvos 13 working
BUT after a restart of HA,
HA seems to install pyatv again but with a lower version and my appletv then stops working?

[vandalon]

in my case 0.4.0a16 is installed according to pip

[postlund]

Trying to figure out why this happens, not sure why yet. If you manage to get any logs that would help a lot!

[postlund]

@vandalon Is it possible for you to verify if this problem still exists with the latest version? I'm struggling with another issue where metadata stops coming (from what I see the TCP-connection more or less hangs). Just want to smoke out if there is a correlation between these bugs.

[vandalon]

I can check in a couple of days.

[postlund]

Perfect, thanks!

[vandalon]

Just removed the integration and reinstalled and repaired. Lets see how it goes :)

[vandalon]

I'm afraid the issue still exists.

[vandalon]

also media_player stoped in this case, it was still show progress for some tv show way over it's run time. (something like 155 minutes of 30)

[postlund]

Right, I kinda guessed that. Can you reproduce and include all the pyatv related logs as well (should appear before the lines you pasted in the initial message)?

[postlund]

If you have the possibility to dump the traffic between Home Assistant and the Apple TV that would be tremendously helpful as well. I believe it's hard to do on HassOS, you would need another computer on the network with possibility to tap into the traffic.

[vandalon]

i've added this to the config:

  logs:
    pyatv: debug
    custom_components.apple_tv: debug

and now we wait :)

[vandalon]

and also:

tcpdump -i eth0 -s 65535 host 192.168.1.50 -w /data/appletv.dump

should give you all traffic between homeassistant and the apple tv

[postlund]

Awesome, thanks! Will be interesting to see the results. What I have seen so far from two other users is that the Apple TV decides to close the connection but pyatv doesn't seem to get notified of this. So re-connection attempts are never made. Why it decides to close the connection is a mystery in itself, but not the biggest issue at hand.

[vandalon]

can i sent you the log and tcpdump output privately? I don't want to share all that on the internet ;)

[postlund]

@vandalon Absolutely! You can see my email if you go to my profile page.

[vandalon]

Done :)

[postlund]

Perfect, I got them! Thanks 😊 Will have a look on Tuesday and get back to you here!

[postlund]

So, I've taken a look and made an initial analysis. By the looks of it, this is not the same issue as I've seen before where the Apple TV closes the connection at some seemingly random point. Here the connection seems to still be open.

The last message received from the device is this one

2020-04-11 20:52:17 DEBUG (MainThread) [pyatv.mrp.connection] << Receive: Protobuf: type: SET_STATE_MESSAGE

Which seems to be consistent with the time you mentioned in your email (it's artwork for something). After this the Apple TV component/pyatv is quite until 21:59:17:

2020-04-11 21:59:17 DEBUG (MainThread) [pyatv.mrp] Retrieved artwork 81130220 from cache
2020-04-11 21:59:20 DEBUG (MainThread) [pyatv.mrp.connection] >> Send (Data=0808122438663036333461322d396564622d346432362d613637652d31313865656331663533663320006a3e0a3c438922cf0802000000000000000000000100000000000000020000002000000003000000010000000000000001008600010000000000000001000000)
2020-04-11 21:59:20 DEBUG (MainThread) [pyatv.mrp.connection] >> Send (Encrypted=034fdeaa1dd05bb3f125097fd9375064dc15477272f8750f51bbdec7bbbe259081242ce80a4d8e9f6f2e87bdaa74c5b5fee3db5b576aabde28aeae248c71fa3ba336f87ba03f568ff1a460200f959fe8b33c141763780878a4a6bbf343a54fe8ec6ac8d6ed1286727a8ce59d59fa620e128f149e36305b1675da)
2020-04-11 21:59:20 DEBUG (MainThread) [pyatv.mrp.connection] >> Send: Protobuf: type: SEND_HID_EVENT_MESSAGE
identifier: "8f0634a2-9edb-4d26-a67e-118eec1f53f3"
errorCode: 0
[sendHIDEventMessage] {
  hidEventData: "C\211\"\317\010\002\000\000\000\000\000\000\000\000\000\000\001\000\000\000\000\000\000\000\002\000\000\000 \000\000\000\003\000\0...
}
2020-04-11 21:59:20 DEBUG (MainThread) [pyatv.mrp.connection] >> Send (Data=0808122435613730396631642d626562652d343532322d623033312d35333530343766616161363620006a3e0a3c438922cf0802000000000000000000000100000000000000020000002000000003000000010000000000000001008600010000000000000001000000)
2020-04-11 21:59:20 DEBUG (MainThread) [pyatv.mrp.connection] >> Send (Encrypted=9b589cb16002524dc0cacc60f74bae10b3bff9dd3514789c4ca9250fe0b11bb85b86540c33526526a3b9ae6fce5a27bae030359ae86212efa422ce7bbb942d46459ca18a432b860b5c6d4a3b3598f5a29f7a6aade381c15f19552fe538f439a9f444c70a7e45d8bb5a9579f96b8fa77b83c71bd12d30c8d8993c)
2020-04-11 21:59:20 DEBUG (MainThread) [pyatv.mrp.connection] >> Send: Protobuf: type: SEND_HID_EVENT_MESSAGE
identifier: "5a709f1d-bebe-4522-b031-535047faaa66"
errorCode: 0
[sendHIDEventMessage] {
  hidEventData: "C\211\"\317\010\002\000\000\000\000\000\000\000\000\000\000\001\000\000\000\000\000\000\000\002\000\000\000 \000\000\000\003\000\0...
}
2020-04-11 21:59:20 DEBUG (MainThread) [pyatv.mrp.connection] >> Send (Data=0808122431396561323161622d396434392d346235302d626363332d37313037383862396230326220006a3e0a3c438922cf0802000000000000000000000100000000000000020000002000000003000000010000000000000001008600010000000000000001000000)
2020-04-11 21:59:20 DEBUG (MainThread) [pyatv.mrp.connection] >> Send (Encrypted=f68707e9c6a8a7f55c836d9d037994714db202676e10b49d238a66b90746b177d320166eb9ed95ab815d8ee8a78c54cdbe0fdfb02e6b544e5dffae5ef94af322607cfe5818343e5d5dadbdd5964e9209f1c133b1ef81cbebc4804c5759d808a001f0abd048ccad64756edd17afb16f41d6e5d4adbfafffbc47e5)
2020-04-11 21:59:20 DEBUG (MainThread) [pyatv.mrp.connection] >> Send: Protobuf: type: SEND_HID_EVENT_MESSAGE
identifier: "19ea21ab-9d49-4b50-bcc3-710788b9b02b"
errorCode: 0
[sendHIDEventMessage] {
  hidEventData: "C\211\"\317\010\002\000\000\000\000\000\000\000\000\000\000\001\000\000\000\000\000\000\000\002\000\000\000 \000\000\000\003\000\0...
}
2020-04-11 21:59:21 DEBUG (MainThread) [pyatv.mrp.connection] >> Send (Data=0808122463356262656336622d356266382d343631312d396234322d34346261623237326164373020006a3e0a3c438922cf0802000000000000000000000100000000000000020000002000000003000000010000000000000001008600010000000000000001000000)
2020-04-11 21:59:21 DEBUG (MainThread) [pyatv.mrp.connection] >> Send (Encrypted=52b8d56e1a9d261d334cc159a020543474a1eb453ab46edc7864235c99a687cecec8ceac1c944544fa0f27a4a9d7dbe71eb680e7a9c06d5dda3fdd49ced9ed3b02eee8edc6fd2c291e0c35f096d35a90ee9939223501aa39d342906c2d52e578883408549c740158f62ac1f45731ddd46fceaba408b3a577f48e)
2020-04-11 21:59:21 DEBUG (MainThread) [pyatv.mrp.connection] >> Send: Protobuf: type: SEND_HID_EVENT_MESSAGE
identifier: "c5bbec6b-5bf8-4611-9b42-44bab272ad70"
errorCode: 0
[sendHIDEventMessage] {
  hidEventData: "C\211\"\317\010\002\000\000\000\000\000\000\000\000\000\000\001\000\000\000\000\000\000\000\002\000\000\000 \000\000\000\003\000\0...
}
2020-04-11 21:59:21 DEBUG (MainThread) [pyatv.mrp.connection] >> Send (Data=0808122439623830396262362d656636392d346533612d623833352d64366139393864373735346120006a3e0a3c438922cf0802000000000000000000000100000000000000020000002000000003000000010000000000000001008600010000000000000001000000)
2020-04-11 21:59:21 DEBUG (MainThread) [pyatv.mrp.connection] >> Send (Encrypted=d4a14d498dea02d55e9522eebc9c1e14a04861bc5195636990efdca6fb521f23b9414566155ce1d3c539a324c65d2342e1062d49b0238c67348be99ccd14dfce381717029e2ae93e4e70d4f7f76477085f1add2c12b842e9d80378f891250a89da80d81d8e3bcd9eb1d9c53325d268d917d953d12f732b8a35d7)
2020-04-11 21:59:21 DEBUG (MainThread) [pyatv.mrp.connection] >> Send: Protobuf: type: SEND_HID_EVENT_MESSAGE
identifier: "9b809bb6-ef69-4e3a-b835-d6a998d7754a"
errorCode: 0
[sendHIDEventMessage] {
  hidEventData: "C\211\"\317\010\002\000\000\000\000\000\000\000\000\000\000\001\000\000\000\000\000\000\000\002\000\000\000 \000\000\000\003\000\0...
}
2020-04-11 21:59:22 DEBUG (MainThread) [pyatv.mrp.connection] >> Send (Data=0808122465306566343362652d616630382d343837392d616437362d64373538653862363661303920006a3e0a3c438922cf080200000000000000000000010000000000000002000000200000000300000001000000000000000c004000010000000000000001000000)
2020-04-11 21:59:22 DEBUG (MainThread) [pyatv.mrp.connection] >> Send (Encrypted=d2e27aa6e75f5f02b165b298723762f9bbcdf52d2625503e16c9c98dcf992ec7e97983838f473f8068191ef4dff85a2ca65cc35cf576532b75db5f9d734a92bce6eff82d26a6c3c242fb8acbbf4d0303459d2c54563c853f2a0467b14783adac63b4fd7b108a588fdedb207213175729793e0ff77b873753d0a7)
2020-04-11 21:59:22 DEBUG (MainThread) [pyatv.mrp.connection] >> Send: Protobuf: type: SEND_HID_EVENT_MESSAGE
identifier: "e0ef43be-af08-4879-ad76-d758e8b66a09"
errorCode: 0
[sendHIDEventMessage] {
  hidEventData: "C\211\"\317\010\002\000\000\000\000\000\000\000\000\000\000\001\000\000\000\000\000\000\000\002\000\000\000 \000\000\000\003\000\0...
}
2020-04-11 21:59:22 DEBUG (MainThread) [pyatv.mrp.connection] >> Send (Data=0808122462393035303161642d623138312d343266332d616537332d39363633396538646664373120006a3e0a3c438922cf080200000000000000000000010000000000000002000000200000000300000001000000000000000c004000010000000000000001000000)
2020-04-11 21:59:22 DEBUG (MainThread) [pyatv.mrp.connection] >> Send (Encrypted=c441f43c22c6f34fb34efd03d25f2905182ec72dea3e367ae5fe9fe1853a06929a01da038d4f14a3f7b6974874bdba8c023d35ebf211ba39878f33e477fe7c8f96f26e19dffa3d5578ab0de7e2e58a1ba72fa0fdc5fe4e3cb2b95976b2be60824cbf82fba7b20db2c0a290d4adde749a0733dd174871c31e63aa)
2020-04-11 21:59:22 DEBUG (MainThread) [pyatv.mrp.connection] >> Send: Protobuf: type: SEND_HID_EVENT_MESSAGE
identifier: "b90501ad-b181-42f3-ae73-96639e8dfd71"
errorCode: 0
[sendHIDEventMessage] {
  hidEventData: "C\211\"\317\010\002\000\000\000\000\000\000\000\000\000\000\001\000\000\000\000\000\000\000\002\000\000\000 \000\000\000\003\000\0...
}
2020-04-11 21:59:22 DEBUG (MainThread) [pyatv.mrp.connection] >> Send (Data=0808122464303532313231622d383730392d343239632d623039372d33303430396134643261333420006a3e0a3c438922cf080200000000000000000000010000000000000002000000200000000300000001000000000000000c004000010000000000000001000000)
2020-04-11 21:59:22 DEBUG (MainThread) [pyatv.mrp.connection] >> Send (Encrypted=7d43af55e6334cd2a810b9ca8c1f632abb8f26ff813ec02c621e0bd3d346538fc7a97b11011c136c147b24f4cb29765398c02399c5a90edfa1a47f411c67c04780234a35418b17daaecea9daa127f28588317b8dcd6901ea4ddc7e4461a186b3678c281ccd77058b405c7c6e5294756276b069689ad1143b8033)
2020-04-11 21:59:22 DEBUG (MainThread) [pyatv.mrp.connection] >> Send: Protobuf: type: SEND_HID_EVENT_MESSAGE
identifier: "d052121b-8709-429c-b097-30409a4d2a34"
errorCode: 0
[sendHIDEventMessage] {
  hidEventData: "C\211\"\317\010\002\000\000\000\000\000\000\000\000\000\000\001\000\000\000\000\000\000\000\002\000\000\000 \000\000\000\003\000\0...
}

The first log probably comes from you opening the frontend or so and pyatv happened to have the artwork cached (so no communication here). After that a bunch of keys are pressed. Seems to be the menu button pressed five times and the home button three times, does this sound familiar? The peculiar thing however is that no responses are received from the device for these messages, BUT, according to the Wireshark logs these messages are received and ACK'ed by TCP which can be seen here:

So obviously the Apple TV receives these messages but doesn't respond to them and leaves the connection dangling for some reason. One interesting thing however is that waiting for a response but not receiving one results in an exception (TimeoutError or something similar). The timeout period is 5s and by the looks of it, that period has passed in the logs so they should be there. This means that exceptions are hidden or ignored somehow and this is something I have seen before as well. I haven't come around digging deeper into that yet, but I will. Because who knows what's happening under the hood if we don't get all error messages?

[postlund]

Ok, so, the asyncio.TimeoutError I mentioned seems to be suppressed by Home Assistant when making service calls. This code has however been re-written on dev, so they will be shown as expected from the next release of Home Assistant.

[vandalon]

Seems to be the menu button pressed five times and the home button three times, does this sound familiar?

Yeah that was me checking if it still works ;)

[vandalon]

Isn't it possible to build in some reconnect routine when one notices that data is not send back from apple tv?

[postlund]

It will re-connect whenever the connection is closed for some reason and I would expect it to be closed (at least at some point) if problems like this occur. Was hoping to not have to resort to dealing with connection problems this way, but it seems like I might have to in the end 😞

[tommyjlong]

Thought I would add, that I'm seeing this as well most of the time I have problems. To reiterate, pyatv is sending successfully, but not getting anything back (except TCP ACK).

I don't know if it matters, but I see that the first byte has a discrepancy between what the log says is being sent, and what tcpdump is saying is being sent:

2020-08-31 13:30:03 DEBUG (MainThread) [pyatv.mrp.connection] 192.168.3.34:42012<->192.168.3.64:49152 >> Send (Encrypted=01e49749de2445c5541803a645bc8154da7592fa4ee81eaa778923cb9c097dc853fdf5efae3fe8b3027bad663b5f249d143aefc3ec5420a883b76ef8a0f773a5584be218cbbb73a8bec976bab9bf9ade4afecab3)

TCP Dump data:
5401e49749de2445c5541803a645bc8154da7592fa4ee81eaa778923cb9c097dc853fdf5efae3fe8b3027bad663b5f249d143aefc3ec5420a883b76ef8a0f773a5584be218cbbb73a8bec976bab9bf9ade4afecab3

[postlund]

@tommyjlong Is it easy for you to replicate with reasonable precision? What I really need are logs from the Apple TV (as stated in #812), but since I can't reproduce it myself I do need some help. So, if you can reproduce, own a Mac and have some free time it would be very appreciated!

Each packet is prepended with the payload size (encoded as a variant in protobuf, see VLQ on Wikipedia or so). Since 0x54 is strictly less than 128, it means that the payload size is 84 bytes. Did not verify, but could be the case.

[tommyjlong]

I gave Xcode a try tonight and got it paired with my AppleTV and brought up the "Console" window and I'm getting Console messages from my AppleTV. I can further filter these on mediaremoted, so when using HA/pyatv to send remote commands (pyatv was operating normally at this time), I get mediaremotedmessages that pop up on the console :)

My pyatv failures start happening anywhere from 0 to 2 days of usage after a reboot of HA, and since I rebooted earlier today, I anticipate seeing the failure tomorrow or the next day. Since I don't know anything about iOS development/environment, I may need some guidelines as to what to look for, or do next. I'll keep the console logs running for now.

[tommyjlong]

The failure occurred this morning. I checked the Xcode console, and unfortunately there were no messages from mediaremoted. Pyatv logs show that messages were sent without error, but nothing received. tcpdump showed likewise that pyatv sent the messages but no message was returned from the AppleTV. Any guidance for what else to look for in the Xcode console logs?