Taking over 60 seconds to "Setup" After restart #357

moriahmorgan · 2019-09-10T19:35:19Z

Describe the bug
After a restart of Home Assistant, I will get a notification that the component took too long to initialize. Component/Plugin still works as it should.

Notification is as follows:
Setup of platform alexa_media is taking longer than 60 seconds. Startup will proceed without waiting any longer.

To Reproduce
Restart Home Assistant via Server Control

Expected behavior
Either to not run "Setup" on every restart of homebridge, or for the setup to not take over 60 seconds.

System details

Home-assistant (version): 0.98.5
Hassio (Yes/No): Yes
alexa_media version: 2.1.2
alexapy version: 1.1.2

Logs

2019-09-10 14:18:13 DEBUG (MainThread) [custom_components.alexa_media] Testing login status: {'login_successful': True}
2019-09-10 14:18:13 DEBUG (MainThread) [custom_components.alexa_media] Setting up Alexa devices for w********1@g*******m
2019-09-10 14:18:13 DEBUG (MainThread) [custom_components.alexa_media] w********1@g*******m: Websocket created: <alexapy.alexawebsocket.WebsocketEchoClient object at 0x7f26fedf73d0>
~
2019-09-10 14:18:14 DEBUG (MainThread) [custom_components.alexa_media] w********1@g*******m: Websocket succesfully connected
~
2019-09-10 14:18:15 DEBUG (MainThread) [custom_components.alexa_media] w********1@g*******m: Found 8 devices, 1 bluetooth
2019-09-10 14:18:15 DEBUG (MainThread) [custom_components.alexa_media] Locale en-us found for G************QQ9
2019-09-10 14:18:15 DEBUG (MainThread) [custom_components.alexa_media] DND False found for G************QQ9
2019-09-10 14:18:15 DEBUG (MainThread) [custom_components.alexa_media] Locale en-us found for G************KVQ
2019-09-10 14:18:15 DEBUG (MainThread) [custom_components.alexa_media] DND False found for G************KVQ
2019-09-10 14:18:15 DEBUG (MainThread) [custom_components.alexa_media] w********1@g*******m: Existing: [] New: ['Big Echo', 'Echo Dot Bedroom']; Filtered out by not being in include: [] or in exclude: ["******'s Alexa Apps", 'Echo Dot Living Room', 'Living Room', 'Everywhere', 'This Device', "******'s Alexa Apps"]
2019-09-10 14:18:15 INFO (SyncWorker_15) [homeassistant.loader] Loaded alarm_control_panel from homeassistant.components.alarm_control_panel
2019-09-10 14:18:15 INFO (MainThread) [homeassistant.setup] Setting up alarm_control_panel
2019-09-10 14:18:15 INFO (MainThread) [homeassistant.setup] Setup of domain alarm_control_panel took 0.0 seconds.
2019-09-10 14:18:16 DEBUG (MainThread) [custom_components.alexa_media] w********1@g*******m: Updated last_called: {'serialNumber': 'G************QQ9', 'timestamp': 1568122124666}
2019-09-10 14:18:16 DEBUG (MainThread) [custom_components.alexa_media] w********1@g*******m: last_called changed:  to {'serialNumber': 'G************QQ9', 'timestamp': 1568122124666}
2019-09-10 14:18:16 INFO (MainThread) [homeassistant.setup] Setup of domain alexa_media took 4.7 seconds.
2019-09-10 14:18:16 INFO (MainThread) [homeassistant.components.media_player] Setting up media_player.alexa_media
2019-09-10 14:18:16 INFO (MainThread) [homeassistant.components.notify] Setting up notify.alexa_media
2019-09-10 14:18:16 DEBUG (MainThread) [custom_components.alexa_media.helpers] async_get_service: Trying with limit 5 delay 2 catch_exceptions True
2019-09-10 14:18:16 DEBUG (MainThread) [custom_components.alexa_media.notify] w********1@g*******m: Media player G************QQ9 not loaded yet; delaying load
2019-09-10 14:18:16 DEBUG (MainThread) [custom_components.alexa_media.helpers] async_get_service: Try: 1/5 result: False
2019-09-10 14:18:16 INFO (MainThread) [homeassistant.components.switch] Setting up switch.alexa_media
2019-09-10 14:18:16 INFO (MainThread) [homeassistant.components.alarm_control_panel] Setting up alarm_control_panel.alexa_media
2019-09-10 14:18:16 DEBUG (MainThread) [custom_components.alexa_media.helpers] async_setup_platform: Trying with limit 5 delay 2 catch_exceptions True
2019-09-10 14:18:16 DEBUG (MainThread) [custom_components.alexa_media.helpers] async_setup_platform: Trying with limit 5 delay 2 catch_exceptions True
2019-09-10 14:18:16 DEBUG (MainThread) [custom_components.alexa_media.switch] w********1@g*******m: Loading switches
2019-09-10 14:18:16 DEBUG (MainThread) [custom_components.alexa_media.switch] w********1@g*******m: Media player G************QQ9 not loaded yet; delaying load
2019-09-10 14:18:16 DEBUG (MainThread) [custom_components.alexa_media.helpers] async_setup_platform: Try: 1/5 result: False
2019-09-10 14:18:16 DEBUG (MainThread) [custom_components.alexa_media.helpers] async_setup_platform: Trying with limit 5 delay 2 catch_exceptions True
2019-09-10 14:18:16 DEBUG (MainThread) [custom_components.alexa_media.media_player] w********1@g*******m: Refreshing Big Echo
2019-09-10 14:18:16 DEBUG (MainThread) [custom_components.alexa_media.media_player] Big Echo: Last_called check: self: G************QQ9 reported: 
2019-09-10 14:18:16 DEBUG (MainThread) [custom_components.alexa_media.alarm_control_panel] w********1@g*******m: No Alexa Guard entity found
2019-09-10 14:18:16 DEBUG (MainThread) [custom_components.alexa_media.alarm_control_panel] w********1@g*******m: Skipping creation of uninitialized device: <Entity Alexa Guard: None>
2019-09-10 14:18:16 DEBUG (MainThread) [custom_components.alexa_media.helpers] async_setup_platform: Try: 1/5 result: False
2019-09-10 14:18:16 DEBUG (MainThread) [custom_components.alexa_media.media_player] w********1@g*******m: Refreshing Echo Dot Bedroom
2019-09-10 14:18:16 DEBUG (MainThread) [custom_components.alexa_media.media_player] Echo Dot Bedroom: Last_called check: self: G************KVQ reported: 
2019-09-10 14:18:16 DEBUG (MainThread) [custom_components.alexa_media.helpers] w********1@g*******m: Adding [<Entity Big Echo: standby>, <Entity Echo Dot Bedroom: standby>]
2019-09-10 14:18:16 DEBUG (MainThread) [custom_components.alexa_media.helpers] async_setup_platform: Try: 1/5 result: True
2019-09-10 14:18:20 DEBUG (MainThread) [custom_components.alexa_media.helpers] async_get_service: Try: 2/5 result: <custom_components.alexa_media.notify.AlexaNotificationService object at 0x7f26f99bff10>
2019-09-10 14:18:20 DEBUG (MainThread) [custom_components.alexa_media.switch] w********1@g*******m: Loading switches
2019-09-10 14:18:20 DEBUG (MainThread) [custom_components.alexa_media.switch] w********1@g*******m: Found G************QQ9 dnd switch with status: False
2019-09-10 14:18:20 DEBUG (MainThread) [custom_components.alexa_media.switch] w********1@g*******m: Found G************QQ9 shuffle switch with status: None
2019-09-10 14:18:20 DEBUG (MainThread) [custom_components.alexa_media.switch] w********1@g*******m: Found G************QQ9 repeat switch with status: None
2019-09-10 14:18:20 DEBUG (MainThread) [custom_components.alexa_media.switch] w********1@g*******m: Found G************KVQ dnd switch with status: False
2019-09-10 14:18:20 DEBUG (MainThread) [custom_components.alexa_media.switch] w********1@g*******m: Found G************KVQ shuffle switch with status: None
2019-09-10 14:18:20 DEBUG (MainThread) [custom_components.alexa_media.switch] w********1@g*******m: Found G************KVQ repeat switch with status: None
2019-09-10 14:18:20 DEBUG (MainThread) [custom_components.alexa_media.helpers] w********1@g*******m: Adding [<Entity Big Echo do not disturb switch: off>, <Entity Big Echo shuffle switch: off>, <Entity Big Echo repeat switch: off>, <Entity Echo Dot Bedroom do not disturb switch: off>, <Entity Echo Dot Bedroom shuffle switch: off>, <Entity Echo Dot Bedroom repeat switch: off>]
2019-09-10 14:18:20 DEBUG (MainThread) [custom_components.alexa_media.helpers] async_setup_platform: Try: 2/5 result: True
2019-09-10 14:18:20 DEBUG (MainThread) [custom_components.alexa_media.alarm_control_panel] w********1@g*******m: No Alexa Guard entity found
2019-09-10 14:18:20 DEBUG (MainThread) [custom_components.alexa_media.alarm_control_panel] w********1@g*******m: Skipping creation of uninitialized device: <Entity Alexa Guard: None>
2019-09-10 14:18:20 DEBUG (MainThread) [custom_components.alexa_media.helpers] async_setup_platform: Try: 2/5 result: False
2019-09-10 14:18:26 WARNING (MainThread) [homeassistant.components.alarm_control_panel] Setup of platform alexa_media is taking over 10 seconds.
2019-09-10 14:18:28 DEBUG (MainThread) [custom_components.alexa_media.alarm_control_panel] w********1@g*******m: No Alexa Guard entity found
2019-09-10 14:18:28 DEBUG (MainThread) [custom_components.alexa_media.alarm_control_panel] w********1@g*******m: Skipping creation of uninitialized device: <Entity Alexa Guard: None>
2019-09-10 14:18:28 DEBUG (MainThread) [custom_components.alexa_media.helpers] async_setup_platform: Try: 3/5 result: False
2019-09-10 14:18:31 DEBUG (MainThread) [custom_components.alexa_media] w********1@g*******m: Received websocket command: PUSH_EQUALIZER_STATE_CHANGE : {'destinationUserId': 'A**********AIM', 'bass': 0, 'treble': 0, 'dopplerId': {'deviceSerialNumber': 'G************KVQ', 'deviceType': '************'}, 'midrange': 0}
2019-09-10 14:18:45 DEBUG (MainThread) [custom_components.alexa_media.alarm_control_panel] w********1@g*******m: No Alexa Guard entity found
2019-09-10 14:18:45 DEBUG (MainThread) [custom_components.alexa_media.alarm_control_panel] w********1@g*******m: Skipping creation of uninitialized device: <Entity Alexa Guard: None>
2019-09-10 14:18:45 DEBUG (MainThread) [custom_components.alexa_media.helpers] async_setup_platform: Try: 4/5 result: False
2019-09-10 14:19:16 ERROR (MainThread) [homeassistant.components.alarm_control_panel] Setup of platform alexa_media is taking longer than 60 seconds. Startup will proceed without waiting any longer.
2019-09-10 14:19:16 INFO (MainThread) [homeassistant.bootstrap] Home Assistant initialized in 65.79s
2019-09-10 14:19:16 INFO (MainThread) [homeassistant.core] Starting Home Assistant
~
2019-09-10 14:19:17 DEBUG (MainThread) [custom_components.alexa_media.media_player] w********1@g*******m: Refreshing Echo Dot Bedroom
2019-09-10 14:19:17 DEBUG (MainThread) [custom_components.alexa_media.media_player] Echo Dot Bedroom: Last_called check: self: G************KVQ reported: G************QQ9
2019-09-10 14:19:17 DEBUG (MainThread) [custom_components.alexa_media.media_player] w********1@g*******m: Refreshing Big Echo
2019-09-10 14:19:17 DEBUG (MainThread) [custom_components.alexa_media.media_player] Big Echo: Last_called check: self: G************QQ9 reported: G************QQ9
2019-09-10 14:19:17 DEBUG (MainThread) [custom_components.alexa_media.media_player] Disabling polling for Big Echo
2019-09-10 14:19:17 DEBUG (MainThread) [custom_components.alexa_media.media_player] Disabling polling for Echo Dot Bedroom
2019-09-10 14:19:17 DEBUG (MainThread) [custom_components.alexa_media.alarm_control_panel] w********1@g*******m: No Alexa Guard entity found
2019-09-10 14:19:17 DEBUG (MainThread) [custom_components.alexa_media.alarm_control_panel] w********1@g*******m: Skipping creation of uninitialized device: <Entity Alexa Guard: None>
2019-09-10 14:19:17 DEBUG (MainThread) [custom_components.alexa_media.helpers] async_setup_platform: Try: 5/5 result: False

