pyatv 🚀 - atvscript stops push updates

This sounds very much like what people are reporting with Home Assistant, where the integration stop working after a while. Not sure why this happens or background. I'm gonna make a stress test and see if I can see any patterns.

postlund on 30 Mar 2020

I’m saving a full output of the script on 2 ATV’s to text file. I’ll let you know if I see anything abnormal when the updates stop.

crxporter on 30 Mar 2020

👍1

@crxporter When you end up in this situation, it would be very interesting if you could run wireshark or tcpdump while zapping between some content. That would help figuring out if the Apple TV stops sending data or if something is wrong at the receiving end.

postlund on 30 Mar 2020

Oh, and one more thing to continue the spamming... Are you running the script in a docker container or not? Do you have a "special" network setup in any way?

postlund on 30 Mar 2020

I don't know anything about wireshark or tcpdump. I can look into it though.

Network setup is nothing special. Node red is running as a system service, the output appears identical whether I run atvscript as I am or just in command line on the pi (no docker). The whole network is open, Apple TVs and Pi are all wired ethernet on the same subnet.

Current status: been running 12 hours, everything still fine.

crxporter on 30 Mar 2020

Just had the error again. Here is the output leading up to the stopped messages:

{"result": "success", "hash": "com.apple.avkit.2509.dbd3c139", "media_type": "video", "device_state": "playing", "title": "How I Met Your Mother | S8 E2 - The Pre-Nup", "artist": null, "album": null, "genre": null, "total_time": 1300, "position": 0, "shuffle": "off", "repeat": "off", "app": null, "app_id": "com.hulu.plus"}
{"result": "success", "hash": "com.apple.avkit.2509.dbd3c139", "media_type": "video", "device_state": "playing", "title": "How I Met Your Mother | S8 E2 - The Pre-Nup", "artist": null, "album": null, "genre": null, "total_time": 1300, "position": 0, "shuffle": "off", "repeat": "off", "app": null, "app_id": "com.hulu.plus"}
{"result": "success", "hash": "com.apple.avkit.2509.dbd3c139", "media_type": "video", "device_state": "playing", "title": "How I Met Your Mother | S8 E2 - The Pre-Nup", "artist": null, "album": null, "genre": null, "total_time": 1300, "position": 416, "shuffle": "off", "repeat": "off", "app": null, "app_id": "com.hulu.plus"}
{"result": "success", "hash": "com.apple.avkit.2509.dbd3c139", "media_type": "video", "device_state": "playing", "title": "How I Met Your Mother | S8 E2 - The Pre-Nup", "artist": null, "album": null, "genre": null, "total_time": 1300, "position": 1199, "shuffle": "off", "repeat": "off", "app": null, "app_id": "com.hulu.plus"}
{"result": "success", "hash": "com.apple.avkit.2509.dbd3c139", "media_type": "video", "device_state": "playing", "title": "How I Met Your Mother | S8 E2 - The Pre-Nup", "artist": null, "album": null, "genre": null, "total_time": 1300, "position": 1278, "shuffle": "off", "repeat": "off", "app": null, "app_id": "com.hulu.plus"}
{"result": "success", "hash": "ca496c14642c78af6dd4250191fe175f6dafd72b4c33bcbab43c454aae051da1", "media_type": "unknown", "device_state": "idle", "title": null, "artist": null, "album": null, "genre": null, "total_time": null, "position": null, "shuffle": "off", "repeat": "off", "app": null, "app_id": null}

All seems pretty normal. The last two messages were right at the end of a show clicking the "home" button on the apple remote (regular remote, not the remote app or anything paired to the TV). The output was normal - the previous message was "playing" then the "idle" message of the home message.

After this the TV was turned off, the {"power_state":"off"} message did not come in. I did atvscript scan which worked as normal.

The atvscript process was still running, no error messages were returned.

After restarting the process (killed with sigterm then restarted with CLI) the {"power_state":"off"} and idle play state came in as expected.

Things ran properly for about 22 hours and look like they died as I held "home" and clicked "sleep" on the apple tv.

crxporter on 31 Mar 2020

Just looked at some time stamps from my files. Looks like it ran for right around 27 hours. Plus or minus a half hour.

crxporter on 31 Mar 2020

Very interesting. We can probably assume that data stops coming. As mentioned earlier, would be nice to look at the network traffic to see if it also stops. You can record the traffic with tcpdump. Short guide would look like this (assuming some debian based system):

Install tcpdump: sudo apt install tcpdump
Get port used: atvremote scan -> extract MRP port, e.g. 49152
Start tcpdump: sudo tcpdump -w output.pcap "port 49152"

