Pyatv: MRP status timeout?

Created on 4 Nov 2019  Â·  18Comments  Â·  Source: postlund/pyatv

In addition to home-assistant I’ve been using atvremote to monitor the status of my Apple TVs for years. This has worked fine pre-MRP (and still does, with an ATV 3). It initially works fine with an Apple TV 4 and tvOS 13.2. But after a while it stops working with an error like this:

Traceback (most recent call last):
  File "/usr/local/lib/python3.5/dist-packages/pyatv/__main__.py", line 488, in _run_application
    return await cli_handler(loop)
  File "/usr/local/lib/python3.5/dist-packages/pyatv/__main__.py", line 313, in cli_handler
    return await _handle_commands(args, loop)
  File "/usr/local/lib/python3.5/dist-packages/pyatv/__main__.py", line 403, in _handle_commands
    ret = await _handle_device_command(args, cmd, atv, loop)
  File "/usr/local/lib/python3.5/dist-packages/pyatv/__main__.py", line 432, in _handle_device_command
    atv.metadata, cmd, True, *cmd_args))
  File "/usr/local/lib/python3.5/dist-packages/pyatv/__main__.py", line 454, in _exec_command
    value = await tmp(*args)
  File "/usr/local/lib/python3.5/dist-packages/pyatv/mrp/__init__.py", line 246, in playing
    await self.protocol.start()
  File "/usr/local/lib/python3.5/dist-packages/pyatv/mrp/protocol.py", line 71, in start
    await self.send_and_receive(msg)
  File "/usr/local/lib/python3.5/dist-packages/pyatv/mrp/protocol.py", line 161, in send_and_receive
    return await self._receive(identifier, timeout)
  File "/usr/local/lib/python3.5/dist-packages/pyatv/mrp/protocol.py", line 170, in _receive
    semaphore.acquire(), timeout, loop=self.loop)
  File "/usr/lib/python3.5/asyncio/tasks.py", line 404, in wait_for
    raise futures.TimeoutError()
concurrent.futures._base.TimeoutError

The command that I’m periodically executing is:

/usr/local/bin/atvremote --id [...] --device_credentials [...] playing

It may be that pyatv is triggering some kind of bug/resource leak in the Apple TV itself; I’m not entirely sure how to proceed. Any ideas?

bug mrp
Source
picture nriley

Most helpful comment

@nriley Going through som old issues here... This is still valid I presume and I have not yet found any solution to it. However, there's a new script called atvscript that can monitor play status and report it back to stdout as JSON. Maybe that can be interesting to you, as a replacement to polling the status? You can read about it here: https://pyatv.dev/documentation/atvscript/

picture postlund on 15 Apr 2020
👍3

All 18 comments

Hmm, this seems strange to be as well. It's always hard to debug these kinds of things. Could you maybe run with --debug and see if you get anything else? Also, when this happens, could you try if the Remote app works on your phone?

postlund picture postlund on 4 Nov 2019

Here’s the debug output:

DEBUG: Discovering devices for 3 seconds
DEBUG: Auto-discovered Living Room Apple TV at 192.168.2.20:7000 (protocol: 3)
DEBUG: Auto-discovered Living Room Apple TV at 192.168.2.20:49870 (protocol: 2)
DEBUG: Auto-discovered Bonus Room Apple TV at 192.168.2.27:3689 (protocol: 1)
DEBUG: Auto-discovered Bonus Room Apple TV at 192.168.2.27:3689 (protocol: 1)
INFO: Auto-discovered Living Room Apple TV at 192.168.2.20
DEBUG: Connected to device
DEBUG: >> Send (Data=080f122462353165666465342d303032642d346433632d613461362d3837653337333533373666642000a2017c0a2465356237336535332d613861312d343432632d383439312d376133663639333034623132120570796174761a066950686f6e65220531344736302a12636f6d2e6170706c652e545652656d6f746532063237332e31323801403a480150016211636f6d2e6170706c652e54564d75736963680170017801880102)
DEBUG: >> Send: Protobuf=type: DEVICE_INFO_MESSAGE
identifier: "b51efde4-002d-4d3c-a4a6-87e3735376fd"
priority: 0
[deviceInfoMessage] {
  uniqueIdentifier: "e5b73e53-a8a1-442c-8491-7a3f69304b12"
  name: "pyatv"
  localizedModelName: "iPhone"
  systemBuildVersion: "14G60"
  applicationBundleIdentifier: "com.apple.TVRemote"
  applicationBundleVersion: "273.12"
  protocolVersion: 1
  lastSupportedMessageType: 58
  supportsSystemPairing: true
  allowsPairing: true
  systemMediaApplication: "com.apple.TVMusic"
  supportsACL: true
  supportsSharedQueue: true
  supportsExtendedMotion: true
  sharedQueueVersion: 2
}