Additional context
Plugin works fine after restart of services, however it just takes forever for home assistant to restart.

Originally set up this plugin via alexpy pip installation/manual install. Removed all of that and installed via HACS.

Have restarted HASS Multiple times. As stated, it works once home-assistant is up, it just delays start.

The text was updated successfully, but these errors were encountered:

alandtse · 2019-09-10T19:50:05Z

Thanks that's a bug. It shouldn't be retrying the alarm control panel in this situation since that's not an error. I'll add it to the queue to fix.

alandtse · 2019-09-11T06:35:11Z

Referenced PR should fix this. You can just replace the file.

aneisch · 2019-09-16T15:05:53Z

I replaced the content of helpers.py and am still seeing an issue with setup time

2019-09-16 10:03:28 ERROR (MainThread) [homeassistant.components.alarm_control_panel] Setup of platform alexa_media is taking longer than 60 seconds. Startup will proceed without waiting any longer.

The issue appears to be related to the alarm_control_panel component of Alexa Media

2019-09-16 10:03:28 INFO (MainThread) [homeassistant.setup] Setup of domain alarm_control_panel took 68.2 seconds.

alandtse · 2019-09-16T17:18:01Z

Make sure you deleted the cache and you're truly loading the new file. If you still see it I'd need logs.

aneisch · 2019-09-16T19:09:38Z