This should save the communication to output.pcap, which you can look at with wireshark for instance. Said file would be very interesting for me when the situation happens.

postlund on 31 Mar 2020

Is tcpdump something that should run continuously for a day or two? Or just run it once when I notice atvscript stopped?

crxporter on 31 Mar 2020

Yeah, it should be run until the error happens to make sure everything is captured. Shouldn't be that much data in theory, although artwork might take some additional space. You can send it via email to me if you like or share via google drive or similar.

postlund on 31 Mar 2020

Cool, I’ll get it started (once per tv if they’re on different ports) for the next crash.

crxporter on 31 Mar 2020

Awesome, thanks! 👍

postlund on 31 Mar 2020

Is it important for tcpdump to be running on the same computer as pyatv?

I put one of my unused pi's on tcpdump duty while running atvscript on my main pi then wondered if that will work.

Edit: no. I’ll get it all on the same pi.

crxporter on 31 Mar 2020

It depends on the network setup and your equipment. Some (most?) switches nowaday does not send traffic to all ports with a promiscous user. So you need to configure the switch for that. For WiFi devices it's usually not possible. So I would say that you need to run it on the same device.

Also, make sure that you "do something" on the Apple TV once you end up in this situation to trigger som additional traffic. We want to see if the traffic stops coming or if it still comes, but is not delivered to the application.

postlund on 1 Apr 2020

I’m coming up on the 24 hour mark with tcpdump running. I’ve been checking both TVs every 4 to 6 hours or so.

Still both working as expected at this point. Two instances of tcpdump are running, one for each ATV port.

Stand by, maybe they’ll break today?

crxporter on 1 Apr 2020

Took a few days but I have some more information. One atvscript is still running great. The other has stopped.

TL/DR: The port changed

I've been running tcpdump on both for a couple of days. I also ran atvscript scan repeatedly.

Here's my report:
I'm working with 2 apple tv's. One at 10.11.11.1 and the other at 10.11.11.2.

Here is the output of atvscript scan from the last few days. Note all ports stayed the same until the last scan. The line before the JSON output is a timestamp.

1585654564810
{"result": "success", "devices": [{"name": "Master TV", "address": "10.11.11.2", "identifier": "5C7DCD07-E8DB-41E3-BCEB-F54480A5163F", "services": [{"protocol": "mrp", "port": 64192}]}, {"name": "Theater TV", "address": "10.11.11.1", "identifier": "F487AF2D-23E3-433B-80C8-D7306F03191B", "services": [{"protocol": "mrp", "port": 56486}]}]}
1585654676024
{"result": "success", "devices": [{"name": "Theater TV", "address": "10.11.11.1", "identifier": "F487AF2D-23E3-433B-80C8-D7306F03191B", "services": [{"protocol": "mrp", "port": 56486}]}, {"name": "Master TV", "address": "10.11.11.2", "identifier": "5C7DCD07-E8DB-41E3-BCEB-F54480A5163F", "services": [{"protocol": "mrp", "port": 64192}]}]}
1585662987171
{"result": "success", "devices": [{"name": "Master TV", "address": "10.11.11.2", "identifier": "5C7DCD07-E8DB-41E3-BCEB-F54480A5163F", "services": [{"protocol": "mrp", "port": 64192}]}, {"name": "Theater TV", "address": "10.11.11.1", "identifier": "F487AF2D-23E3-433B-80C8-D7306F03191B", "services": [{"protocol": "mrp", "port": 56486}]}]}
1585790614901
{"result": "success", "devices": [{"name": "Master TV", "address": "10.11.11.2", "identifier": "5C7DCD07-E8DB-41E3-BCEB-F54480A5163F", "services": [{"protocol": "mrp", "port": 64192}]}, {"name": "Theater TV", "address": "10.11.11.1", "identifier": "F487AF2D-23E3-433B-80C8-D7306F03191B", "services": [{"protocol": "mrp", "port": 56486}]}]}
1585940076290
{"result": "success", "devices": [{"name": "Master TV", "address": "10.11.11.2", "identifier": "5C7DCD07-E8DB-41E3-BCEB-F54480A5163F", "services": [{"protocol": "mrp", "port": 64192}]}, {"name": "Theater TV", "address": "10.11.11.1", "identifier": "F487AF2D-23E3-433B-80C8-D7306F03191B", "services": [{"protocol": "mrp", "port": 49156}]}]}

Cool. Now you'll want the tcpdump files. Hopefully this takes you to my iCloud share. "bigtv.pcap" is the one that stopped working (10.11.11.1). "littletv.pcap" is the tv that kept working (10.11.11.2).