DEBUG: Disconnected from device: None
Traceback (most recent call last):
  File "/usr/local/lib/python3.5/dist-packages/pyatv/__main__.py", line 488, in _run_application
    return await cli_handler(loop)
  File "/usr/local/lib/python3.5/dist-packages/pyatv/__main__.py", line 313, in cli_handler
    return await _handle_commands(args, loop)
  File "/usr/local/lib/python3.5/dist-packages/pyatv/__main__.py", line 403, in _handle_commands
    ret = await _handle_device_command(args, cmd, atv, loop)
  File "/usr/local/lib/python3.5/dist-packages/pyatv/__main__.py", line 432, in _handle_device_command
    atv.metadata, cmd, True, *cmd_args))
  File "/usr/local/lib/python3.5/dist-packages/pyatv/__main__.py", line 454, in _exec_command
    value = await tmp(*args)
  File "/usr/local/lib/python3.5/dist-packages/pyatv/mrp/__init__.py", line 246, in playing
    await self.protocol.start()
  File "/usr/local/lib/python3.5/dist-packages/pyatv/mrp/protocol.py", line 71, in start
    await self.send_and_receive(msg)
  File "/usr/local/lib/python3.5/dist-packages/pyatv/mrp/protocol.py", line 161, in send_and_receive
    return await self._receive(identifier, timeout)
  File "/usr/local/lib/python3.5/dist-packages/pyatv/mrp/protocol.py", line 170, in _receive
    semaphore.acquire(), timeout, loop=self.loop)
  File "/usr/lib/python3.5/asyncio/tasks.py", line 404, in wait_for
    raise futures.TimeoutError()
concurrent.futures._base.TimeoutError

>>> An error occurred, full stack trace above

The Remote app doesn’t work either; the TV shows up in the devices list when I tap on it, it disappears from the list and doesn’t connect. Sometimes I get a “No Connection” dialog. However, the Control Center remote continues to work — guessing it uses yet another different protocol?

After I restart the Apple TV, both atvremote and the Remote app start working again.

nriley picture nriley on 4 Nov 2019

Well I have exactly the same problem. I described this issue in other topic. I believe there is a bug on TV OS side. We have to figure out which protocol Control Center remote is using, because it is rock solid. Also is your ATV hardwired or using WiFi ?

raufis27 picture raufis27 on 4 Nov 2019

Well I have exactly the same problem. I described this issue in other topic. I believe there is a bug on TV OS side. We have to figure out which protocol Control Center remote is using, because it is rock solid. Also is your ATV hardwired or using WiFi ?