5243d547122e85fa1b5b99b597d1bd05 helpers.py

I have removed the pycache directory in custom_components/alexa_media. Let me know what you need from logs and I'll get them here. Thank you for your hard work!

masonevans · 2019-09-16T20:28:45Z

As a second data point, I made this update and it did fix the startup issue.

Stop home-assistant
Update helpers.py
Remove __pycache__
Start back up

If it matters, I have alexa_media_player being managed by HACS

aneisch · 2019-09-16T21:19:31Z

~~No dice here.~~ Working now, perhaps it was a permissions issue. I chowned/chmodded the helpers.py file to my hass user.

Stop hass

Update helpers.py

Remove custom_components/alexa_media/__pycache__

Remove custom_components/__pycache__ (for good measure)

Start hass

wrboyce · 2019-09-16T21:41:26Z

fwiw I did not need to touch my __pycache__, and I believe Python should be smart enough to work this out for itself (based on ctime/mtime).

For anyone arriving here now looking for a fix, this should set you straight:

curl -o /path/to/hass/config/custom_components/alexa_media/helpers.py https://raw.githubusercontent.com/custom-components/alexa_media_player/2cf63a3c3307798bad1f28076768c2f37ba6433b/custom_components/alexa_media/helpers.py

aneisch · 2019-09-16T22:40:43Z