These are the final messages that came to the one that stopped (bigtv.pcap). This was about 12 hours before I noticed that things had stopped working. The last timestamp above (1585940076290) is when I discovered things not working. I had just turned on the tv, played some content, and turned off the tv. I don't expect anything in tcpdump at this time since the port had already changed. I don't know how to find out when the port changed.

{"result": "success", "hash": "f188b5ed-2b50-40e3-a106-f707ccaaf77a", "media_type": "video", "device_state": "paused", "title": "Star Wars: The Force Awakens", "artist": null, "album": null, "genre": null, "total_time": 8336, "position": 7291, "shuffle": "off", "repeat": "off", "app": null, "app_id": "com.disney.disneyplus"}
{"result": "success", "hash": "f188b5ed-2b50-40e3-a106-f707ccaaf77a", "media_type": "video", "device_state": "paused", "title": "Star Wars: The Force Awakens", "artist": null, "album": null, "genre": null, "total_time": 8336, "position": 7291, "shuffle": "off", "repeat": "off", "app": null, "app_id": "com.disney.disneyplus"}
{"result": "success", "hash": "f188b5ed-2b50-40e3-a106-f707ccaaf77a", "media_type": "video", "device_state": "playing", "title": "Star Wars: The Force Awakens", "artist": null, "album": null, "genre": null, "total_time": 8336, "position": 7291, "shuffle": "off", "repeat": "off", "app": null, "app_id": "com.disney.disneyplus"}
{"result": "success", "hash": "f188b5ed-2b50-40e3-a106-f707ccaaf77a", "media_type": "video", "device_state": "paused", "title": "Star Wars: The Force Awakens", "artist": null, "album": null, "genre": null, "total_time": 8336, "position": 7517, "shuffle": "off", "repeat": "off", "app": null, "app_id": "com.disney.disneyplus"}
{"result": "success", "hash": "f188b5ed-2b50-40e3-a106-f707ccaaf77a", "media_type": "video", "device_state": "paused", "title": "Star Wars: The Force Awakens", "artist": null, "album": null, "genre": null, "total_time": 8336, "position": 7517, "shuffle": "off", "repeat": "off", "app": null, "app_id": "com.disney.disneyplus"}
{"result": "success", "hash": "f188b5ed-2b50-40e3-a106-f707ccaaf77a", "media_type": "video", "device_state": "paused", "title": "Star Wars: The Force Awakens", "artist": null, "album": null, "genre": null, "total_time": 8336, "position": 7517, "shuffle": "off", "repeat": "off", "app": null, "app_id": "com.disney.disneyplus"}
{"result": "success", "hash": "f188b5ed-2b50-40e3-a106-f707ccaaf77a", "media_type": "video", "device_state": "paused", "title": "Star Wars: The Force Awakens", "artist": null, "album": null, "genre": null, "total_time": 8336, "position": 7517, "shuffle": "off", "repeat": "off", "app": null, "app_id": "com.disney.disneyplus"}
{"result": "success", "hash": "f188b5ed-2b50-40e3-a106-f707ccaaf77a", "media_type": "video", "device_state": "paused", "title": "Star Wars: The Force Awakens", "artist": null, "album": null, "genre": null, "total_time": 8336, "position": 7517, "shuffle": "off", "repeat": "off", "app": null, "app_id": "com.disney.disneyplus"}
{"result": "success", "hash": "f188b5ed-2b50-40e3-a106-f707ccaaf77a", "media_type": "video", "device_state": "playing", "title": "Star Wars: The Force Awakens", "artist": null, "album": null, "genre": null, "total_time": 8336, "position": 7517, "shuffle": "off", "repeat": "off", "app": null, "app_id": "com.disney.disneyplus"}
{"result": "success", "hash": "ca496c14642c78af6dd4250191fe175f6dafd72b4c33bcbab43c454aae051da1", "media_type": "unknown", "device_state": "playing", "title": null, "artist": null, "album": null, "genre": null, "total_time": null, "position": null, "shuffle": "off", "repeat": "off", "app": null, "app_id": "com.disney.disneyplus"}
{"result": "success", "hash": "ca496c14642c78af6dd4250191fe175f6dafd72b4c33bcbab43c454aae051da1", "media_type": "unknown", "device_state": "playing", "title": null, "artist": null, "album": null, "genre": null, "total_time": null, "position": null, "shuffle": "off", "repeat": "off", "app": null, "app_id": "com.disney.disneyplus"}
{"result": "success", "hash": "ca496c14642c78af6dd4250191fe175f6dafd72b4c33bcbab43c454aae051da1", "media_type": "unknown", "device_state": "idle", "title": null, "artist": null, "album": null, "genre": null, "total_time": null, "position": null, "shuffle": "off", "repeat": "off", "app": null, "app_id": null}
{"result": "success", "power_state": "off"}
{"result": "success", "hash": "ca496c14642c78af6dd4250191fe175f6dafd72b4c33bcbab43c454aae051da1", "media_type": "unknown", "device_state": "idle", "title": null, "artist": null, "album": null, "genre": null, "total_time": null, "position": null, "shuffle": "off", "repeat": "off", "app": null, "app_id": null}
{"result": "success", "hash": "ca496c14642c78af6dd4250191fe175f6dafd72b4c33bcbab43c454aae051da1", "media_type": "unknown", "device_state": "idle", "title": null, "artist": null, "album": null, "genre": null, "total_time": null, "position": null, "shuffle": "off", "repeat": "off", "app": null, "app_id": null}

