search

alandtse / alexa_media_player

This is a custom component to allow control of Amazon Alexa devices in Home Assistant using the unofficial Alexa API.
Apache License 2.0
1.51k stars 289 forks source link

An exception of type CancelledError occurred. #764

Closed aptonline closed 4 years ago

aptonline commented 4 years ago

Describe the bug

I recently removed the integration as my devices were showing as 'unavailable'. After installing the component again (which went smoothly and allowed logging in) the integration shows no devices even though my account has a number of devices enabled and can be seen in the Alexa iOS app and the Alexa website.

Please see below for the log errors.

To Reproduce Steps to reproduce the behavior:

  1. Removed existing integration and component.
  2. Reinstalled integration and component.
  3. Logged in.
  4. See error logs.

Expected behaviour

Devices should appear in devices/entities after installing and logging in.

Screenshots If applicable, add screenshots to help explain your problem.

N/A

System details

Logs Please provide logs. We'll be most likely asking for them anyway.

Log Details (ERROR)
Logger: alexapy.helpers
Source: __main__.py:356 
First occurred: 10:02:43 (18 occurrences) 
Last logged: 10:03:56

alexaapi._static_request:An error occured accessing AlexaAPI: An exception of type CancelledError occurred. Arguments: ()
alexaapi.get_bluetooth:An error occured accessing AlexaAPI: An exception of type CancelledError occurred. Arguments: ()
alexaapi.get_dnd_state:An error occured accessing AlexaAPI: An exception of type CancelledError occurred. Arguments: ()
alexaapi.get_authentication:An error occured accessing AlexaAPI: An exception of type CancelledError occurred. Arguments: ()

Log Details (ERROR)
Logger: custom_components.alexa_media
Source: helpers/update_coordinator.py:140 
Integration: Alexa Media Player (documentation) 
First occurred: 10:02:43 (1 occurrences) 
Last logged: 10:02:43

Timeout fetching alexa_media data

Additional context

As mentioned above was working but devices became unavailable hence why removed and reinstalled. Checked to make sure pickle was removed and recreated.

alandtse commented 4 years ago

It's unable to connect to Amazon within the update time window. Please provide your startup logs.

aptonline commented 4 years ago

See below. I’ve enabled logging from the component and scrubbed best i can any credentials:

2020-06-05 06:54:24 WARNING (MainThread) [homeassistant.loader] You are using a custom integration for alexa_media which has not been tested by Home Assistant. This component might cause stability problems, be sure to disable it if you experience issues with Home Assistant.
2020-06-05 06:54:24 WARNING (MainThread) [homeassistant.loader] You are using a custom integration for apple_tv which has not been tested by Home Assistant. This component might cause stability problems, be sure to disable it if you experience issues with Home Assistant.
2020-06-05 06:54:24 WARNING (MainThread) [homeassistant.loader] You are using a custom integration for garbage_collection which has not been tested by Home Assistant. This component might cause stability problems, be sure to disable it if you experience issues with Home Assistant.
2020-06-05 06:54:24 WARNING (MainThread) [homeassistant.loader] You are using a custom integration for hacs which has not been tested by Home Assistant. This component might cause stability problems, be sure to disable it if you experience issues with Home Assistant.
2020-06-05 06:54:24 WARNING (MainThread) [homeassistant.loader] You are using a custom integration for eufy_robovac which has not been tested by Home Assistant. This component might cause stability problems, be sure to disable it if you experience issues with Home Assistant.
2020-06-05 06:54:28 DEBUG (MainThread) [custom_components.alexa_media] Nothing to import from configuration.yaml, loading from Integrations
2020-06-05 06:54:28 INFO (MainThread) [custom_components.alexa_media] 
-------------------------------------------------------------------
alexa_media
Version: 2.8.3
This is a custom component
If you have any issues with this you need to open an issue here:
https://github.com/custom-components/alexa_media_player/issues
-------------------------------------------------------------------

