Same issue was now reported here: https://github.com/home-assistant/home-assistant/issues/6276
Can you try that our as well? Also, maybe you can add this in your config as well:
logger:
logs:
pyatv.daap: debug
That should give more output hopefully.
One more thing… If you try atvremote --debug artwork, what happens?
Atvremove --debug artwork:
ERROR: To autodiscover an Apple TV, add -a
Atvremove -a --debug artwork:
DEBUG: Discovering devices for 3 seconds DEBUG: Auto-discovered service Living Room TV at 192.168.X.X (hsgid: 00000000-0763-7101-c2b7-b1f779354111) DEBUG: Auto-discovered service Office at 192.168.X.X (hsgid: 00000000-0763-7101-c2b7-b1f779354111) ERROR: Found more than one Apple TV; specify one using --address and --login_id Found Apple TVs: - Living Room TV at 192.168.X.X (login id: 00000000-0763-7101-c2b7-b1f779354111) - Office at 192.168.X.X (login id: 00000000-0763-7101-c2b7-b1f779354111)
atvremote --debug --address 192.168.X.X --login_id 00000000-0763-7101-c2b7-b1f779354111 artwork:
DEBUG: GET URL: http://192.168.X.X:3689/login?hsgid=00000000-0763-7101-c2b7-b1f779354111&hasFP=1 DEBUG: Data[32]: b'6d6c6f67000000186d73747400000004000000c86d6c69640000000400000023' DEBUG: _login_request: mlog: [container, dmap.loginresponse] mstt: 200 [uint, dmap.status] mlid: 35 [uint, dmap.sessionid]
INFO: Logged in and got session id 35 DEBUG: GET URL: http://192.168.X.X:3689/ctrl-int/1/playstatusupdate?session-id=35&revision-number=0 DEBUG: Data[155]: b'636d7374000000936d73747400000004000000c8636d7372000000040000002e63616673000000010063616665000000010063617665000000010063617673000000010063617073000000010363617368000000010063617270000000010063616172000000040000000663616173000000040000000263616b730000000106'... DEBUG: _get_request: cmst: [container, dmcp.playstatus] mstt: 200 [uint, dmap.status] cmsr: 46 [uint, dmcp.serverrevision] cafs: 0 [uint, dacp.fullscreen] cafe: False [bool, dacp.fullscreenenabled] cave: False [bool, dacp.dacpvisualizerenabled] cavs: 0 [uint, dacp.visualizer] caps: 3 [uint, dacp.playstatus] cash: 0 [uint, dacp.shufflestate] carp: 0 [uint, dacp.repeatstate] caar: 6 [uint, dacp.albumrepeat] caas: 2 [uint, dacp.albumshuffle] caks: 6 [uint, unknown tag] casc: 1 [uint, unknown tag] cavc: True [bool, dacp.volumecontrollable] casu: 0 [uint, dacp.su]
DEBUG: Already logged in, re-using seasion id 35 DEBUG: GET URL: http://192.168.X.X:3689/ctrl-int/1/nowplayingartwork?mw=1024&mh=576&session-id=35 DEBUG: Data[0]: b'' DEBUG: _get_request: b'' No artwork is currently available.
Thanks for the update! Not sure yet why this happen, but I think I fixed it in https://github.com/home-assistant/home-assistant/pull/6323.
@aaronwolen, if you have time to test, the PR above has push update support 
I’ll test out the new code and report back.
However, I haven’t received a failed to login: 400 (bad login id?) error since updating to 0.39. I still get the occasional
[homeassistant.components.media_player.apple_tv] timed out while connecting to Apple TV
but no more log flooding 
Cool, then it might have been fixed after the actual 0.38 release. A few things didn’t make it in time The “timed out” errors will probably never go away and they will look a bit different now. But they are usually not a problem since they should only occur when device is in standby or offline for some other reason. So we should be fine
Not a peep from Apple TV in my logs after incorporating PR #6323. Even better, artwork now shows up, which is super awesome! 
Thanks so much for your work on this. It’s an awesome addition to HA.
One thing I noticed is the widget does a little dance every few seconds:
It’s not a big deal, just thought I’d mention it.
That is awesome to hear! 
But it should not behave like that. Can you enable the pyatv logs just so we can see if it performs any excessive requests? Just to understand the situation. Now, you are watching something but have put it in pause mode? Does it always do this even if you are not playing anything?
It’s not just the Apple TV component, I think it’s a Media_Player issue since I see this on my Roku and Sonos as well.
Uh oh, they’re back and in greater numbers:
Mar 03 09:10:59 raspberrypi2 hass[23372]: 17-03-03 09:10:59 WARNING (MainThread) [homeassistant.components.media_player.apple_tv] A <class 'pyatv.exceptions.AuthenticationError'> error occurred: failed to login: 400
Here’s the output from atvremote --debug artwork:
DEBUG: GET URL: http://192.168.1.204:3689/login?hsgid=REDACT&hasFP=1
DEBUG: Data[32]: b'6d6c6f67000000186d73747400000004000000c86d6c6964000000040000000e'
DEBUG: _login_request: mlog: [container, dmap.loginresponse]
mstt: 200 [uint, dmap.status]
mlid: 14 [uint, dmap.sessionid]
INFO: Logged in and got session id 14
DEBUG: GET URL: http://192.168.1.204:3689/ctrl-int/1/playstatusupdate?session-id=14&revision-number=0
DEBUG: Data[155]: b'636d7374000000936d73747400000004000000c8636d737200000004000000aa63616673000000010063616665000000010063617665000000010063617673000000010063617073000000010363617368000000010063617270000000010063616172000000040000000663616173000000040000000263616b730000000101'...
DEBUG: _get_request: cmst: [container, dmcp.playstatus]
mstt: 200 [uint, dmap.status]
cmsr: 170 [uint, dmcp.serverrevision]
cafs: 0 [uint, dacp.fullscreen]
cafe: False [bool, dacp.fullscreenenabled]
cave: False [bool, dacp.dacpvisualizerenabled]
cavs: 0 [uint, dacp.visualizer]
caps: 3 [uint, dacp.playstatus]
cash: 0 [uint, dacp.shufflestate]
carp: 0 [uint, dacp.repeatstate]
caar: 6 [uint, dacp.albumrepeat]
caas: 2 [uint, dacp.albumshuffle]
caks: 1 [uint, unknown tag]
casc: 1 [uint, unknown tag]
cavc: True [bool, dacp.volumecontrollable]
casu: 0 [uint, dacp.su]
DEBUG: Already logged in, re-using seasion id 14
DEBUG: GET URL: http://192.168.1.204:3689/ctrl-int/1/nowplayingartwork?mw=1024&mh=576&session-id=14
DEBUG: Data[0]: b''
DEBUG: _get_request: b''
No artwork is currently available.
This is on HASS 0.39.2 with PR PR #6323 incorporated.
Ok, very strange. I don’t see this at all with my device. One thing I would like to try is pairing and see if that helps. Current support in pyatv is not ideal and I’m gonna push some improvements to it. Still not 100% done, also want to incorporate this support into Home Assistant.
But in the meantime, I just released pyatv 0.2.2, maybe you can install that in a venv or so and try to pair (just atvremote pair) and use the randomized pairing guid you get? Would be interesting to see if it helps.
Same issue here on all 3 ATV’s – running 39.3
Just installed 0.40.1, which has introduced a new crop of Apple TV related errors:
Mar 16 10:50:36 raspberrypi2 hass[21163]: 17-03-16 10:50:36 WARNING (MainThread) [homeassistant.components.media_player.apple_tv] A <class 'AttributeError'> error occurred: 'NoneType' object has no attribute 'cancel'
Mar 16 10:50:46 raspberrypi2 hass[21163]: 17-03-16 10:50:46 WARNING (MainThread) [homeassistant.components.media_player.apple_tv] A <class 'AttributeError'> error occurred: 'NoneType' object has no attribute 'cancel'
Mar 16 10:50:56 raspberrypi2 hass[21163]: 17-03-16 10:50:56 WARNING (MainThread) [homeassistant.components.media_player.apple_tv] A <class 'AttributeError'> error occurred: 'NoneType' object has no attribute 'cancel'
Mar 16 10:51:01 raspberrypi2 hass[21163]: 17-03-16 10:51:01 ERROR (MainThread) [homeassistant.core] Error doing job: Unclosed connection
Mar 16 10:51:01 raspberrypi2 hass[21163]: 17-03-16 10:51:01 ERROR (MainThread) [homeassistant.core] Error doing job: Unclosed response
Mar 16 10:51:01 raspberrypi2 hass[21163]: 17-03-16 10:51:01 ERROR (MainThread) [homeassistant.core] Error doing job: Unclosed connection
Mar 16 10:51:01 raspberrypi2 hass[21163]: 17-03-16 10:51:01 ERROR (MainThread) [homeassistant.core] Error doing job: Unclosed response
Mar 16 10:51:01 raspberrypi2 hass[21163]: 17-03-16 10:51:01 ERROR (MainThread) [homeassistant.core] Error doing job: Unclosed connection
Mar 16 10:51:01 raspberrypi2 hass[21163]: 17-03-16 10:51:01 ERROR (MainThread) [homeassistant.core] Error doing job: Unclosed response
Mar 16 10:51:06 raspberrypi2 hass[21163]: 17-03-16 10:51:06 WARNING (MainThread) [homeassistant.components.media_player.apple_tv] A <class 'AttributeError'> error occurred: 'NoneType' object has no attribute 'cancel'
Is anyone else seeing this in their log?
Still seeing quite a few failed logins, also my atv tiles do the little dance as well.
grep "failed to login" /etc/homeassistant/home-assistant.log |wc -l 5769
Running version 0.41.0
Can you try to do something with atvremote when you see these errors? A theory I have is that a re-login would help and maybe if you login from somewhere else, Home Assistant would perform a new login since the session it uses would no longer be valid. So basically, run Home Assistant as usual and just run “atvremote -a playing” or so in another shell. Hopefully you should find a log printout along the line “implicitly logged out” in your log. If this works, I can add a check I pyatv do a re-login of error 400 happens.
Yea, I’ll give that a try the next time I see the 400 errors in my logs, and report back.
@aaronwolen @Jer78 I couldn’t find a specific thread about the dancing media player component, that I’m also experiencing, so I started one! Media_Player Dancing
So I was working on HA again today, and noticed the good ole “400” error. In another terminal, I ran “atvremote -a playing”, but I did not see the “implicitly logged out” message in my logs.
Here’s what I did see…
17-04-09 19:34:00 WARNING (MainThread) [homeassistant.components.media_player.apple_tv] A <class 'pyatv.exceptions.AuthenticationError'> error occurred: failed to login: 400 17-04-09 19:34:10 WARNING (MainThread) [homeassistant.components.media_player.apple_tv] A <class 'pyatv.exceptions.AuthenticationError'> error occurred: failed to login: 400 17-04-09 19:34:20 WARNING (MainThread) [homeassistant.components.media_player.apple_tv] A <class 'pyatv.exceptions.AuthenticationError'> error occurred: failed to login: 400 17-04-09 19:34:30 WARNING (MainThread) [homeassistant.components.media_player.apple_tv] A <class 'pyatv.exceptions.AuthenticationError'> error occurred: failed to login: 400 17-04-09 19:34:40 WARNING (MainThread) [homeassistant.components.media_player.apple_tv] A <class 'pyatv.exceptions.AuthenticationError'> error occurred: failed to login: 400 Apr 9 19:34:40 droid hass[7767]: #033[33m17-04-09 19:34:40 WARNING (MainThread) [homeassistant.components.media_player.apple_tv] A <class 'pyatv.exceptions.AuthenticationError'> error occurred: failed to login: 400#033[0m 17-04-09 19:34:50 WARNING (MainThread) [homeassistant.components.media_player.apple_tv] A <class 'pyatv.exceptions.AuthenticationError'> error occurred: failed to login: 400 Apr 9 19:34:50 droid hass[7767]: #033[33m17-04-09 19:34:50 WARNING (MainThread) [homeassistant.components.media_player.apple_tv] A <class 'pyatv.exceptions.AuthenticationError'> error occurred: failed to login: 400#033[0m Apr 9 19:35:00 droid hass[7767]: #033[33m17-04-09 19:35:00 WARNING (MainThread) [homeassistant.components.media_player.apple_tv] A <class 'pyatv.exceptions.AuthenticationError'> error occurred: failed to login: 400#033[0m 17-04-09 19:35:00 WARNING (MainThread) [homeassistant.components.media_player.apple_tv] A <class 'pyatv.exceptions.AuthenticationError'> error occurred: failed to login: 400 17-04-09 19:35:10 WARNING (MainThread) [homeassistant.components.media_player.apple_tv] A <class 'pyatv.exceptions.AuthenticationError'> error occurred: failed to login: 400 Apr 9 19:35:10 droid hass[7767]: #033[33m17-04-09 19:35:10 WARNING (MainThread) [homeassistant.components.media_player.apple_tv] A <class 'pyatv.exceptions.AuthenticationError'> error occurred: failed to login: 400#033[0m 17-04-09 19:35:20 WARNING (MainThread) [homeassistant.components.media_player.apple_tv] A <class 'pyatv.exceptions.AuthenticationError'> error occurred: failed to login: 400 Apr 9 19:35:20 droid hass[7767]: #033[33m17-04-09 19:35:20 WARNING (MainThread) [homeassistant.components.media_player.apple_tv] A <class 'pyatv.exceptions.AuthenticationError'> error occurred: failed to login: 400#033[0m
Hi all,
Chiming in with the same issue.
“atvremote -a playing” gives the correct output, but no “implicitly logged out” message appears in the logs. 400 errors continue.