Restarting atvscript process makes everything work again as expected.

Is there anything else I can do? Seems like it would be nice to have a message coming in right before the port jumps so I know to re-connect?

crxporter on 3 Apr 2020

I've had a chance now to take a peek at the TCP traffic (which is the most interesting part here). Right at the end I see this:

fin_rst

So, I'm no TCP expert so I had to Google a bit. By the looks of it, the Apple TV start sending FIN packets to various ports (40512, 60622 and 60166). FIN ("finish") basically means: I have no more data to send out but I will continue listen until you send FIN. Basically a soft way to close the connection.

For this connection, the Apple TV closes the connection at 1349 and pyatv ACKs this at 1354. So after this the connection can be considered closed I guess. Duration seems to be 198616/3600=55,17h with about 1350 packets exchanged. Last exchanged message seems to be this:

type: DEVICE_INFO_UPDATE_MESSAGE
errorCode: 0
[deviceInfoMessage] {
  uniqueIdentifier: "F487AF2D-23E3-433B-80C8-D7306F03191B"
  name: "Theater TV"
  localizedModelName: "Apple\302\240TV"
  systemBuildVersion: "17K795"
  applicationBundleIdentifier: "com.apple.mediaremoted"
  protocolVersion: 1
  lastSupportedMessageType: 77
  supportsSystemPairing: true
  allowsPairing: true
  systemMediaApplication: "com.apple.TVMusic"
  supportsACL: true
  supportsSharedQueue: true
  supportsExtendedMotion: true
  bluetoothAddress: "@\313\300\331\237\305"
  sharedQueueVersion: 2
  managedConfigDeviceID: "40:cb:c0:d9:9f:8a"
  deviceClass: 4
  logicalDeviceCount: 0
  isProxyGroupPlayer: false
  isGroupLeader: false
  isAirplayActive: false
  systemPodcastApplication: "com.apple.podcasts"
  enderDefaultGroupUID: "B876C187-E3A6-4C62-9A60-6207BF66966B"
  airplayReceivers: "TVAirPlay"
}

There are two question marks here as I see it: why does the Apple TV close the connection and why is pyatv not detecting this disconnection? I can live with the fact that the Apple TV disconnects, we can recover in that case. But not being notified about this from the protocol stack is not OK. I will have to dig a bit deeper into this, but perhaps we can add some additional debug logs and see what happens. Great findings however, thanks so much for the logs: 👍 It will be interesting to see what the other device reports.

postlund on 6 Apr 2020

Ok, so one reason for no "disconnect" message is basically because I didn't implement a listener for those events. So nothing happens. I created #561 which will print something when connection is lost. Maybe I should make the script exit when that happens. Hold my beer...

postlund on 6 Apr 2020

I had to let the tcpdump stop on the other tv. I can start them back up if you think another round would be helpful.

Either an output message from atvscript (so I can reconnect) or an automatic reconnect would be pretty cool. The IP address is not changing of course. Manual restart of the script works every time.

crxporter on 6 Apr 2020

It would be great if you could make another attempt. #561 was just merged, so you will get some output if the connection is closed and the script will exit with a non-zero exit code. So if you run from latest commit on master that should work fine 👍

Documentation is here:
https://pyatv.dev/documentation/atvscript/#connection-status

postlund on 6 Apr 2020

Can you remind me how to update from GitHub?

crxporter on 6 Apr 2020

You install directly with pip, see instructions here. Make sure you remove pyatv before you install so you don't end up with multiple versions installed (pip uninstall pyatv). Or add --upgrade to when installing (but the first tends to be safer).