2020-06-05 06:54:28 INFO (MainThread) [custom_components.alexa_media] Loaded alexapy==1.10.1
2020-06-05 06:54:28 DEBUG (MainThread) [alexapy.alexalogin] Trying to load pickled cookie from file /config/.storage/alexa_media.email@domain.com.pickle
2020-06-05 06:54:29 DEBUG (MainThread) [alexapy.alexalogin] cookie loaded: <class 'collections.defaultdict'> defaultdict(<class 'http.cookies.SimpleCookie'>, {'amazon.co.uk': <SimpleCookie: at-acbuk=''>})
2020-06-05 06:54:29 DEBUG (MainThread) [alexapy.alexalogin] Loaded 9 cookies
2020-06-05 06:54:29 DEBUG (MainThread) [alexapy.alexalogin] Testing whether logged in to alexa.amazon.co.uk
2020-06-05 06:54:29 DEBUG (MainThread) [alexapy.alexalogin] Header: {"User-Agent": "Mozilla/5.0 (Windows NT 6.3; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/68.0.3440.106 Safari/537.36", "Accept": "text/html,application/xhtml+xml, application/xml;q=0.9,*/*;q=0.8", "Accept-Language": "*"}
2020-06-05 06:54:30 DEBUG (MainThread) [alexapy.alexalogin] GET: 
https://alexa.amazon.co.uk/api/bootstrap with
<CIMultiDictProxy('Host': 'alexa.amazon.co.uk', 'User-Agent': 'Mozilla/5.0 (Windows NT 6.3; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/68.0.3440.106 Safari/537.36', 'Accept': 'text/html,application/xhtml+xml, application/xml;q=0.9,*/*;q=0.8', 'Accept-Language': '*', 'Accept-Encoding': 'gzip, deflate', 'Cookie': 'at-acbuk=Atza|----; csrf=; sess-at-acbuk="PB//tMwKmPiYNc7YyTL1RY="; session-id=258-5718570-2158912; session-id-time=2221824798l; session-token="/N6QTBZP0Dpf/E+/+/+3U="; sst-acbuk=Sst1|-0iY---; ubid-acbuk=257--6924515; x-acbuk="Os1vH?"')>
 returned 200:OK with response <CIMultiDictProxy('Content-Type': 'application/json', 'Content-Length': '133', 'Connection': 'keep-alive', 'Server': 'Server', 'Date': 'Fri, 05 Jun 2020 06:54:29 GMT', 'x-amzn-RequestId': '011ae97d-5297-4648-a038-706b048907b3', 'Content-Encoding': 'gzip', 'Vary': 'Content-Type,Accept-Encoding,X-Amzn-CDN-Cache,X-Amzn-AX-Treatment,User-Agent', 'x-amz-rid': '', 'X-Cache': 'Miss from cloudfront', 'Via': '1.1 b02c5108645d71e94b66c369c35c449b.cloudfront.net (CloudFront)', 'X-Amz-Cf-Pop': 'LHR62-C5', 'X-Amz-Cf-Id': 'ENkfEc5W3lFUA6dxkX0o_mLc3m9SYKfzN2poBjy0FbP5sHwWkgGfAQ==')>