Yes, sounds fairly similar. Control center does not use a different protocol, it's the same. I usually use control center when I test my MRP proxy. My guess is that this is a bug in MRP on the Apple TV side. It probably doesn't handle poor clients that well (that doesn't strictly follow protocol) and ends up in a bad state. But that's just a qualified guess on my part.

The reason why control center works better maybe has to do with long lived TCP-sessions or something similar. So control center still has a valid session when the rest stops working. Would be decent design to keep delays down when quickly accessing the remote (like you usually do with control center). Only a guess here as well.

Only way to find out would be to sniff packets. Would be interesting to know which port(s) works and which port is used when it stops working. Also which port control center uses at the time (when the other is working and after it stops working). If you could investigate this with wireshark that could help. Once it stops working you could try overriding the port in atvremote and use the same as control center uses.

postlund picture postlund on 4 Nov 2019

Unfortunately I’m only physically at the location of this Apple TV every few months - next time will be the end of December. If the problem isn’t solved by then I’m happy to take a look with Wireshark, otherwise @raufis27 is probably a better choice!

nriley picture nriley on 4 Nov 2019

My Apple TV is on Ethernet for what it’s worth.

Nicholas

On Nov 4, 2019, at 12:00 PM, raufis27 notifications@github.com wrote:


Well I have exactly the same problem. I described this problem in other topic. I believe there is a bug on TV OS side. We have to figure out which protocol Control Center remote is using, because it is rock solid. Also is your ATV hardwired or using WiFi ?

—
You are receiving this because you authored the thread.
Reply to this email directly, view it on GitHub, or unsubscribe.

nriley picture nriley on 4 Nov 2019

Have you guys seen this lately? Maybe tried with the Home Assistant component?

postlund picture postlund on 6 Dec 2019

Since this problem was happening I switched to pinging the Apple TV to monitor status. Are there changes in pyatv and/or tvOS that you think might fix it?

I am going to be replacing the Apple TV 4 ("HD") in question with a 4K one at the end of the month and replacing the ATV 3 (that I continue to successfully monitor with this method) with the ATV 4 — can try turning on the more sophisticated monitoring again then for both devices and see if there is any difference.

nriley picture nriley on 6 Dec 2019

@nriley I have made some changes to the connection flow (which messages are sent and when). So there might be different behavior now, would be interesting to know if it has made any difference.

postlund picture postlund on 6 Dec 2019

I stopped using it, because of multiple issues including not being able to decode playing status. I can try later on weekend and report back.

raufis27 picture raufis27 on 6 Dec 2019
👍1

@postlund - I've had this running for about a day now on the Apple TV 4 (same device that caused the original issue), and it seems to be working well. Sometimes I get this but it does not seem to affect the status output:

WARNING: Failed to resolve _appletv-v2._tcp.local. ([...]._appletv-v2._tcp.local.)

Will enable it on the Apple TV 4K today. I'm here for about another 3 days so hopefully will either be able to reproduce the problem or feel pretty comfortable that it's fixed.

nriley picture nriley on 29 Dec 2019

Oh well, so much for that — it's back.

On Sun, 29 Dec 2019 12:19:02, status failed (1) -- Traceback (most recent call last):
 File "/usr/local/lib/python3.5/dist-packages/pyatv/__main__.py", line 538, in _run_application
   return await cli_handler(loop)
 File "/usr/local/lib/python3.5/dist-packages/pyatv/__main__.py", line 367, in cli_handler
   return await _handle_commands(args, config, loop)
 File "/usr/local/lib/python3.5/dist-packages/pyatv/__main__.py", line 447, in _handle_commands
   atv = await connect(config, loop, protocol=args.protocol)
 File "/usr/local/lib/python3.5/dist-packages/pyatv/__init__.py", line 160, in connect
   await atv.connect()
 File "/usr/local/lib/python3.5/dist-packages/pyatv/mrp/__init__.py", line 360, in connect
   await self._protocol.start()
 File "/usr/local/lib/python3.5/dist-packages/pyatv/mrp/protocol.py", line 71, in start
   await self.send_and_receive(msg)
 File "/usr/local/lib/python3.5/dist-packages/pyatv/mrp/protocol.py", line 141, in send_and_receive
   return await self._receive(identifier, timeout)
 File "/usr/local/lib/python3.5/dist-packages/pyatv/mrp/protocol.py", line 150, in _receive
   semaphore.acquire(), timeout, loop=self.loop)
 File "/usr/lib/python3.5/asyncio/tasks.py", line 404, in wait_for
   raise futures.TimeoutError()
concurrent.futures._base.TimeoutError

An error occurred, full stack trace above
ERROR: Unclosed client session
client_session: <aiohttp.client.ClientSession object at 0x7fb98bef67f0>.
nriley picture nriley on 29 Dec 2019

The fun never stops. We will have to dig deeper into this. Since it's an edge-case, I will give it low priority for now.