postlund on 6 Apr 2020

Thank you sir. I'm running the new branch (I think) and running tcpdump on both tvs. Once they both disconnect I'll load the files to the same link from above.

Does atvscript ... push_updates exit when {"result": "failure", "connection": "closed"} is received or does it keep running? There's a chance I don't have to do anything if it exits, my setup tries to relaunch the process on exit or error.

crxporter on 6 Apr 2020

Yeah, it will exit right after that message is printed. So in that case it will probably recover for you once that happens.

postlund on 6 Apr 2020

How often do they change ports? I'm at about 5 days running TCP dump and running atvscript -scan to check that the ports haven't changed.

No issues yet. Before I close, I'd like to provide a couple more rounds of TCP dump and make sure things kick over to restart the process on error.

crxporter on 11 Apr 2020

Alright I had another one go down today - a bit more graceful than last time. This time I did get "connection closed" and "exception" from atvscript. Best I can tell it quit working this evening when the TV turned on. The last 2 messages are odd - showing what we watched two nights ago at a position of about 45 hours. Just before watching TV, the port was the same as the tcpdump file. After watching TV tonight the port had changed. Presumably when the connection closed message came through.

I've uploaded a new tcpdump file to the same icloud share as before.

In my setup the process didn't quit after the failure message but that is fine, I can simply use that message to trigger it to restart atvscript.

Last lines of atvscript output, around 8:30 PM local time on Sunday April 12.

{"result": "success", "hash": "com.apple.avkit.3784.dbcb2e1c", "media_type": "video", "device_state": "playing", "title": "How I Met Your Mother | S9 E24 - Last Forever, Part 2", "artist": null, "album": null, "genre": null, "total_time": 1296, "position": null, "shuffle": "off", "repeat": "off", "app": null, "app_id": "com.hulu.plus"}
{"result": "success", "hash": "com.apple.avkit.3784.dbcb2e1c", "media_type": "video", "device_state": "playing", "title": "How I Met Your Mother | S9 E24 - Last Forever, Part 2", "artist": null, "album": null, "genre": null, "total_time": 1296, "position": null, "shuffle": "off", "repeat": "off", "app": null, "app_id": "com.hulu.plus"}
{"result": "success", "hash": "com.apple.avkit.3784.dbcb2e1c", "media_type": "video", "device_state": "playing", "title": "How I Met Your Mother | S9 E24 - Last Forever, Part 2", "artist": null, "album": null, "genre": null, "total_time": 1296, "position": 1193, "shuffle": "off", "repeat": "off", "app": null, "app_id": "com.hulu.plus"}
{"result": "success", "hash": "com.apple.avkit.3784.dbcb2e1c", "media_type": "video", "device_state": "playing", "title": "How I Met Your Mother | S9 E24 - Last Forever, Part 2", "artist": null, "album": null, "genre": null, "total_time": 1296, "position": 1270, "shuffle": "off", "repeat": "off", "app": null, "app_id": "com.hulu.plus"}
{"result": "success", "hash": "ca496c14642c78af6dd4250191fe175f6dafd72b4c33bcbab43c454aae051da1", "media_type": "unknown", "device_state": "idle", "title": null, "artist": null, "album": null, "genre": null, "total_time": null, "position": null, "shuffle": "off", "repeat": "off", "app": null, "app_id": null}
{"result": "success", "power_state": "off"}
{"result": "success", "hash": "ca496c14642c78af6dd4250191fe175f6dafd72b4c33bcbab43c454aae051da1", "media_type": "unknown", "device_state": "idle", "title": null, "artist": null, "album": null, "genre": null, "total_time": null, "position": null, "shuffle": "off", "repeat": "off", "app": null, "app_id": null}
{"result": "success", "hash": "ca496c14642c78af6dd4250191fe175f6dafd72b4c33bcbab43c454aae051da1", "media_type": "unknown", "device_state": "idle", "title": null, "artist": null, "album": null, "genre": null, "total_time": null, "position": null, "shuffle": "off", "repeat": "off", "app": null, "app_id": null}
{"result": "success", "power_state": "on"}
{"result": "success", "power_state": "off"}
{"result": "success", "power_state": "on"}
{"result": "success", "power_state": "off"}
{"result": "success", "hash": "ca496c14642c78af6dd4250191fe175f6dafd72b4c33bcbab43c454aae051da1", "media_type": "unknown", "device_state": "idle", "title": null, "artist": null, "album": null, "genre": null, "total_time": null, "position": null, "shuffle": "off", "repeat": "off", "app": null, "app_id": null}
{"result": "success", "power_state": "on"}
{"result": "success", "hash": "ca496c14642c78af6dd4250191fe175f6dafd72b4c33bcbab43c454aae051da1", "media_type": "unknown", "device_state": "idle", "title": null, "artist": null, "album": null, "genre": null, "total_time": null, "position": null, "shuffle": "off", "repeat": "off", "app": null, "app_id": null}
{"result": "success", "hash": "com.apple.avkit.3784.dbcb2e1c", "media_type": "video", "device_state": "playing", "title": "How I Met Your Mother | S9 E24 - Last Forever, Part 2", "artist": null, "album": null, "genre": null, "total_time": 1296, "position": 162270, "shuffle": "off", "repeat": "off", "app": null, "app_id": "com.hulu.plus"}
{"result": "success", "hash": "com.apple.avkit.3784.dbcb2e1c", "media_type": "video", "device_state": "playing", "title": "How I Met Your Mother | S9 E24 - Last Forever, Part 2", "artist": null, "album": null, "genre": null, "total_time": 1296, "position": 162270, "shuffle": "off", "repeat": "off", "app": null, "app_id": "com.hulu.plus"}
{"result": "failure", "connection": "closed"}
{"result": "failure", "exception": ""}

