Timeouts during login

[postlund]

I've seen a lot of these errors when when connecting to my Apple TV (with OS 7.2.2):

atvremote --debug -a playing
DEBUG: Discovering devices for 3 seconds
DEBUG: Auto-discovered service Apple TV at 10.0.10.22 (hsgid: XXXX)
INFO: Auto-discovered Apple TV at 10.0.10.22
DEBUG: GET URL: http://10.0.10.22:3689/login?hsgid=XXXX&hasFP=1
Traceback (most recent call last):
  File "/Users/postlund/tmp/pyatv/pyatv/__main__.py", line 223, in _run_application
    asyncio.wait_for((yield from cli_handler(loop)), timeout=15)
  File "/Users/postlund/tmp/pyatv/pyatv/__main__.py", line 72, in cli_handler
    return (yield from _handle_autodiscover(args, loop))
  File "/Users/postlund/tmp/pyatv/pyatv/__main__.py", line 116, in _handle_autodiscover
    yield from _handle_command(args, loop)
  File "/Users/postlund/tmp/pyatv/pyatv/__main__.py", line 151, in _handle_command
    playing_resp = yield from atv.metadata.playing()
  File "/Users/postlund/tmp/pyatv/pyatv/internal/apple_tv.py", line 225, in playing
    playstatus = yield from self.apple_tv.playstatus()
  File "/Users/postlund/tmp/pyatv/pyatv/daap.py", line 126, in get
    yield from self._assure_logged_in()
  File "/Users/postlund/tmp/pyatv/pyatv/daap.py", line 177, in _assure_logged_in
    yield from self.login()
  File "/Users/postlund/tmp/pyatv/pyatv/daap.py", line 115, in login
    resp = yield from self._do(self.session.get_data, url)
  File "/Users/postlund/tmp/pyatv/pyatv/daap.py", line 144, in _do
    resp, status = yield from action(url)
  File "/Users/postlund/tmp/pyatv/pyatv/daap.py", line 50, in get_data
    url, headers=_DMAP_HEADERS, timeout=self._timeout)
  File "/Users/postlund/tmp/pyatv/lib/python3.5/site-packages/aiohttp/client.py", line 530, in __iter__
    resp = yield from self._coro
  File "/Users/postlund/tmp/pyatv/lib/python3.5/site-packages/aiohttp/client.py", line 176, in _request
    conn = yield from self._connector.connect(req)
  File "/Users/postlund/tmp/pyatv/lib/python3.5/site-packages/async_timeout/__init__.py", line 44, in __exit__
    raise asyncio.TimeoutError from None
concurrent.futures._base.TimeoutError

>>> An error occurred, full stack trace above

By looking at the traffic with wireshark, it looks like the Apple TV for some reason starts responding with ICMP Redirects. After a bunch of retries (five in my case) it fails. Not sure why it would do that. If anyone has any idea, I would appreciate some help. I can add that it usually (but not always) happens when the device is in standby. When I wake it up, it works again.

@robbiet480, have you seen this?

[robbiet480]

Nope, have not seen this!

[postlund]

Ok, maybe it's something with a gen 3 device. Thanks for the feedback!

[postlund]

I'm starting to believe that this is related to the Bonjour Sleep Proxy that I mentioned in #39. After studying some logs with Wireshark, I can see that requests are sent to the Apple TV and I get a response. Shortly thereafter the request goes to my AirPort Express instead (IP to the device is correct, but not the MAC). Device map looks like this:

• Raspberr_53:4d:f5: Raspberry Pi I run atvremote on
• Apple_d6:41:09: Apple TV
• Apple_42:86:92: My AirPort express (Bonjour Sleep Proxy in this case)

One request that works looks like this:

19	0.112848	10.0.10.45	10.0.10.22	TCP	66	48384 → 3689 [ACK] Seq=1009 Ack=604 Win=32512 Len=0 TSval=24485402 TSecr=1038588150	Raspberr_53:4d:f5	Apple_d6:41:09 (Apple TV)
22	10.125691	10.0.10.22	10.0.10.45	HTTP	243	HTTP/1.1 200 OK 	Apple_d6:41:09	Raspberr_53:4d:f5
21	10.119631	10.0.10.22	10.0.10.45	TCP	66	3689 → 48384 [ACK] Seq=604 Ack=1349 Win=130720 Len=0 TSval=1038598179 TSecr=24486402	Apple_d6:41:09	Raspberr_53:4d:f5

A few frames later, the destination MAC changes to my AP:

26	21.122199	10.0.10.45	10.0.10.22	HTTP	406	GET /ctrl-int/1/playstatusupdate?session-id=686737999&revision-number=0 HTTP/1.1 	Raspberr_53:4d:f5	Apple_42:86:92 (AirPort Express)
27	21.332874	10.0.10.45	10.0.10.22	TCP	406	[TCP Retransmission] 48384 → 3689 [PSH, ACK] Seq=1349 Ack=823 Win=33536 Len=340 TSval=24487524 TSecr=1038598184	Raspberr_53:4d:f5	Apple_42:86:92
28	21.552909	10.0.10.45	10.0.10.22	TCP	406	[TCP Retransmission] 48384 → 3689 [PSH, ACK] Seq=1349 Ack=823 Win=33536 Len=340 TSval=24487546 TSecr=1038598184	Raspberr_53:4d:f5	Apple_42:86:92

Very odd. But at least I have something to work with now as I have a great deal of problems with this. I just saved traffic on port 3689, so I cannot see if any ARP traffic happened. Will have to verify that later.

[postlund]

I have not seen this anymore, must have been a really strange environment issue. Will close this for now and open it in case it comes back.

[paviro]

Seems like I have this problem as well...

DEBUG: Discovering devices for 3 seconds
DEBUG: Auto-discovered service Wohnzimmer at 192.168.178.29 (hsgid: XXXXX)
DEBUG: Ignoring 192.168.178.29 since its already known with HSGID
DEBUG: Aborting since a device was found
INFO: Auto-discovered Wohnzimmer at 192.168.178.29
DEBUG: GET URL: http://192.168.178.29:3689/login?hsgid= XXXXX&hasFP=1
/srv/homeassistant/lib/python3.5/site-packages/pyatv/internal/apple_tv.py:509: RuntimeWarning: coroutine 'ClientSession.close' was never awaited
  self._session.close()
Traceback (most recent call last):
  File "/srv/homeassistant/lib/python3.5/site-packages/pyatv/__main__.py", line 420, in _run_application
    return (yield from cli_handler(loop))
  File "/srv/homeassistant/lib/python3.5/site-packages/pyatv/__main__.py", line 255, in cli_handler
    return (yield from _handle_autodiscover(args, loop))
  File "/srv/homeassistant/lib/python3.5/site-packages/pyatv/__main__.py", line 299, in _handle_autodiscover
    return (yield from _handle_commands(args, loop))
  File "/srv/homeassistant/lib/python3.5/site-packages/pyatv/__main__.py", line 331, in _handle_commands
    ret = yield from _handle_device_command(args, cmd, atv, loop)
  File "/srv/homeassistant/lib/python3.5/site-packages/pyatv/__main__.py", line 362, in _handle_device_command
    atv.metadata, cmd, True, *cmd_args))
  File "/srv/homeassistant/lib/python3.5/site-packages/pyatv/__main__.py", line 385, in _exec_command
    value = yield from tmp(*args)
  File "/srv/homeassistant/lib/python3.5/site-packages/pyatv/internal/apple_tv.py", line 321, in playing
    playstatus = yield from self.apple_tv.playstatus()
  File "/srv/homeassistant/lib/python3.5/site-packages/pyatv/internal/apple_tv.py", line 55, in playstatus
    resp = yield from self.daap.get(cmd_url, timeout=timeout)
  File "/srv/homeassistant/lib/python3.5/site-packages/pyatv/daap.py", line 65, in get
    yield from self._assure_logged_in()
  File "/srv/homeassistant/lib/python3.5/site-packages/pyatv/daap.py", line 127, in _assure_logged_in
    yield from self.login()
  File "/srv/homeassistant/lib/python3.5/site-packages/pyatv/daap.py", line 51, in login
    resp = yield from self._do(_login_request, is_login=True)
  File "/srv/homeassistant/lib/python3.5/site-packages/pyatv/daap.py", line 89, in _do
    resp, status = yield from action()
  File "/srv/homeassistant/lib/python3.5/site-packages/pyatv/net.py", line 39, in get_data
    raise ex
  File "/srv/homeassistant/lib/python3.5/site-packages/pyatv/net.py", line 30, in get_data
    timeout=DEFAULT_TIMEOUT if timeout is None else timeout)
  File "/srv/homeassistant/lib/python3.5/site-packages/aiohttp/client.py", line 391, in _request
    await resp.start(conn)
  File "/srv/homeassistant/lib/python3.5/site-packages/aiohttp/client_reqrep.py", line 770, in start
    self._continue = None
  File "/srv/homeassistant/lib/python3.5/site-packages/aiohttp/helpers.py", line 673, in __exit__
    raise asyncio.TimeoutError from None
concurrent.futures._base.TimeoutError

>>> An error occurred, full stack trace above
ERROR: Unclosed client session
client_session: <aiohttp.client.ClientSession object at 0x8082f6630>

Currently running inside a FreeNAS Jail but it definitely worked before and I can't seem to remember to have changed anything besides updating Homeassistant.

Update: Just testes the same command (atvremote --debug -a playing) on my Mac and I got the same error.

Used Hardware: Apple TV3 with the latest tvOS