Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

AppleTV platform stopped working in 0.40.0 (push_updates) #6642

Closed
UltraSub opened this issue Mar 15, 2017 · 22 comments
Closed

AppleTV platform stopped working in 0.40.0 (push_updates) #6642

UltraSub opened this issue Mar 15, 2017 · 22 comments

Comments

@UltraSub
Copy link

Home Assistant release:
0.40.0

Python release:
Python 3.5.2+

Component/platform:
apple_tv

Description of problem:
Upgraded from 38.2 to 40.0 which brought push updates, but now I get "Not connected to Apple TV" in the mediaplayer card and a lot of repeating errors:
An error occurred (restarting): 'NoneType' object has no attribute 'cancel'

Expected:
A working AppleTV component :)

Debug output
Using atvremote I can login and work fine with the apple tv's using various commands. Wat doesn't work is push_updates command, this produces the following:

INFO: Logged in and got session id 2037286001
Press ENTER to stop
An error occurred (restarting): 'NoneType' object has no attribute 'cancel'
An error occurred (restarting): 'NoneType' object has no attribute 'cancel'
An error occurred (restarting): 'NoneType' object has no attribute 'cancel'
ERROR: Unclosed connection
client_connection: Connection<('<redacted>', 3689, False)>
ERROR: Unclosed response
client_response: <ClientResponse(http://<redacted>:3689/ctrl-int/1/playstatusupdate?session-id=2037286001&revision-number=0) [200 OK]>
<CIMultiDictProxy('Date': 'Wed, 15 Mar 2017 18:11:43 GMT', 'Daap-Server': 'iTunes/11.1b37 (OS X)', 'Content-Type': 'application/x-dmap-tagged', 'Content-Length': '42', 'Content-Encoding': 'gzip')>

ERROR: Unclosed connection
client_connection: Connection<('<redacted>', 3689, False)>
ERROR: Unclosed response
client_response: <ClientResponse(http://<redacted>:3689/ctrl-int/1/playstatusupdate?session-id=2037286001&revision-number=0) [200 OK]>
<CIMultiDictProxy('Date': 'Wed, 15 Mar 2017 18:11:44 GMT', 'Daap-Server': 'iTunes/11.1b37 (OS X)', 'Content-Type': 'application/x-dmap-tagged', 'Content-Length': '42', 'Content-Encoding': 'gzip')>

ERROR: Unclosed connection
client_connection: Connection<('<redacted>', 3689, False)>
ERROR: Unclosed response
client_response: <ClientResponse(http://<redacted>:3689/ctrl-int/1/playstatusupdate?session-id=2037286001&revision-number=0) [200 OK]>
<CIMultiDictProxy('Date': 'Wed, 15 Mar 2017 18:11:45 GMT', 'Daap-Server': 'iTunes/11.1b37 (OS X)', 'Content-Type': 'application/x-dmap-tagged', 'Content-Length': '42', 'Content-Encoding': 'gzip')>

An error occurred (restarting): 'NoneType' object has no attribute 'cancel'
An error occurred (restarting): 'NoneType' object has no attribute 'cancel'
An error occurred (restarting): 'NoneType' object has no attribute 'cancel'
An error occurred (restarting): 'NoneType' object has no attribute 'cancel'

ERROR: Unclosed connection

Since by default the platform now uses push_updates I think this is cause?

@schmittx
Copy link
Contributor

I'm experiencing the exact same bug.

AppleTV component was working fine on 0.39.x with Python 3.6.x but after upgrading to 0.40 I get the same "Not Connected to Apple TV" and error logs as @UltraSub

@postlund
Copy link
Contributor

Interesting, I have not seen this before. I will have to look into this later today. If I prepare a branch with some additional logging, can any of you try that out for me? Also, it would help a bit if you try to run atvremote --debug -a push_updates.

@UltraSub
Copy link
Author

Not yet running a development instance of HA. If you tell me how to test your branch on my production instance I will test, no problem!

@rwmessner
Copy link

I'm having the same problem, I did run atvremote -v -a push_updates and it shows connection/etc but throws the same error as Ultrasub.

@postlund
Copy link
Contributor

Runnig with --debug prints one extra output, can you provide what's printed to the terminal? It will help a lot.

@UltraSub
Copy link
Author

UltraSub commented Mar 16, 2017

Here it is:

(hass) hass@<redacted>:~$ atvremote --debug --address <redacted> --login_id <redacted> -v push_updates
INFO: Logged in and got session id 1371316799 Press ENTER to stop An error occurred (restarting): 'NoneType' object has no attribute 'cancel'
An error occurred (restarting): 'NoneType' object has no attribute 'cancel'
An error occurred (restarting): 'NoneType' object has no attribute 'cancel'
ERROR: Unclosed connection
client_connection: Connection<('<redacted>', 3689, False)>
ERROR: Unclosed response
client_response: <ClientResponse(http://<redacted>:3689/ctrl-int/1/playstatusupdate?session-id=1371316799&revision-number=0) [200 OK]>
<CIMultiDictProxy('Date': 'Thu, 16 Mar 2017 13:33:25 GMT', 'Daap-Server': 'iTunes/11.1b37 (OS X)', 'Content-Type': 'application/x-dmap-tagged', 'Content-Length': '42', 'Content-Encoding': 'gzip')>

ERROR: Unclosed connection
client_connection: Connection<('<redacted>', 3689, False)>
ERROR: Unclosed response
client_response: <ClientResponse(http://<redacted>:3689/ctrl-int/1/playstatusupdate?session-id=1371316799&revision-number=0) [200 OK]>
<CIMultiDictProxy('Date': 'Thu, 16 Mar 2017 13:33:26 GMT', 'Daap-Server': 'iTunes/11.1b37 (OS X)', 'Content-Type': 'application/x-dmap-tagged', 'Content-Length': '42', 'Content-Encoding': 'gzip')>

ERROR: Unclosed connection
client_connection: Connection<('<redacted>', 3689, False)>
ERROR: Unclosed response
client_response: <ClientResponse(http://<redacted>:3689/ctrl-int/1/playstatusupdate?session-id=1371316799&revision-number=0) [200 OK]>
<CIMultiDictProxy('Date': 'Thu, 16 Mar 2017 13:33:27 GMT', 'Daap-Server': 'iTunes/11.1b37 (OS X)', 'Content-Type': 'application/x-dmap-tagged', 'Content-Length': '42', 'Content-Encoding': 'gzip')>

An error occurred (restarting): 'NoneType' object has no attribute 'cancel'
An error occurred (restarting): 'NoneType' object has no attribute 'cancel'
An error occurred (restarting): 'NoneType' object has no attribute 'cancel'
An error occurred (restarting): 'NoneType' object has no attribute 'cancel'
An error occurred (restarting): 'NoneType' object has no attribute 'cancel'
An error occurred (restarting): 'NoneType' object has no attribute 'cancel'
An error occurred (restarting): 'NoneType' object has no attribute 'cancel'
An error occurred (restarting): 'NoneType' object has no attribute 'cancel'
An error occurred (restarting): 'NoneType' object has no attribute 'cancel'
An error occurred (restarting): 'NoneType' object has no attribute 'cancel'
ERROR: Unclosed connection
client_connection: Connection<('<redacted>', 3689, False)>
ERROR: Unclosed response
client_response: <ClientResponse(http://<redacted>:3689/ctrl-int/1/playstatusupdate?session-id=1371316799&revision-number=0) [200 OK]>
<CIMultiDictProxy('Date': 'Thu, 16 Mar 2017 13:33:29 GMT', 'Daap-Server': 'iTunes/11.1b37 (OS X)', 'Content-Type': 'application/x-dmap-tagged', 'Content-Length': '42', 'Content-Encoding': 'gzip')>

ERROR: Unclosed connection
client_connection: Connection<('<redacted>', 3689, False)>
ERROR: Unclosed response
client_response: <ClientResponse(http://<redacted>:3689/ctrl-int/1/playstatusupdate?session-id=1371316799&revision-number=0) [200 OK]>
<CIMultiDictProxy('Date': 'Thu, 16 Mar 2017 13:33:30 GMT', 'Daap-Server': 'iTunes/11.1b37 (OS X)', 'Content-Type': 'application/x-dmap-tagged', 'Content-Length': '42', 'Content-Encoding': 'gzip')>

ERROR: Unclosed connection
client_connection: Connection<('<redacted>', 3689, False)>
ERROR: Unclosed response
client_response: <ClientResponse(http://<redacted>:3689/ctrl-int/1/playstatusupdate?session-id=1371316799&revision-number=0) [200 OK]>
<CIMultiDictProxy('Date': 'Thu, 16 Mar 2017 13:33:31 GMT', 'Daap-Server': 'iTunes/11.1b37 (OS X)', 'Content-Type': 'application/x-dmap-tagged', 'Content-Length': '42', 'Content-Encoding': 'gzip')>

ERROR: Unclosed connection
client_connection: Connection<('<redacted>', 3689, False)>
ERROR: Unclosed response
client_response: <ClientResponse(http://<redacted>:3689/ctrl-int/1/playstatusupdate?session-id=1371316799&revision-number=0) [200 OK]>
<CIMultiDictProxy('Date': 'Thu, 16 Mar 2017 13:33:32 GMT', 'Daap-Server': 'iTunes/11.1b37 (OS X)', 'Content-Type': 'application/x-dmap-tagged', 'Content-Length': '42', 'Content-Encoding': 'gzip')>

ERROR: Unclosed connection
client_connection: Connection<('<redacted>', 3689, False)>
ERROR: Unclosed response
client_response: <ClientResponse(http://<redacted>:3689/ctrl-int/1/playstatusupdate?session-id=1371316799&revision-number=0) [200 OK]>
<CIMultiDictProxy('Date': 'Thu, 16 Mar 2017 13:33:33 GMT', 'Daap-Server': 'iTunes/11.1b37 (OS X)', 'Content-Type': 'application/x-dmap-tagged', 'Content-Length': '42', 'Content-Encoding': 'gzip')>

ERROR: Unclosed connection
client_connection: Connection<('<redacted>', 3689, False)>
ERROR: Unclosed response
client_response: <ClientResponse(http://<redacted>:3689/ctrl-int/1/playstatusupdate?session-id=1371316799&revision-number=0) [200 OK]>
<CIMultiDictProxy('Date': 'Thu, 16 Mar 2017 13:33:34 GMT', 'Daap-Server': 'iTunes/11.1b37 (OS X)', 'Content-Type': 'application/x-dmap-tagged', 'Content-Length': '42', 'Content-Encoding': 'gzip')>

ERROR: Unclosed connection
client_connection: Connection<('<redacted>', 3689, False)>
ERROR: Unclosed response
client_response: <ClientResponse(http://<redacted>:3689/ctrl-int/1/playstatusupdate?session-id=1371316799&revision-number=0) [200 OK]>
<CIMultiDictProxy('Date': 'Thu, 16 Mar 2017 13:33:35 GMT', 'Daap-Server': 'iTunes/11.1b37 (OS X)', 'Content-Type': 'application/x-dmap-tagged', 'Content-Length': '42', 'Content-Encoding': 'gzip')>

ERROR: Unclosed connection
client_connection: Connection<('<redacted>', 3689, False)>
ERROR: Unclosed response
client_response: <ClientResponse(http://<redacted>:3689/ctrl-int/1/playstatusupdate?session-id=1371316799&revision-number=0) [200 OK]>
<CIMultiDictProxy('Date': 'Thu, 16 Mar 2017 13:33:36 GMT', 'Daap-Server': 'iTunes/11.1b37 (OS X)', 'Content-Type': 'application/x-dmap-tagged', 'Content-Length': '42', 'Content-Encoding': 'gzip')>

ERROR: Unclosed connection
client_connection: Connection<('<redacted>', 3689, False)>
ERROR: Unclosed response
client_response: <ClientResponse(http://<redacted>:3689/ctrl-int/1/playstatusupdate?session-id=1371316799&revision-number=0) [200 OK]>
<CIMultiDictProxy('Date': 'Thu, 16 Mar 2017 13:33:37 GMT', 'Daap-Server': 'iTunes/11.1b37 (OS X)', 'Content-Type': 'application/x-dmap-tagged', 'Content-Length': '42', 'Content-Encoding': 'gzip')>

An error occurred (restarting): 'NoneType' object has no attribute 'cancel'
An error occurred (restarting): 'NoneType' object has no attribute 'cancel'
An error occurred (restarting): 'NoneType' object has no attribute 'cancel'
An error occurred (restarting): 'NoneType' object has no attribute 'cancel'
An error occurred (restarting): 'NoneType' object has no attribute 'cancel'
An error occurred (restarting): 'NoneType' object has no attribute 'cancel'

ERROR: Unclosed connection
client_connection: Connection<('<redacted>', 3689, False)>
ERROR: Unclosed response
client_response: <ClientResponse(http://<redacted>:3689/ctrl-int/1/playstatusupdate?session-id=1371316799&revision-number=0) [200 OK]>
<CIMultiDictProxy('Date': 'Thu, 16 Mar 2017 13:33:38 GMT', 'Daap-Server': 'iTunes/11.1b37 (OS X)', 'Content-Type': 'application/x-dmap-tagged', 'Content-Length': '42', 'Content-Encoding': 'gzip')>

ERROR: Unclosed connection
client_connection: Connection<('<redacted>', 3689, False)>
ERROR: Unclosed response
client_response: <ClientResponse(http://<redacted>:3689/ctrl-int/1/playstatusupdate?session-id=1371316799&revision-number=0) [200 OK]>
<CIMultiDictProxy('Date': 'Thu, 16 Mar 2017 13:33:39 GMT', 'Daap-Server': 'iTunes/11.1b37 (OS X)', 'Content-Type': 'application/x-dmap-tagged', 'Content-Length': '42', 'Content-Encoding': 'gzip')>

ERROR: Unclosed connection
client_connection: Connection<('<redacted>', 3689, False)>
ERROR: Unclosed response
client_response: <ClientResponse(http://<redacted>:3689/ctrl-int/1/playstatusupdate?session-id=1371316799&revision-number=0) [200 OK]>
<CIMultiDictProxy('Date': 'Thu, 16 Mar 2017 13:33:40 GMT', 'Daap-Server': 'iTunes/11.1b37 (OS X)', 'Content-Type': 'application/x-dmap-tagged', 'Content-Length': '42', 'Content-Encoding': 'gzip')>

ERROR: Unclosed connection
client_connection: Connection<('<redacted>', 3689, False)>
ERROR: Unclosed response
client_response: <ClientResponse(http://<redacted>:3689/ctrl-int/1/playstatusupdate?session-id=1371316799&revision-number=0) [200 OK]>
<CIMultiDictProxy('Date': 'Thu, 16 Mar 2017 13:33:41 GMT', 'Daap-Server': 'iTunes/11.1b37 (OS X)', 'Content-Type': 'application/x-dmap-tagged', 'Content-Length': '42', 'Content-Encoding': 'gzip')>

ERROR: Unclosed connection
client_connection: Connection<('<redacted>', 3689, False)>
ERROR: Unclosed response
client_response: <ClientResponse(http://<redacted>:3689/ctrl-int/1/playstatusupdate?session-id=1371316799&revision-number=0) [200 OK]>
<CIMultiDictProxy('Date': 'Thu, 16 Mar 2017 13:33:42 GMT', 'Daap-Server': 'iTunes/11.1b37 (OS X)', 'Content-Type': 'application/x-dmap-tagged', 'Content-Length': '42', 'Content-Encoding': 'gzip')>

ERROR: Unclosed connection
client_connection: Connection<('<redacted>', 3689, False)>
ERROR: Unclosed response
client_response: <ClientResponse(http://<redacted>:3689/ctrl-int/1/playstatusupdate?session-id=1371316799&revision-number=0) [200 OK]>
<CIMultiDictProxy('Date': 'Thu, 16 Mar 2017 13:33:43 GMT', 'Daap-Server': 'iTunes/11.1b37 (OS X)', 'Content-Type': 'application/x-dmap-tagged', 'Content-Length': '42', 'Content-Encoding': 'gzip')>

ERROR: Unclosed connection
client_connection: Connection<('<redacted>', 3689, False)>
ERROR: Unclosed response
client_response: <ClientResponse(http://<redacted>:3689/ctrl-int/1/playstatusupdate?session-id=1371316799&revision-number=0) [200 OK]>
<CIMultiDictProxy('Date': 'Thu, 16 Mar 2017 13:33:28 GMT', 'Daap-Server': 'iTunes/11.1b37 (OS X)', 'Content-Type': 'application/x-dmap-tagged', 'Content-Length': '42', 'Content-Encoding': 'gzip')>

@postlund
Copy link
Contributor

There seems to be a bug in atvremote so that --debug is ignored if -v is specified after that flag. Can you remove -v and run again? It is not needed as --debug logs everything. I will write a bug report about this.

@UltraSub
Copy link
Author

UltraSub commented Mar 16, 2017

(hass) hass@<redacted>:~$ atvremote --debug --address <redacted> --login_id <redacted> push_updates
DEBUG: GET URL: http://<redacted>:3689/login?hsgid=<redacted>&hasFP=1
DEBUG: Data[32]: b'6d6c6f67000000186d73747400000004000000c86d6c6964000000044e9c7901'
DEBUG: _login_request: mlog: [container, dmap.loginresponse]
  mstt: 200 [uint, dmap.status]
  mlid: 1318877441 [uint, dmap.sessionid]

INFO: Logged in and got session id 1318877441
DEBUG: GET URL: http://<redacted>:3689/ctrl-int/1/playstatusupdate?session-id=1318877441&revision-number=0
DEBUG: Data[32]: b'636d7374000000186d73747400000004000000c8636d73720000000400000297'
DEBUG: _get_request: cmst: [container, dmcp.playstatus]
  mstt: 200 [uint, dmap.status]
  cmsr: 663 [uint, dmcp.serverrevision]

Press ENTER to stop
DEBUG: Waiting for playstatus updates
DEBUG: Already logged in, re-using seasion id 1318877441
DEBUG: GET URL: http://<redacted>:3689/ctrl-int/1/playstatusupdate?session-id=1318877441&revision-number=0
DEBUG: Playstatus error occurred: 'NoneType' object has no attribute 'cancel'
An error occurred (restarting): 'NoneType' object has no attribute 'cancel'
DEBUG: Initial delay set to 1
DEBUG: Waiting for playstatus updates
DEBUG: Already logged in, re-using seasion id 1318877441
DEBUG: GET URL: http://<redacted>:3689/ctrl-int/1/playstatusupdate?session-id=1318877441&revision-number=0
DEBUG: Playstatus error occurred: 'NoneType' object has no attribute 'cancel'
An error occurred (restarting): 'NoneType' object has no attribute 'cancel'
DEBUG: Initial delay set to 1
DEBUG: Waiting for playstatus updates
DEBUG: Already logged in, re-using seasion id 1318877441
DEBUG: GET URL: http://<redacted>:3689/ctrl-int/1/playstatusupdate?session-id=1318877441&revision-number=0
DEBUG: Playstatus error occurred: 'NoneType' object has no attribute 'cancel'
An error occurred (restarting): 'NoneType' object has no attribute 'cancel'
DEBUG: Initial delay set to 1
DEBUG: Waiting for playstatus updates
DEBUG: Already logged in, re-using seasion id 1318877441
DEBUG: GET URL: http://<redacted>:3689/ctrl-int/1/playstatusupdate?session-id=1318877441&revision-number=0
ERROR: Unclosed connection
client_connection: Connection<('<redacted>', 3689, False)>
ERROR: Unclosed response
client_response: <ClientResponse(http://<redacted>:3689/ctrl-int/1/playstatusupdate?session-id=1318877441&revision-number=0) [200 OK]>
<CIMultiDictProxy('Date': 'Thu, 16 Mar 2017 14:40:55 GMT', 'Daap-Server': 'iTunes/11.1b37 (OS X)', 'Content-Type': 'application/x-dmap-tagged', 'Content-Length': '42', 'Content-Encoding': 'gzip')>

ERROR: Unclosed connection
client_connection: Connection<('<redacted>', 3689, False)>
ERROR: Unclosed response
client_response: <ClientResponse(http://<redacted>:3689/ctrl-int/1/playstatusupdate?session-id=1318877441&revision-number=0) [200 OK]>
<CIMultiDictProxy('Date': 'Thu, 16 Mar 2017 14:40:56 GMT', 'Daap-Server': 'iTunes/11.1b37 (OS X)', 'Content-Type': 'application/x-dmap-tagged', 'Content-Length': '42', 'Content-Encoding': 'gzip')>

ERROR: Unclosed connection
client_connection: Connection<('<redacted>', 3689, False)>
ERROR: Unclosed response
client_response: <ClientResponse(http://<redacted>:3689/ctrl-int/1/playstatusupdate?session-id=1318877441&revision-number=0) [200 OK]>
<CIMultiDictProxy('Date': 'Thu, 16 Mar 2017 14:40:57 GMT', 'Daap-Server': 'iTunes/11.1b37 (OS X)', 'Content-Type': 'application/x-dmap-tagged', 'Content-Length': '42', 'Content-Encoding': 'gzip')>

DEBUG: Playstatus error occurred: 'NoneType' object has no attribute 'cancel'
An error occurred (restarting): 'NoneType' object has no attribute 'cancel'
DEBUG: Initial delay set to 1
DEBUG: Waiting for playstatus updates
DEBUG: Already logged in, re-using seasion id 1318877441
DEBUG: GET URL: http://<redacted>:3689/ctrl-int/1/playstatusupdate?session-id=1318877441&revision-number=0
DEBUG: Playstatus error occurred: 'NoneType' object has no attribute 'cancel'
An error occurred (restarting): 'NoneType' object has no attribute 'cancel'
DEBUG: Initial delay set to 1
DEBUG: Waiting for playstatus updates
DEBUG: Already logged in, re-using seasion id 1318877441
DEBUG: GET URL: http://<redacted>:3689/ctrl-int/1/playstatusupdate?session-id=1318877441&revision-number=0
DEBUG: Playstatus error occurred: 'NoneType' object has no attribute 'cancel'
An error occurred (restarting): 'NoneType' object has no attribute 'cancel'
DEBUG: Initial delay set to 1
DEBUG: Waiting for playstatus updates
DEBUG: Already logged in, re-using seasion id 1318877441
DEBUG: GET URL: http://<redacted>:3689/ctrl-int/1/playstatusupdate?session-id=1318877441&revision-number=0
DEBUG: Playstatus error occurred: 'NoneType' object has no attribute 'cancel'
An error occurred (restarting): 'NoneType' object has no attribute 'cancel'
DEBUG: Initial delay set to 1
DEBUG: Waiting for playstatus updates
DEBUG: Already logged in, re-using seasion id 1318877441
DEBUG: GET URL: http://<redacted>:3689/ctrl-int/1/playstatusupdate?session-id=1318877441&revision-number=0
DEBUG: Playstatus error occurred: 'NoneType' object has no attribute 'cancel'
An error occurred (restarting): 'NoneType' object has no attribute 'cancel'
DEBUG: Initial delay set to 1
DEBUG: Waiting for playstatus updates
DEBUG: Already logged in, re-using seasion id 1318877441
DEBUG: GET URL: http://<redacted>:3689/ctrl-int/1/playstatusupdate?session-id=1318877441&revision-number=0
DEBUG: Playstatus error occurred: 'NoneType' object has no attribute 'cancel'
An error occurred (restarting): 'NoneType' object has no attribute 'cancel'
DEBUG: Initial delay set to 1
DEBUG: Waiting for playstatus updates
DEBUG: Already logged in, re-using seasion id 1318877441
DEBUG: GET URL: http://<redacted>:3689/ctrl-int/1/playstatusupdate?session-id=1318877441&revision-number=0
DEBUG: Playstatus error occurred: 'NoneType' object has no attribute 'cancel'
An error occurred (restarting): 'NoneType' object has no attribute 'cancel'
DEBUG: Initial delay set to 1
DEBUG: Waiting for playstatus updates
DEBUG: Already logged in, re-using seasion id 1318877441
DEBUG: GET URL: http://<redacted>:3689/ctrl-int/1/playstatusupdate?session-id=1318877441&revision-number=0
DEBUG: Playstatus error occurred: 'NoneType' object has no attribute 'cancel'
An error occurred (restarting): 'NoneType' object has no attribute 'cancel'
DEBUG: Initial delay set to 1

ERROR: Unclosed connection
client_connection: Connection<('<redacted>', 3689, False)>
ERROR: Unclosed response
client_response: <ClientResponse(http://<redacted>:3689/ctrl-int/1/playstatusupdate?session-id=1318877441&revision-number=0) [200 OK]>
<CIMultiDictProxy('Date': 'Thu, 16 Mar 2017 14:40:58 GMT', 'Daap-Server': 'iTunes/11.1b37 (OS X)', 'Content-Type': 'application/x-dmap-tagged', 'Content-Length': '42', 'Content-Encoding': 'gzip')>

ERROR: Unclosed connection
client_connection: Connection<('<redacted>', 3689, False)>
ERROR: Unclosed response
client_response: <ClientResponse(http://<redacted>:3689/ctrl-int/1/playstatusupdate?session-id=1318877441&revision-number=0) [200 OK]>
<CIMultiDictProxy('Date': 'Thu, 16 Mar 2017 14:40:59 GMT', 'Daap-Server': 'iTunes/11.1b37 (OS X)', 'Content-Type': 'application/x-dmap-tagged', 'Content-Length': '42', 'Content-Encoding': 'gzip')>

ERROR: Unclosed connection
client_connection: Connection<('<redacted>', 3689, False)>
ERROR: Unclosed response
client_response: <ClientResponse(http://<redacted>:3689/ctrl-int/1/playstatusupdate?session-id=1318877441&revision-number=0) [200 OK]>
<CIMultiDictProxy('Date': 'Thu, 16 Mar 2017 14:41:00 GMT', 'Daap-Server': 'iTunes/11.1b37 (OS X)', 'Content-Type': 'application/x-dmap-tagged', 'Content-Length': '42', 'Content-Encoding': 'gzip')>

ERROR: Unclosed connection
client_connection: Connection<('<redacted>', 3689, False)>
ERROR: Unclosed response
client_response: <ClientResponse(http://<redacted>:3689/ctrl-int/1/playstatusupdate?session-id=1318877441&revision-number=0) [200 OK]>
<CIMultiDictProxy('Date': 'Thu, 16 Mar 2017 14:41:01 GMT', 'Daap-Server': 'iTunes/11.1b37 (OS X)', 'Content-Type': 'application/x-dmap-tagged', 'Content-Length': '42', 'Content-Encoding': 'gzip')>

ERROR: Unclosed connection
client_connection: Connection<('<redacted>', 3689, False)>
ERROR: Unclosed response
client_response: <ClientResponse(http://<redacted>:3689/ctrl-int/1/playstatusupdate?session-id=1318877441&revision-number=0) [200 OK]>
<CIMultiDictProxy('Date': 'Thu, 16 Mar 2017 14:41:02 GMT', 'Daap-Server': 'iTunes/11.1b37 (OS X)', 'Content-Type': 'application/x-dmap-tagged', 'Content-Length': '42', 'Content-Encoding': 'gzip')>

ERROR: Unclosed connection
client_connection: Connection<('<redacted>', 3689, False)>
ERROR: Unclosed response
client_response: <ClientResponse(http://<redacted>:3689/ctrl-int/1/playstatusupdate?session-id=1318877441&revision-number=0) [200 OK]>
<CIMultiDictProxy('Date': 'Thu, 16 Mar 2017 14:41:03 GMT', 'Daap-Server': 'iTunes/11.1b37 (OS X)', 'Content-Type': 'application/x-dmap-tagged', 'Content-Length': '42', 'Content-Encoding': 'gzip')>

ERROR: Unclosed connection
client_connection: Connection<('<redacted>', 3689, False)>
ERROR: Unclosed response
client_response: <ClientResponse(http://<redacted>:3689/ctrl-int/1/playstatusupdate?session-id=1318877441&revision-number=0) [200 OK]>
<CIMultiDictProxy('Date': 'Thu, 16 Mar 2017 14:41:04 GMT', 'Daap-Server': 'iTunes/11.1b37 (OS X)', 'Content-Type': 'application/x-dmap-tagged', 'Content-Length': '42', 'Content-Encoding': 'gzip')>

ERROR: Unclosed connection
client_connection: Connection<('<redacted>', 3689, False)>
ERROR: Unclosed response
client_response: <ClientResponse(http://<redacted>:3689/ctrl-int/1/playstatusupdate?session-id=1318877441&revision-number=0) [200 OK]>
<CIMultiDictProxy('Date': 'Thu, 16 Mar 2017 14:41:05 GMT', 'Daap-Server': 'iTunes/11.1b37 (OS X)', 'Content-Type': 'application/x-dmap-tagged', 'Content-Length': '42', 'Content-Encoding': 'gzip')>

Hope this helps :)

@aaronwolen
Copy link

aaronwolen commented Mar 16, 2017

Here's a little more data for the pile:

$ atvremote --debug --address <redacted> --login_id <redacted>&hasFP=1
DEBUG: Data[32]: b'6d6c6f67000000186d73747400000004000000c86d6c69640000000400000029'
DEBUG: _login_request: mlog: [container, dmap.loginresponse]
  mstt: 200 [uint, dmap.status]
  mlid: 41 [uint, dmap.sessionid]

INFO: Logged in and got session id 41
DEBUG: GET URL: http://<redacted>:3689/ctrl-int/1/playstatusupdate?session-id=41&revision-number=0
DEBUG: Data[155]: b'636d7374000000936d73747400000004000000c8636d737200000004000007f963616673000000010063616665000000010063617665000000010063617673000000010063617073000000010363617368000000010063617270000000010063616172000000040000000663616173000000040000000263616b730000000101'...
DEBUG: _get_request: cmst: [container, dmcp.playstatus]
  mstt: 200 [uint, dmap.status]
  cmsr: 2041 [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]

Press ENTER to stop
DEBUG: Waiting for playstatus updates
DEBUG: Already logged in, re-using seasion id 41
DEBUG: GET URL: http://<redacted>:3689/ctrl-int/1/playstatusupdate?session-id=41&revision-number=2041
DEBUG: Data[0]: b''
DEBUG: _get_request:
DEBUG: Playstatus error occurred: failed to login: 400
An error occurred (restarting): failed to login: 400
DEBUG: Initial delay set to 1
DEBUG: Waiting for playstatus updates

@postlund
Copy link
Contributor

That's a lot better, thanks @UltraSub! I still cannot get my head around what is happening here 😮

I have created a branch in the pyatv repo that prints a stacktrace for when an error occurs. This way, maybe I can figure out where this happens. Maybe you can try that out and re-run atvremote?

What you should do is basically this.

  • Go to some directory, e.g. the home directory (just type cd) and continue with these commands
  • git clone https://github.com/postlund/pyatv.git
  • cd pyatv
  • ./setup_dev_env.sh
  • source bin/activate
  • git checkout -b log_stacktrace origin/log_stacktrace
  • Now run atvremote again

If you start a new terminal, you must go to pyatv and run the source command again like this:

  • cd pyatv
  • source bin/activate

@postlund
Copy link
Contributor

@aaronwolen Interesting, you still have the 400 issue. Perhaps we can troubleshoot that too.

@UltraSub
Copy link
Author

Will check later tonight and report back @postlund!
Bit too much to do on a mobile phone over vpn :)

@postlund
Copy link
Contributor

@UltraSub Sure :)

@UltraSub
Copy link
Author

UltraSub commented Mar 16, 2017

Couldn't wait, did it on mobile:

(pyatv) root@<redacted>:~/debug/pyatv# atvremote --debug --address <redacted> --login_id <redacted> push_updates
DEBUG: GET URL: http://<redacted>:3689/login?hsgid=<redacted>&hasFP=1
DEBUG: Data[32]: b'6d6c6f67000000186d73747400000004000000c86d6c69640000000400000008'
DEBUG: _login_request: mlog: [container, dmap.loginresponse]
  mstt: 200 [uint, dmap.status]
  mlid: 8 [uint, dmap.sessionid]

INFO: Logged in and got session id 8
DEBUG: GET URL: http://<redacted>:3689/ctrl-int/1/playstatusupdate?session-id=8&revision-number=0
DEBUG: Data[155]: b'636d7374000000936d73747400000004000000c8636d7372000000040000005863616673000000010063616665000000010063617665000000010063617673000000010063617073000000010363617368000000010063617270000000010063616172000000040000000663616173000000040000000263616b730000000101'...
DEBUG: _get_request: cmst: [container, dmcp.playstatus]
  mstt: 200 [uint, dmap.status]
  cmsr: 88 [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]

Press ENTER to stop
DEBUG: Waiting for playstatus updates
DEBUG: Already logged in, re-using seasion id 8
DEBUG: GET URL: http://<redacted>:3689/ctrl-int/1/playstatusupdate?session-id=8&revision-number=0
DEBUG: Data[155]: b'636d7374000000936d73747400000004000000c8636d7372000000040000005863616673000000010063616665000000010063617665000000010063617673000000010063617073000000010363617368000000010063617270000000010063616172000000040000000663616173000000040000000263616b730000000101'...
DEBUG: _get_request: cmst: [container, dmcp.playstatus]
  mstt: 200 [uint, dmap.status]
  cmsr: 88 [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: Waiting for playstatus updates
DEBUG: Already logged in, re-using seasion id 8
DEBUG: GET URL: http://<redacted>:3689/ctrl-int/1/playstatusupdate?session-id=8&revision-number=88
Media type: Video
Play state: Paused

And then it just sits there.
Forgot to check versions of atvremote to see if they're different, but I upgraded the version which generated the errors in the previous posts to latest yesterday. Will check again later tonight.

/edit
Maybe the kids got home and changed the status of the AppleTV. Hmm.

/edit 2
Nope, using pyatv in the hass environment gives me the same errors. It is at version 0.2.2.
pyatv which has the stacktrace is at 0.2.3.dev1

@aaronwolen
Copy link

Here's my output using the log_stacktrace branch:

$ atvremote --debug --address <redacted> --login_id <redacted> push_updates
DEBUG: GET URL: http://<redacted>:3689/login?hsgid=<redacted>&hasFP=1
DEBUG: Data[32]: b'6d6c6f67000000186d73747400000004000000c86d6c69640000000400000001'
DEBUG: _login_request: mlog: [container, dmap.loginresponse]
  mstt: 200 [uint, dmap.status]
  mlid: 1 [uint, dmap.sessionid]

INFO: Logged in and got session id 1
DEBUG: GET URL: http://<redacted>:3689/ctrl-int/1/playstatusupdate?session-id=1&revision-number=0
DEBUG: Data[155]: b'636d7374000000936d73747400000004000000c8636d7372000000040000000363616673000000010063616665000000010063617665000000010063617673000000010063617073000000010363617368000000010063617270000000010063616172000000040000000663616173000000040000000263616b730000000101'...
DEBUG: _get_request: cmst: [container, dmcp.playstatus]
  mstt: 200 [uint, dmap.status]
  cmsr: 3 [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]

Press ENTER to stop
DEBUG: Waiting for playstatus updates
DEBUG: Already logged in, re-using seasion id 1
DEBUG: GET URL: http://<redacted>:3689/ctrl-int/1/playstatusupdate?session-id=1&revision-number=0
DEBUG: Data[155]: b'636d7374000000936d73747400000004000000c8636d7372000000040000000363616673000000010063616665000000010063617665000000010063617673000000010063617073000000010363617368000000010063617270000000010063616172000000040000000663616173000000040000000263616b730000000101'...
DEBUG: _get_request: cmst: [container, dmcp.playstatus]
  mstt: 200 [uint, dmap.status]
  cmsr: 3 [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: Waiting for playstatus updates
DEBUG: Already logged in, re-using seasion id 1
DEBUG: GET URL: http://<redacted>:3689/ctrl-int/1/playstatusupdate?session-id=1&revision-number=3
Media type: Video
Play state: Paused
--------------------

@postlund
Copy link
Contributor

Humm, this is strange. Because now it seems to work as intended (for both of you). I based this branch of the same commit that is pyatv 0.2.2, which is used by Home Assistant. So this is really weird. Question is if this has something to do which version of aiohttp that is used. I just setup a new environment myself and it pulled in aiohttp 2.0.0rc1 whilst 1.3.4 is pinned by Home Assistant. So, can you try to change aiohttp version and see if he errors appears again:

  • pip uninstall aiohttp
  • pip install aiohttp==1.3.4

@postlund
Copy link
Contributor

Aha! When downgrading aiohttp I got the error myself:

DEBUG: Playstatus error occurred:   File "/Users/postlund/pyatv/pyatv/internal/apple_tv.py", line 333, in _poller
    use_revision=True, timeout=0)
  File "/Users/postlund/pyatv/pyatv/internal/apple_tv.py", line 46, in playstatus
    resp = yield from self.daap.get(cmd_url, timeout=timeout)
  File "/Users/postlund/pyatv/pyatv/daap.py", line 135, in get
    return (yield from self._do(_get_request, is_daap=daap_data))
  File "/Users/postlund/pyatv/pyatv/daap.py", line 154, in _do
    resp, status = yield from action()
  File "/Users/postlund/pyatv/pyatv/daap.py", line 54, in get_data
    raise ex
  File "/Users/postlund/pyatv/pyatv/daap.py", line 47, in get_data
    timeout=DEFAULT_TIMEOUT if timeout is None else timeout)
  File "/Users/postlund/pyatv/lib/python3.5/site-packages/aiohttp/client.py", line 583, in __iter__
    resp = yield from self._coro
  File "/Users/postlund/pyatv/lib/python3.5/site-packages/aiohttp/client.py", line 279, in _request
    resp.connection.add_callback(handle.cancel)

I found the bug too: aio-libs/aiohttp#1720

@aaronwolen
Copy link

aaronwolen commented Mar 16, 2017

Downgrading aiohttp definitely seems to have triggered something:

$ atvremote --debug --address <redacted> --login_id <redacted> push_updates
DEBUG: GET URL: http://<redacted>:3689/login?hsgid=<redacted>&hasFP=1
DEBUG: Data[32]: b'6d6c6f67000000186d73747400000004000000c86d6c69640000000400000002'
DEBUG: _login_request: mlog: [container, dmap.loginresponse]
  mstt: 200 [uint, dmap.status]
  mlid: 2 [uint, dmap.sessionid]

INFO: Logged in and got session id 2
DEBUG: GET URL: http://<redacted>:3689/ctrl-int/1/playstatusupdate?session-id=2&revision-number=0
DEBUG: Data[155]: b'636d7374000000936d73747400000004000000c8636d7372000000040000000363616673000000010063616665000000010063617665000000010063617673000000010063617073000000010363617368000000010063617270000000010063616172000000040000000663616173000000040000000263616b730000000101'...
DEBUG: _get_request: cmst: [container, dmcp.playstatus]
  mstt: 200 [uint, dmap.status]
  cmsr: 3 [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]

Press ENTER to stop
DEBUG: Waiting for playstatus updates
DEBUG: Already logged in, re-using seasion id 2
DEBUG: GET URL: http://<redacted>:3689/ctrl-int/1/playstatusupdate?session-id=2&revision-number=0
DEBUG: Playstatus error occurred:   File "/home/aaron/Documents/pyatv/pyatv/internal/apple_tv.py", line 333, in _poller
    use_revision=True, timeout=0)
  File "/home/aaron/Documents/pyatv/pyatv/internal/apple_tv.py", line 46, in playstatus
    resp = yield from self.daap.get(cmd_url, timeout=timeout)
  File "/home/aaron/Documents/pyatv/pyatv/daap.py", line 135, in get
    return (yield from self._do(_get_request, is_daap=daap_data))
  File "/home/aaron/Documents/pyatv/pyatv/daap.py", line 154, in _do
    resp, status = yield from action()
  File "/home/aaron/Documents/pyatv/pyatv/daap.py", line 54, in get_data
    raise ex
  File "/home/aaron/Documents/pyatv/pyatv/daap.py", line 47, in get_data
    timeout=DEFAULT_TIMEOUT if timeout is None else timeout)
  File "/home/aaron/Documents/pyatv/lib/python3.4/site-packages/aiohttp/client.py", line 583, in __iter__
    resp = yield from self._coro
  File "/home/aaron/Documents/pyatv/lib/python3.4/site-packages/aiohttp/client.py", line 279, in _request
    resp.connection.add_callback(handle.cancel) 

An error occurred (restarting): 'NoneType' object has no attribute 'cancel'
DEBUG: Initial delay set to 1
DEBUG: Waiting for playstatus updates
DEBUG: Already logged in, re-using seasion id 2
DEBUG: GET URL: http://<redacted>:3689/ctrl-int/1/playstatusupdate?session-id=2&revision-number=0
DEBUG: Playstatus error occurred:   File "/home/aaron/Documents/pyatv/pyatv/internal/apple_tv.py", line 333, in _poller
    use_revision=True, timeout=0)
  File "/home/aaron/Documents/pyatv/pyatv/internal/apple_tv.py", line 46, in playstatus
    resp = yield from self.daap.get(cmd_url, timeout=timeout)
  File "/home/aaron/Documents/pyatv/pyatv/daap.py", line 135, in get
    return (yield from self._do(_get_request, is_daap=daap_data))
  File "/home/aaron/Documents/pyatv/pyatv/daap.py", line 154, in _do
    resp, status = yield from action()
  File "/home/aaron/Documents/pyatv/pyatv/daap.py", line 54, in get_data
    raise ex
  File "/home/aaron/Documents/pyatv/pyatv/daap.py", line 47, in get_data
    timeout=DEFAULT_TIMEOUT if timeout is None else timeout)
  File "/home/aaron/Documents/pyatv/lib/python3.4/site-packages/aiohttp/client.py", line 583, in __iter__
    resp = yield from self._coro
  File "/home/aaron/Documents/pyatv/lib/python3.4/site-packages/aiohttp/client.py", line 279, in _request
    resp.connection.add_callback(handle.cancel)

@postlund
Copy link
Contributor

Not much we can do, we'll have to wait for a new aiohttp release and make sure an uplift gets included in 0.40.2. Thank you guys for helping me out fixing this! 😄

Also, @aaronwolen, maybe you can keep an eye open for the "400" errors when the new release is out. Maybe it fixes something, who knows. I can't see anything particular strange with in the log you posted above.

@postlund
Copy link
Contributor

Fixed in aiohttp 1.3.5 which was merged by PR #6660. I think we can close this now.

@UltraSub
Copy link
Author

Awesome @postlund!
Thanks for the quick response and troubleshoot!

@postlund
Copy link
Contributor

Same to you @UltraSub!

@home-assistant home-assistant locked and limited conversation to collaborators Jun 24, 2017
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
None yet
Projects
None yet
Development

No branches or pull requests

5 participants