crxporter on 13 Apr 2020

The Wireshark seems to point to the same thing as before, i.e. the device closes the connection. I'm trying to add some additional error handling to atvscript so that it terminates properly (#574) but also logging to file. The problem you mention regarding incorrect metadata showing up is very hard to debug without proper logs (and looking at the Wireshark logs are very tedious). I'll let you know when it is ready!

postlund on 14 Apr 2020

I do have a text file with all of the atvscript output during the last few days if that could be helpful.

If there’s an update I can run to help out (i.e. with more verbose logging) let me know. I’m happy to provide logs to help development.

crxporter on 14 Apr 2020

That log is unfortunately not very helpful for troubleshooting this as it only reports what the state is, it doesn't allow me to see what is happening under the hood in the same way as the regular debug logs.

I just merged #576, which adds the --debug flag. It will append the debug log to a file called atvscript.log. This is exactly what I need. I also just merged #574, which should finally make the script exit correctly upon error. It also includes a stack trace for exceptions if that is available. Would be great if you could upgrade to latest on master and re-run atvscript with the --debug flag also attached. You should be able to upgrade just like you did when installing, but adding --upgrade right after install.

postlund on 15 Apr 2020

Three questions:

Where does the atvscript.log file save?

Can I run debug on both TVs at once?

Do you still want tcpdump running?

I can keep the logs coming until you’ve got what you need. For my use it’s pretty well ready to go, I just need to set up the functions to really use the atvscript outputs in my automations.

crxporter on 15 Apr 2020

Three questions:

Where does the atvscript.log file save?

In the directory that you are currently standing when running atvscript. In the future, an option can be added to change this.

Can I run debug on both TVs at once?

Sure, but you will have to start atvscript from different directories.

Do you still want tcpdump running?

I don't think that is necessary.

I can keep the logs coming until you’ve got what you need. For my use it’s pretty well ready to go, I just need to set up the functions to really use the atvscript outputs in my automations.

That is awesome, I really appreciate that you can help me out with this and put in the time! 😄 Hopefully we can get something that works as good as possible out of this.

postlund on 15 Apr 2020

Great! I’ll get it updated today and run one in debug mode. I’m not sure what the running directory for the node red is but I think I can figure it out.

crxporter on 15 Apr 2020

Updated and running one with --debug. Datetime key is a nice addition.