postlund picture postlund on 29 Dec 2019

Thanks for trying to fix it; I suspect it is just Apple's bug, probably a resource leak. I monitor at 1 minute intervals so this equates with about 1500 requests before things go poorly.

nriley picture nriley on 29 Dec 2019

@nriley Going through som old issues here... This is still valid I presume and I have not yet found any solution to it. However, there's a new script called atvscript that can monitor play status and report it back to stdout as JSON. Maybe that can be interesting to you, as a replacement to polling the status? You can read about it here: https://pyatv.dev/documentation/atvscript/

postlund picture postlund on 15 Apr 2020
👍3

@nriley I'm starting to suspect this happens because the device goes to sleep (see #595 if you want the short background). So, one interesting thing to try is to disable auto-sleep. I'm working on some improvements to remove the need for it, but I will need a few days probably.

postlund picture postlund on 19 Apr 2020

So, I think I am done now. I have increased the HTTP request timeout and added other mechanisms to unicast scanning to wake the device. So hopefully it should work now. Here is an example with regular scanning (by specifying --id):

$ atvremote --id xxx --debug playing
2020-04-21 10:38:38 DEBUG: Discovering devices for 3 seconds
2020-04-21 10:38:39 DEBUG: Auto-discovered My Music on a6b98bcd-forked-daapd at 10.0.10.200:3689 (Protocol.DMAP)
2020-04-21 10:38:39 DEBUG: Auto-discovered Kontor at 10.0.10.101:7000 (Protocol.AirPlay)
2020-04-21 10:38:39 DEBUG: Auto-discovered Vardagsrum at 10.0.10.81:49152 (Protocol.MRP)
2020-04-21 10:38:39 DEBUG: Auto-discovered Vardagsrum at 10.0.10.81:7000 (Protocol.AirPlay)
2020-04-21 10:38:39 DEBUG: Auto-discovered Apple TV (2) at 10.0.10.100:7000 (Protocol.AirPlay)
2020-04-21 10:38:39 DEBUG: Auto-discovered Apple TV at 10.0.10.100:3689 (Protocol.DMAP)
2020-04-21 10:38:39 DEBUG: Auto-discovered Apple TV at 10.0.10.100:3689 (Protocol.DMAP)
2020-04-21 10:38:41 INFO: Auto-discovered Apple TV (2) at 10.0.10.100
2020-04-21 10:38:41 DEBUG: No AirPlay credentials loaded
2020-04-21 10:38:41 DEBUG: GET URL: http://10.0.10.100:3689/login?hsgid=yyy&hasFP=1
2020-04-21 10:38:56 DEBUG: Response: status=200, headers=[Date=Tue, 21 Apr 2020 08:40:53 GMT, DAAP-Server=iTunes/11.1b37 (OS X), Content-Type=application/x-dmap-tagged, Content-Length=47, Content-Encoding=gzip]
2020-04-21 10:38:56 DEBUG: << GET (Data=6d6c6f67000000186d73747400000004000000c86d6c69640000000456002515)
2020-04-21 10:38:56 DEBUG: _login_request: mlog: [container, dmap.loginresponse]
  mstt: 200 [uint, dmap.status]
  mlid: 1442850069 [uint, dmap.sessionid]

2020-04-21 10:38:56 INFO: Logged in and got session id 1442850069
2020-04-21 10:38:56 DEBUG: Already logged in, re-using seasion id 1442850069
2020-04-21 10:38:56 DEBUG: GET URL: http://10.0.10.100:3689/ctrl-int/1/playstatusupdate?session-id=1442850069&revision-number=0
2020-04-21 10:38:56 DEBUG: Response: status=200, headers=[Date=Tue, 21 Apr 2020 08:40:53 GMT, DAAP-Server=iTunes/11.1b37 (OS X), Content-Type=application/x-dmap-tagged, Content-Length=41, Content-Encoding=gzip]
2020-04-21 10:38:56 DEBUG: << GET (Data=636d7374000000186d73747400000004000000c8636d73720000000400000012)
2020-04-21 10:38:56 DEBUG: _get_request: cmst: [container, dmcp.playstatus]
  mstt: 200 [uint, dmap.status]
  cmsr: 18 [uint, dmcp.serverrevision]

  Media type: Unknown