Change the url above to https://raw.githubusercontent.com/custom-components/alexa_media_player/2cf63a3c3307798bad1f28076768c2f37ba6433b/custom_components/alexa_media/helpers.py 😃

wrboyce · 2019-09-16T22:41:42Z

Thanks @aneisch, clipboard error!

Kanga-Who · 2019-09-19T03:10:08Z

Can confirm the updated file fixes the issue. Thank you.

aneisch · 2019-09-19T19:31:27Z

For anyone else who stumbles here... I still had the "issue" but it turns out my configuration was wrong. I had both:

alexa_media:
  accounts:
    - email: !secret amazon_email
      password: !secret amazon_pass
      url: "amazon.com"

AND

alarm_control_panel:
  - platform: alexa_media

in my config. If you have alexa_media: it will create all of the supported domains.

alandtse added the bug Something isn't working label Sep 11, 2019

alandtse mentioned this issue Sep 11, 2019

fix(helpers): correctly treat add_devices with empty list as non error #358

Merged

alandtse mentioned this issue Sep 19, 2019

homeassistant.components.alarm_control_panel slowing reboot substantially #368

Closed

This was referenced Sep 19, 2019

Error loading component. #366

Closed

2.2.0 #371

Merged

alandtse closed this as completed in #371 Sep 19, 2019

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Taking over 60 seconds to "Setup" After restart #357

Taking over 60 seconds to "Setup" After restart #357

moriahmorgan commented Sep 10, 2019 •

edited

Loading

alandtse commented Sep 10, 2019

alandtse commented Sep 11, 2019

aneisch commented Sep 16, 2019

alandtse commented Sep 16, 2019

aneisch commented Sep 16, 2019

masonevans commented Sep 16, 2019 •

edited

Loading

aneisch commented Sep 16, 2019 •

edited

Loading

wrboyce commented Sep 16, 2019 •

edited

Loading

aneisch commented Sep 16, 2019

wrboyce commented Sep 16, 2019

Kanga-Who commented Sep 19, 2019

aneisch commented Sep 19, 2019 •

edited

Loading

Taking over 60 seconds to "Setup" After restart #357

Taking over 60 seconds to "Setup" After restart #357

Comments

moriahmorgan commented Sep 10, 2019 • edited Loading

alandtse commented Sep 10, 2019

alandtse commented Sep 11, 2019

aneisch commented Sep 16, 2019

alandtse commented Sep 16, 2019

aneisch commented Sep 16, 2019

masonevans commented Sep 16, 2019 • edited Loading

aneisch commented Sep 16, 2019 • edited Loading

wrboyce commented Sep 16, 2019 • edited Loading

aneisch commented Sep 16, 2019

wrboyce commented Sep 16, 2019

Kanga-Who commented Sep 19, 2019

aneisch commented Sep 19, 2019 • edited Loading

moriahmorgan commented Sep 10, 2019 •

edited

Loading

masonevans commented Sep 16, 2019 •

edited

Loading

aneisch commented Sep 16, 2019 •

edited

Loading

wrboyce commented Sep 16, 2019 •

edited

Loading

aneisch commented Sep 19, 2019 •

edited

Loading