Anything specific you want me to watch for? My best-case is that the script runs for a long time and restarts quickly after errors (whether it be a new port, restart the atv, power loss, etc). If it exits properly (previous version didn't, this one hopefully will) then my setup should start it right back up.

crxporter on 15 Apr 2020

The problem with the device closing the connection will still exist, so at some point that should happen. Hopefully the script will exit properly now and be restarted, so that's one thing to look for. The other one is the incorrect metadata you mentioned earlier, where old content was pushed. If you see that, then that will help me as long as I can correlate the debug log and output of atvscript (which should be easy now with the time stamp).

postlund on 15 Apr 2020

👍1

I had some network problems today (power outage) and got some error logs. This is probably what's expected if the apple tv restarts? Anyway, after the errors the script restarted without any intervention. Just how I need! The lines with 0 are new - that's the script exiting. That wasn't happening automatically with previous versions.

Let me know if you want debug logs from this event. I'm still running this one in debug mode for later if/when I get errors to share.

atvscript output:

{"result": "success", "datetime": "2020-04-19T12:40:56.581181-05:00", "power_state": "on"}
{"result": "success", "datetime": "2020-04-19T12:40:58.962317-05:00", "hash": "ca496c14642c78af6dd4250191fe175f6dafd72b4c33bcbab43c454aae051da1", "media_type": "unknown", "device_state": "idle", "title": null, "artist": null, "album": null, "genre": null, "total_time": null, "position": null, "shuffle": "off", "repeat": "off", "app": null, "app_id": null}
{"result": "success", "datetime": "2020-04-19T12:41:57.401822-05:00", "power_state": "off"}
{"result": "failure", "datetime": "2020-04-19T14:59:21.694818-05:00", "error": "device_not_found"}
0
{"result": "failure", "datetime": "2020-04-19T14:59:25.832818-05:00", "exception": "[Errno 101] Network is unreachable", "stacktrace": "Traceback (most recent call last):\n  File \"/home/pi/.local/lib/python3.7/site-packages/pyatv/scripts/atvscript.py\", line 306, in appstart\n    print(args.output(await _handle_command(args, abort_sem, loop)), flush=True)\n  File \"/home/pi/.local/lib/python3.7/site-packages/pyatv/scripts/atvscript.py\", line 188, in _handle_command\n    config = await _autodiscover_device(args, loop)\n  File \"/home/pi/.local/lib/python3.7/site-packages/pyatv/scripts/atvscript.py\", line 164, in _autodiscover_device\n    atvs = await scan(loop, **options)\n  File \"/home/pi/.local/lib/python3.7/site-packages/pyatv/__init__.py\", line 276, in scan\n    devices = (await scanner.discover(timeout)).values()\n  File \"/home/pi/.local/lib/python3.7/site-packages/pyatv/__init__.py\", line 197, in discover\n    *[self._get_services(host, timeout) for host in self.hosts]\n  File \"/home/pi/.local/lib/python3.7/site-packages/pyatv/__init__.py\", line 209, in _get_services\n    self.loop, host, services, port=port, timeout=timeout\n  File \"/home/pi/.local/lib/python3.7/site-packages/pyatv/support/udns.py\", line 249, in request\n    remote_addr=(str(address), port),\n  File \"/usr/lib/python3.7/asyncio/base_events.py\", line 1245, in create_datagram_endpoint\n    raise exceptions[0]\n  File \"/usr/lib/python3.7/asyncio/base_events.py\", line 1232, in create_datagram_endpoint\n    await self.sock_connect(sock, remote_address)\n  File \"/usr/lib/python3.7/asyncio/selector_events.py\", line 464, in sock_connect\n    return await fut\n  File \"/usr/lib/python3.7/asyncio/selector_events.py\", line 469, in _sock_connect\n    sock.connect(address)\nOSError: [Errno 101] Network is unreachable\n"}
0
{"result": "failure", "datetime": "2020-04-19T14:59:44.373969-05:00", "exception": "[Errno 101] Network is unreachable", "stacktrace": "Traceback (most recent call last):\n  File \"/home/pi/.local/lib/python3.7/site-packages/pyatv/scripts/atvscript.py\", line 306, in appstart\n    print(args.output(await _handle_command(args, abort_sem, loop)), flush=True)\n  File \"/home/pi/.local/lib/python3.7/site-packages/pyatv/scripts/atvscript.py\", line 188, in _handle_command\n    config = await _autodiscover_device(args, loop)\n  File \"/home/pi/.local/lib/python3.7/site-packages/pyatv/scripts/atvscript.py\", line 164, in _autodiscover_device\n    atvs = await scan(loop, **options)\n  File \"/home/pi/.local/lib/python3.7/site-packages/pyatv/__init__.py\", line 276, in scan\n    devices = (await scanner.discover(timeout)).values()\n  File \"/home/pi/.local/lib/python3.7/site-packages/pyatv/__init__.py\", line 197, in discover\n    *[self._get_services(host, timeout) for host in self.hosts]\n  File \"/home/pi/.local/lib/python3.7/site-packages/pyatv/__init__.py\", line 209, in _get_services\n    self.loop, host, services, port=port, timeout=timeout\n  File \"/home/pi/.local/lib/python3.7/site-packages/pyatv/support/udns.py\", line 249, in request\n    remote_addr=(str(address), port),\n  File \"/usr/lib/python3.7/asyncio/base_events.py\", line 1245, in create_datagram_endpoint\n    raise exceptions[0]\n  File \"/usr/lib/python3.7/asyncio/base_events.py\", line 1232, in create_datagram_endpoint\n    await self.sock_connect(sock, remote_address)\n  File \"/usr/lib/python3.7/asyncio/selector_events.py\", line 464, in sock_connect\n    return await fut\n  File \"/usr/lib/python3.7/asyncio/selector_events.py\", line 469, in _sock_connect\n    sock.connect(address)\nOSError: [Errno 101] Network is unreachable\n"}
0
{"result": "success", "datetime": "2020-04-19T14:59:53.685458-05:00", "power_state": "off"}
{"result": "success", "datetime": "2020-04-19T14:59:53.687657-05:00", "hash": "ca496c14642c78af6dd4250191fe175f6dafd72b4c33bcbab43c454aae051da1", "media_type": "unknown", "device_state": "idle", "title": null, "artist": null, "album": null, "genre": null, "total_time": null, "position": null, "shuffle": "off", "repeat": "off", "app": null, "app_id": null}
{"result": "failure", "datetime": "2020-04-19T15:00:11.833215-05:00", "exception": "[Errno 101] Network is unreachable", "stacktrace": "Traceback (most recent call last):\n  File \"/home/pi/.local/lib/python3.7/site-packages/pyatv/scripts/atvscript.py\", line 306, in appstart\n    print(args.output(await _handle_command(args, abort_sem, loop)), flush=True)\n  File \"/home/pi/.local/lib/python3.7/site-packages/pyatv/scripts/atvscript.py\", line 188, in _handle_command\n    config = await _autodiscover_device(args, loop)\n  File \"/home/pi/.local/lib/python3.7/site-packages/pyatv/scripts/atvscript.py\", line 164, in _autodiscover_device\n    atvs = await scan(loop, **options)\n  File \"/home/pi/.local/lib/python3.7/site-packages/pyatv/__init__.py\", line 276, in scan\n    devices = (await scanner.discover(timeout)).values()\n  File \"/home/pi/.local/lib/python3.7/site-packages/pyatv/__init__.py\", line 197, in discover\n    *[self._get_services(host, timeout) for host in self.hosts]\n  File \"/home/pi/.local/lib/python3.7/site-packages/pyatv/__init__.py\", line 209, in _get_services\n    self.loop, host, services, port=port, timeout=timeout\n  File \"/home/pi/.local/lib/python3.7/site-packages/pyatv/support/udns.py\", line 249, in request\n    remote_addr=(str(address), port),\n  File \"/usr/lib/python3.7/asyncio/base_events.py\", line 1245, in create_datagram_endpoint\n    raise exceptions[0]\n  File \"/usr/lib/python3.7/asyncio/base_events.py\", line 1232, in create_datagram_endpoint\n    await self.sock_connect(sock, remote_address)\n  File \"/usr/lib/python3.7/asyncio/selector_events.py\", line 464, in sock_connect\n    return await fut\n  File \"/usr/lib/python3.7/asyncio/selector_events.py\", line 469, in _sock_connect\n    sock.connect(address)\nOSError: [Errno 101] Network is unreachable\n"}
0
{"result": "success", "datetime": "2020-04-19T15:00:21.077115-05:00", "power_state": "off"}
{"result": "success", "datetime": "2020-04-19T15:00:21.079208-05:00", "hash": "ca496c14642c78af6dd4250191fe175f6dafd72b4c33bcbab43c454aae051da1", "media_type": "unknown", "device_state": "idle", "title": null, "artist": null, "album": null, "genre": null, "total_time": null, "position": null, "shuffle": "off", "repeat": "off", "app": null, "app_id": null}
{"result": "success", "datetime": "2020-04-19T15:32:12.253196-05:00", "power_state": "on"}
{"result": "success", "datetime": "2020-04-19T15:32:14.772767-05:00", "power_state": "off"}

crxporter on 20 Apr 2020

The debug logs looks as I would expect them to when something bad happens (i.e. device restarts), so I'm satisfied with that assuming you are as well. We can probably check that off our list. The remaining part is probably the incorrect metadata updates then.

postlund on 20 Apr 2020

I’ll put together a little script to log whenever position > total_time then provide debug logs if/when that happens next.

crxporter on 20 Apr 2020

👍1

Recent updates with error handling and properly quitting the process have my setup working great. Switching ports works (process restarts), I haven’t had a disconnect or lost push updates in over a week.

Closing for now, I might be back later. I’m keeping things on debug mode for now.

crxporter on 1 May 2020

Pyatv: atvscript stops push updates

All 38 comments

Related issues