Device state: Idle
      Repeat: Off
     Shuffle: Off
2020-04-21 10:38:56 DEBUG: Connection was closed properly

Notice the 15s delay between GET and response. This is the time it takes for the device to wake up.

Similarly for unicast scanning:

$ atvremote -s 10.0.10.100 --debug -t 30 playing
2020-04-21 10:37:51 DEBUG: Knocking at port 3689 on 10.0.10.100
2020-04-21 10:37:51 DEBUG: Knocking at port 7000 on 10.0.10.100
2020-04-21 10:37:51 DEBUG: Knocking at port 49152 on 10.0.10.100
2020-04-21 10:37:51 DEBUG: Knocking at port 32498 on 10.0.10.100
2020-04-21 10:37:51 DEBUG: Sending DNS request to 10.0.10.100 (Data=35ff012000040000000000000b5f6170706c6574762d7632045f746370056c6f63616c0000ff80010b5f746f7563682d61626c65045f746370056c6f63616c0000ff80010e5f6d6564696172656d6f74657476045f746370056c6f63616c0000ff8001085f616972706c6179045f746370056c6f63616c0000ff8001)
2020-04-21 10:37:52 DEBUG: Sending DNS request to 10.0.10.100 (Data=35ff012000040000000000000b5f6170706c6574762d7632045f746370056c6f63616c0000ff80010b5f746f7563682d61626c65045f746370056c6f63616c0000ff80010e5f6d6564696172656d6f74657476045f746370056c6f63616c0000ff8001085f616972706c6179045f746370056c6f63616c0000ff8001)
2020-04-21 10:37:53 DEBUG: Sending DNS request to 10.0.10.100 (Data=35ff012000040000000000000b5f6170706c6574762d7632045f746370056c6f63616c0000ff80010b5f746f7563682d61626c65045f746370056c6f63616c0000ff80010e5f6d6564696172656d6f74657476045f746370056c6f63616c0000ff8001085f616972706c6179045f746370056c6f63616c0000ff8001)
2020-04-21 10:37:53 DEBUG: Knocking at port 3689 on 10.0.10.100
2020-04-21 10:37:53 DEBUG: Knocking at port 7000 on 10.0.10.100
2020-04-21 10:37:53 DEBUG: Knocking at port 49152 on 10.0.10.100
2020-04-21 10:37:53 DEBUG: Knocking at port 32498 on 10.0.10.100
2020-04-21 10:37:54 DEBUG: Sending DNS request to 10.0.10.100 (Data=35ff012000040000000000000b5f6170706c6574762d7632045f746370056c6f63616c0000ff80010b5f746f7563682d61626c65045f746370056c6f63616c0000ff80010e5f6d6564696172656d6f74657476045f746370056c6f63616c0000ff8001085f616972706c6179045f746370056c6f63616c0000ff8001)
2020-04-21 10:37:55 DEBUG: Sending DNS request to 10.0.10.100 (Data=35ff012000040000000000000b5f6170706c6574762d7632045f746370056c6f63616c0000ff80010b5f746f7563682d61626c65045f746370056c6f63616c0000ff80010e5f6d6564696172656d6f74657476045f746370056c6f63616c0000ff8001085f616972706c6179045f746370056c6f63616c0000ff8001)
2020-04-21 10:37:55 DEBUG: Knocking at port 3689 on 10.0.10.100
2020-04-21 10:37:55 DEBUG: Knocking at port 7000 on 10.0.10.100
2020-04-21 10:37:55 DEBUG: Knocking at port 49152 on 10.0.10.100
2020-04-21 10:37:55 DEBUG: Knocking at port 32498 on 10.0.10.100
2020-04-21 10:37:56 DEBUG: Sending DNS request to 10.0.10.100 (Data=35ff012000040000000000000b5f6170706c6574762d7632045f746370056c6f63616c0000ff80010b5f746f7563682d61626c65045f746370056c6f63616c0000ff80010e5f6d6564696172656d6f74657476045f746370056c6f63616c0000ff8001085f616972706c6179045f746370056c6f63616c0000ff8001)
2020-04-21 10:37:57 DEBUG: Sending DNS request to 10.0.10.100 (Data=35ff012000040000000000000b5f6170706c6574762d7632045f746370056c6f63616c0000ff80010b5f746f7563682d61626c65045f746370056c6f63616c0000ff80010e5f6d6564696172656d6f74657476045f746370056c6f63616c0000ff8001085f616972706c6179045f746370056c6f63616c0000ff8001)
2020-04-21 10:37:58 DEBUG: Knocking at port 3689 on 10.0.10.100
2020-04-21 10:37:58 DEBUG: Knocking at port 7000 on 10.0.10.100
2020-04-21 10:37:58 DEBUG: Knocking at port 49152 on 10.0.10.100
2020-04-21 10:37:58 DEBUG: Knocking at port 32498 on 10.0.10.100
2020-04-21 10:37:58 DEBUG: Sending DNS request to 10.0.10.100 (Data=35ff012000040000000000000b5f6170706c6574762d7632045f746370056c6f63616c0000ff80010b5f746f7563682d61626c65045f746370056c6f63616c0000ff80010e5f6d6564696172656d6f74657476045f746370056c6f63616c0000ff8001085f616972706c6179045f746370056c6f63616c0000ff8001)
2020-04-21 10:37:59 DEBUG: Sending DNS request to 10.0.10.100 (Data=35ff012000040000000000000b5f6170706c6574762d7632045f746370056c6f63616c0000ff80010b5f746f7563682d61626c65045f746370056c6f63616c0000ff80010e5f6d6564696172656d6f74657476045f746370056c6f63616c0000ff8001085f616972706c6179045f746370056c6f63616c0000ff8001)
2020-04-21 10:38:00 DEBUG: Knocking at port 3689 on 10.0.10.100
2020-04-21 10:38:00 DEBUG: Knocking at port 7000 on 10.0.10.100
2020-04-21 10:38:00 DEBUG: Knocking at port 49152 on 10.0.10.100
2020-04-21 10:38:00 DEBUG: Knocking at port 32498 on 10.0.10.100
2020-04-21 10:38:00 DEBUG: Sending DNS request to 10.0.10.100 (Data=35ff012000040000000000000b5f6170706c6574762d7632045f746370056c6f63616c0000ff80010b5f746f7563682d61626c65045f746370056c6f63616c0000ff80010e5f6d6564696172656d6f74657476045f746370056c6f63616c0000ff8001085f616972706c6179045f746370056c6f63616c0000ff8001)
2020-04-21 10:38:01 DEBUG: Sending DNS request to 10.0.10.100 (Data=35ff012000040000000000000b5f6170706c6574762d7632045f746370056c6f63616c0000ff80010b5f746f7563682d61626c65045f746370056c6f63616c0000ff80010e5f6d6564696172656d6f74657476045f746370056c6f63616c0000ff8001085f616972706c6179045f746370056c6f63616c0000ff8001)
2020-04-21 10:38:02 DEBUG: Knocking at port 3689 on 10.0.10.100
2020-04-21 10:38:02 DEBUG: Knocking at port 7000 on 10.0.10.100
2020-04-21 10:38:02 DEBUG: Knocking at port 49152 on 10.0.10.100
2020-04-21 10:38:02 DEBUG: Knocking at port 32498 on 10.0.10.100
2020-04-21 10:38:02 DEBUG: Sending DNS request to 10.0.10.100 (Data=35ff012000040000000000000b5f6170706c6574762d7632045f746370056c6f63616c0000ff80010b5f746f7563682d61626c65045f746370056c6f63616c0000ff80010e5f6d6564696172656d6f74657476045f746370056c6f63616c0000ff8001085f616972706c6179045f746370056c6f63616c0000ff8001)
2020-04-21 10:38:03 DEBUG: Sending DNS request to 10.0.10.100 (Data=35ff012000040000000000000b5f6170706c6574762d7632045f746370056c6f63616c0000ff80010b5f746f7563682d61626c65045f746370056c6f63616c0000ff80010e5f6d6564696172656d6f74657476045f746370056c6f63616c0000ff8001085f616972706c6179045f746370056c6f63616c0000ff8001)
2020-04-21 10:38:04 DEBUG: Knocking at port 3689 on 10.0.10.100
2020-04-21 10:38:04 DEBUG: Knocking at port 7000 on 10.0.10.100
2020-04-21 10:38:04 DEBUG: Knocking at port 49152 on 10.0.10.100
2020-04-21 10:38:04 DEBUG: Knocking at port 32498 on 10.0.10.100
2020-04-21 10:38:04 DEBUG: Sending DNS request to 10.0.10.100 (Data=35ff012000040000000000000b5f6170706c6574762d7632045f746370056c6f63616c0000ff80010b5f746f7563682d61626c65045f746370056c6f63616c0000ff80010e5f6d6564696172656d6f74657476045f746370056c6f63616c0000ff8001085f616972706c6179045f746370056c6f63616c0000ff8001)
2020-04-21 10:38:05 DEBUG: Sending DNS request to 10.0.10.100 (Data=35ff012000040000000000000b5f6170706c6574762d7632045f746370056c6f63616c0000ff80010b5f746f7563682d61626c65045f746370056c6f63616c0000ff80010e5f6d6564696172656d6f74657476045f746370056c6f63616c0000ff8001085f616972706c6179045f746370056c6f63616c0000ff8001)
2020-04-21 10:38:06 DEBUG: Knocking at port 3689 on 10.0.10.100
2020-04-21 10:38:06 DEBUG: Knocking at port 7000 on 10.0.10.100
2020-04-21 10:38:06 DEBUG: Knocking at port 49152 on 10.0.10.100
2020-04-21 10:38:06 DEBUG: Knocking at port 32498 on 10.0.10.100
2020-04-21 10:38:06 DEBUG: Sending DNS request to 10.0.10.100 (Data=35ff012000040000000000000b5f6170706c6574762d7632045f746370056c6f63616c0000ff80010b5f746f7563682d61626c65045f746370056c6f63616c0000ff80010e5f6d6564696172656d6f74657476045f746370056c6f63616c0000ff8001085f616972706c6179045f746370056c6f63616c0000ff8001)
2020-04-21 10:38:07 DEBUG: Sending DNS request to 10.0.10.100 (Data=35ff012000040000000000000b5f6170706c6574762d7632045f746370056c6f63616c0000ff80010b5f746f7563682d61626c65045f746370056c6f63616c0000ff80010e5f6d6564696172656d6f74657476045f746370056c6f63616c0000ff8001085f616972706c6179045f746370056c6f63616c0000ff8001)
2020-04-21 10:38:08 DEBUG: Knocking at port 3689 on 10.0.10.100
2020-04-21 10:38:08 DEBUG: Knocking at port 7000 on 10.0.10.100
2020-04-21 10:38:08 DEBUG: Knocking at port 49152 on 10.0.10.100
2020-04-21 10:38:08 DEBUG: Knocking at port 32498 on 10.0.10.100
2020-04-21 10:38:08 DEBUG: Sending DNS request to 10.0.10.100 (Data=35ff012000040000000000000b5f6170706c6574762d7632045f746370056c6f63616c0000ff80010b5f746f7563682d61626c65045f746370056c6f63616c0000ff80010e5f6d6564696172656d6f74657476045f746370056c6f63616c0000ff8001085f616972706c6179045f746370056c6f63616c0000ff8001)
2020-04-21 10:38:09 DEBUG: Sending DNS request to 10.0.10.100 (Data=35ff012000040000000000000b5f6170706c6574762d7632045f746370056c6f63616c0000ff80010b5f746f7563682d61626c65045f746370056c6f63616c0000ff80010e5f6d6564696172656d6f74657476045f746370056c6f63616c0000ff8001085f616972706c6179045f746370056c6f63616c0000ff8001)
2020-04-21 10:38:09 DEBUG: Received DNS response from 10.0.10.100 (Data=35ff840000030003000000090b5f6170706c6574762d7632045f746370056c6f63616c0000ff80010b5f746f7563682d61626c65c01800ff8001085f616972706c6179c01800ff8001c03a000c00010000000a00100d4170706c65c2a0545620283229c03ac028000c00010000000a00131032444632453735303736333943323639c028c00c000c00010000000a00131032444632453735303736333943323639c00cc055002100010000000a0012000000001b58094170706c6554562d32c01dc055001000010000000a00dc1a64657669636569643d37303a37333a43423a44363a34313a30391766656174757265733d307835413746464646372c307...)
2020-04-21 10:38:09 DEBUG: Cleaning up after UDNS request
2020-04-21 10:38:09 DEBUG: Cleaning up after UDNS request
2020-04-21 10:38:09 DEBUG: Auto-discovered Apple TV (2) at 10.0.10.100:7000 (Protocol.AirPlay)
2020-04-21 10:38:09 DEBUG: Auto-discovered Apple TV at 10.0.10.100:3689 (Protocol.DMAP)
2020-04-21 10:38:09 DEBUG: Auto-discovered Apple TV at 10.0.10.100:3689 (Protocol.DMAP)
2020-04-21 10:38:09 INFO: Auto-discovered Apple TV (2) at 10.0.10.100
2020-04-21 10:38:09 DEBUG: No AirPlay credentials loaded
2020-04-21 10:38:09 DEBUG: GET URL: http://10.0.10.100:3689/login?hsgid=yyy&hasFP=1
2020-04-21 10:38:09 DEBUG: Response: status=200, headers=[Date=Tue, 21 Apr 2020 08:40:07 GMT, DAAP-Server=iTunes/11.1b37 (OS X), Content-Type=application/x-dmap-tagged, Content-Length=47, Content-Encoding=gzip]
2020-04-21 10:38:09 DEBUG: << GET (Data=6d6c6f67000000186d73747400000004000000c86d6c69640000000440cb4693)
2020-04-21 10:38:09 DEBUG: _login_request: mlog: [container, dmap.loginresponse]
  mstt: 200 [uint, dmap.status]
  mlid: 1087063699 [uint, dmap.sessionid]