2020-06-05 06:54:30 DEBUG (MainThread) [alexapy.alexalogin] Logged in as email@domain.com
2020-06-05 06:54:30 DEBUG (MainThread) [alexapy.alexalogin] Using cookies to log in
2020-06-05 06:54:30 DEBUG (MainThread) [alexapy.alexalogin] Log in successful with cookies
2020-06-05 06:54:30 DEBUG (MainThread) [alexapy.alexalogin] Updating self._cookies with 2020-06-05 06:54:30 DEBUG (MainThread) [custom_components.alexa_media.configurator] Testing login status: {'login_successful': True}
2020-06-05 06:54:30 DEBUG (MainThread) [custom_components.alexa_media.configurator] Setting up Alexa devices for email@domain.com
2020-06-05 06:54:30 DEBUG (MainThread) [custom_components.alexa_media] email@domain.com: Websocket created: <alexapy.alexawebsocket.WebsocketEchoClient object at 0x7f76758a9b50>
2020-06-05 06:54:30 DEBUG (MainThread) [alexapy.alexawebsocket] Connecting to wss://dp-gw-na.amazon.co.uk/?x-amz-device-type=ALEGCNGL9K0HM&x-amz-device-serial=257-7574745-6924515-1591340070000 with {'User-Agent': 'Mozilla/5.0 (Windows NT 6.3; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/68.0.3440.106 Safari/537.36', 'Accept': 'text/html,application/xhtml+xml, application/xml;q=0.9,*/*;q=0.8', 'Accept-Language': '*', 'Referer': 'https://alexa.amazon.co.uk/api/bootstrap', 'Cookie': 'session-id=258-5718570-2158912; session-id-time=2221824798l; ubid-acbuk=257-7574745-6924515; session-token=; at-acbuk=Atza|IwEBIFOjvmMOwTwTHYqR0_GRraOtu3b5xKClKjn; sst-acbuk=Sst1; csrf=1187703762; ', 'Origin': 'https://alexa.amazon.co.uk'}
2020-06-05 06:54:31 DEBUG (MainThread) [alexapy.alexawebsocket] Initating Async Handshake.
2020-06-05 06:54:31 DEBUG (MainThread) [alexapy.alexawebsocket] Starting message parsing loop.
2020-06-05 06:54:31 DEBUG (MainThread) [alexapy.alexawebsocket] Received WebSocket: 0x37a3b607 0x0000009c {"protocolName":"A:H","parameters":{"AlphaProtocolHandler.maxFragmentSize":"16000","AlphaProtocolHandler.receiveWindowSize":"16"}}TUNE
2020-06-05 06:54:31 DEBUG (MainThread) [alexapy.alexawebsocket] Encoding WebSocket Handshake MSG.
2020-06-05 06:54:31 DEBUG (MainThread) [alexapy.alexawebsocket] Encoding Gateway Handshake MSG.
2020-06-05 06:54:31 DEBUG (MainThread) [alexapy.alexawebsocket] Encoding Gateway Register MSG.
2020-06-05 06:54:31 DEBUG (MainThread) [alexapy.alexawebsocket] Received WebSocket: MSG 0x00000361 0x03ce0878 f 0x00000001 0xa97dbe82 0x000000b9 ACK 0x00000003 1.0 0x00000024 01e09e62-f504-476c-85c8-9c97c8da26ed 0x00000064 0x0000016978ff598c 0x0000017283427b76 END FABE
2020-06-05 06:54:31 DEBUG (MainThread) [alexapy.alexawebsocket] Received ACK MSG for Registration.
2020-06-05 06:54:31 DEBUG (MainThread) [alexapy.alexawebsocket] Encoding PING.
2020-06-05 06:54:32 DEBUG (MainThread) [custom_components.alexa_media] emaila@domain.com: Websocket succesfully connected
2020-06-05 06:54:32 DEBUG (MainThread) [custom_components.alexa_media] Creating coordinator
2020-06-05 06:54:32 DEBUG (MainThread) [custom_components.alexa_media] Refreshing coordinator
2020-06-05 06:54:32 DEBUG (MainThread) [alexapy.alexaapi] static GET: https://alexa.amazon.co.uk/api/notifications returned 200:OK:application/json
2020-06-05 06:54:32 DEBUG (MainThread) [alexapy.alexaapi] static GET: https://alexa.amazon.co.uk/api/devices-v2/device returned 200:OK:application/json
2020-06-05 06:54:33 DEBUG (MainThread) [alexapy.alexaapi] static GET: https://alexa.amazon.co.uk/api/device-preferences returned 200:OK:application/json
2020-06-05 06:54:42 ERROR (MainThread) [alexapy.helpers] alexaapi._static_request:An error occured accessing AlexaAPI: An exception of type CancelledError occurred. Arguments:
()
2020-06-05 06:54:42 ERROR (MainThread) [alexapy.helpers] alexaapi.get_bluetooth:An error occured accessing AlexaAPI: An exception of type CancelledError occurred. Arguments:
()
2020-06-05 06:54:42 ERROR (MainThread) [alexapy.helpers] alexaapi._static_request:An error occured accessing AlexaAPI: An exception of type CancelledError occurred. Arguments:
()
2020-06-05 06:54:42 ERROR (MainThread) [alexapy.helpers] alexaapi.get_dnd_state:An error occured accessing AlexaAPI: An exception of type CancelledError occurred. Arguments:
()
2020-06-05 06:54:42 ERROR (MainThread) [alexapy.helpers] alexaapi._static_request:An error occured accessing AlexaAPI: An exception of type CancelledError occurred. Arguments:
()
2020-06-05 06:54:42 ERROR (MainThread) [alexapy.helpers] alexaapi.get_authentication:An error occured accessing AlexaAPI: An exception of type CancelledError occurred. Arguments:
()
2020-06-05 06:54:42 ERROR (MainThread) [custom_components.alexa_media] Timeout fetching alexa_media data
2020-06-05 06:54:42 DEBUG (MainThread) [custom_components.alexa_media] Finished fetching alexa_media data in 10.011 seconds
alandtse commented 4 years ago