2020-04-21 10:38:09 INFO: Logged in and got session id 1087063699
2020-04-21 10:38:09 DEBUG: Already logged in, re-using seasion id 1087063699
2020-04-21 10:38:09 DEBUG: GET URL: http://10.0.10.100:3689/ctrl-int/1/playstatusupdate?session-id=1087063699&revision-number=0
2020-04-21 10:38:09 DEBUG: Response: status=200, headers=[Date=Tue, 21 Apr 2020 08:40:07 GMT, DAAP-Server=iTunes/11.1b37 (OS X), Content-Type=application/x-dmap-tagged, Content-Length=41, Content-Encoding=gzip]
2020-04-21 10:38:09 DEBUG: << GET (Data=636d7374000000186d73747400000004000000c8636d73720000000400000012)
2020-04-21 10:38:09 DEBUG: _get_request: cmst: [container, dmcp.playstatus]
  mstt: 200 [uint, dmap.status]
  cmsr: 18 [uint, dmcp.serverrevision]

  Media type: Unknown
Device state: Idle
      Repeat: Off
     Shuffle: Off
2020-04-21 10:38:09 DEBUG: Connection was closed properly

Ports are periodically knocked and services identified in order to wake the device. A longer timeout needs to be specified manually in this case as I don't want to impose a 30 second scan timeout by default for regular scanning. If you could try out master now @nriley, that would be great! Hopefully this should solve the problem.

postlund picture postlund on 21 Apr 2020

I strongly believe my previous changes fixed this issue, so I'm going to close it. Feel free to open it again if the issue remains.

postlund picture postlund on 31 May 2020
Was this page helpful?
0 / 5 - 0 ratings

Related issues

Gio76 picture Gio76  Â·  3Comments
Krocko picture Krocko  Â·  10Comments
poudenes picture poudenes  Â·  3Comments
jjlawren picture jjlawren  Â·  11Comments
postlund picture postlund  Â·  13Comments