There's something strange going on with your system as it's timing out on the network request. It's taking more than 10 seconds to contact Amazon's server. Can you please rename your .pickle file and restart?

aptonline commented 4 years ago

Ok I renamed, rebooted and I got a notification in HA saying I needed to login which I did. I received a push notification and text from Amazon saying sign-in detected and then the integration re-appeared in HA... but still no devices showing. Its successfully talking to Amazon but not pulling through the devices for some reason. This is a new install of HA and it WAS working but my devices showed up as 'unavailable' so reinstalled as mentioned above.

alandtse commented 4 years ago

What do the logs say now? Is it the same error?

aptonline commented 4 years ago

Sorry yes, same error.

alandtse commented 4 years ago

If it's the same error, then there's something wrong with the system as it's not getting a response from Amazon within 10 seconds. Try uninstalling alexa_media and waiting till it's started and then adding the integration manually.

aptonline commented 4 years ago

Ok I did as you suggested and also updated to latest version of Alexa_Media_Player and the combination of the two 'seems' to have fixed the issue. I'm not checked the logs but if I get anymore issues I will update this issue. Thanks.

alandtse commented 4 years ago

At your next reboot see if the issue comes back. It's possible that the component is running into some limit in the connections it's trying to spawn so it's waiting for some other component to allow it to make more connections. The specific code at issue is trying to hit 5 separate Amazon pages to download all the info within 10 seconds. In my testing, it should complete all this in 1 second. If this keeps coming back, I guess I could make the timeout be for each of the 5 accesses individually instead of collectively.

aptonline commented 4 years ago

Ok for a while my integration was working but I have just updated to latest version (2.8.6) and not my devices are again unavailable in Lovelace (but there are showing as being in the integration) and Im seeing the following error in the logs:

Logger: alexapy.helpers
Source: __main__.py:356 
First occurred: 10:48:19 (15 occurrences) 
Last logged: 10:54:54

alexaapi.get_bluetooth((<alexapy.alexalogin.AlexaLogin object at 0x7f96083a28d0>,), {}): Timeout error occured accessing AlexaAPI: An exception of type CancelledError occurred. Arguments: ()
alexaapi.get_dnd_state((<alexapy.alexalogin.AlexaLogin object at 0x7f96083a28d0>,), {}): Timeout error occured accessing AlexaAPI: An exception of type CancelledError occurred. Arguments: ()
alexaapi.get_authentication((<alexapy.alexalogin.AlexaLogin object at 0x7f96083a28d0>,), {}): Timeout error occured accessing AlexaAPI: An exception of type CancelledError occurred. Arguments: ()

and also

Logger: custom_components.alexa_media
Source: helpers/update_coordinator.py:150 
Integration: Alexa Media Player (documentation) 
First occurred: 10:48:19 (1 occurrences) 
Last logged: 10:48:19

Error fetching alexa_media data: Error communicating with API:

If needed I will enable full logging for this agin.

alandtse commented 4 years ago

Does the same fix from before work where you add the integration after HA has started?

aptonline commented 4 years ago

It does but over time the devices become unavailable.

alandtse commented 4 years ago

If you're willing to test, you can try increasing the timeout by modifying the line here:

            async with async_timeout.timeout(10):

Increase the number to something like 30 or 60 or whatever. HA will complain that the component is taking too long to update. See what number resolves it for you.

The issue is this is entirely a system/network issue on how long it takes Alexa to respond to the 5 requests made.

alandtse commented 4 years ago

Are you still seeing this error or did the proposed change help?

aptonline commented 4 years ago

Sorry for the delay, recently the devices has been behaving and I haven't had the 'unavailable' issue. Fingers crossed whatever the problem was is now fixed as at least not showing itself.

alandtse commented 4 years ago

Glad it resolved. I do have a fix planned since I could reproduce it sometimes. I'll close this out after that fix goes out.