No access to web UI after Hass restart or host reboot

[ghost]

@layanto commented on Oct 8, 2018, 10:47 PM UTC:

Doesn't happen every Hass restart or host reboot but happened a few times in the last few days. The only way I can fix is by reinstalling Hassio and restore snapshot. I have only started using Hassio for a few days and already had to reinstall at least 5 times. When I cannot connect to web UI, I can still connect via SSH or samba.
hassio ha logs:

core-ssh:~# hassio ha logs
Error decoding json invalid character '-' after top-level value: 2018-10-09 08:40:08 INFO (MainThread) [homeassistant.loader] Loaded history from homeassistant.components.history
2018-10-09 08:40:08 INFO (MainThread) [homeassistant.loader] Loaded recorder from homeassistant.components.recorder
2018-10-09 08:40:08 INFO (MainThread) [homeassistant.setup] Setting up http
2018-10-09 08:40:08 INFO (MainThread) [homeassistant.setup] Setup of domain http took 0.1 seconds.
2018-10-09 08:40:08 INFO (MainThread) [homeassistant.setup] Setting up recorder
2018-10-09 08:40:08 INFO (MainThread) [homeassistant.setup] Setting up websocket_api
2018-10-09 08:40:08 INFO (MainThread) [homeassistant.setup] Setup of domain websocket_api took 0.0 seconds.
2018-10-09 08:40:08 INFO (MainThread) [homeassistant.setup] Setting up api
2018-10-09 08:40:08 INFO (MainThread) [homeassistant.setup] Setting up system_log
2018-10-09 08:40:08 INFO (MainThread) [homeassistant.setup] Setup of domain system_log took 0.0 seconds.
2018-10-09 08:40:08 INFO (MainThread) [homeassistant.setup] Setting up auth
2018-10-09 08:40:08 INFO (MainThread) [homeassistant.setup] Setup of domain auth took 0.0 seconds.
2018-10-09 08:40:08 INFO (MainThread) [homeassistant.setup] Setting up onboarding
2018-10-09 08:40:08 INFO (MainThread) [homeassistant.setup] Setup of domain api took 0.1 seconds.
2018-10-09 08:40:08 INFO (MainThread) [homeassistant.setup] Setup of domain onboarding took 0.0 seconds.
2018-10-09 08:40:08 INFO (MainThread) [homeassistant.setup] Setting up frontend
2018-10-09 08:40:14 INFO (MainThread) [homeassistant.setup] Setup of domain frontend took 6.2 seconds.
2018-10-09 08:40:15 WARNING (Recorder) [homeassistant.components.recorder] Ended unfinished session (id=20 from 2018-10-08 21:23:16.377042)
2018-10-09 08:40:15 INFO (MainThread) [homeassistant.setup] Setup of domain recorder took 7.3 seconds.
2018-10-09 08:40:15 INFO (MainThread) [homeassistant.setup] Setting up history
2018-10-09 08:40:16 INFO (MainThread) [homeassistant.setup] Setup of domain history took 0.0 seconds.
2018-10-09 08:40:16 INFO (MainThread) [homeassistant.loader] Loaded updater from homeassistant.components.updater
2018-10-09 08:40:16 INFO (MainThread) [homeassistant.setup] Setting up updater
2018-10-09 08:40:16 INFO (MainThread) [homeassistant.loader] Loaded cloud from homeassistant.components.cloud
2018-10-09 08:40:16 INFO (MainThread) [homeassistant.loader] Loaded discovery from homeassistant.components.discovery
2018-10-09 08:40:16 INFO (MainThread) [homeassistant.setup] Setting up discovery
2018-10-09 08:40:16 INFO (MainThread) [homeassistant.setup] Setup of domain discovery took 0.2 seconds.
2018-10-09 08:40:16 INFO (MainThread) [homeassistant.loader] Loaded group from homeassistant.components.group
2018-10-09 08:40:16 INFO (MainThread) [homeassistant.setup] Setting up group
2018-10-09 08:40:16 INFO (MainThread) [homeassistant.setup] Setup of domain group took 0.0 seconds.
2018-10-09 08:40:16 INFO (MainThread) [homeassistant.loader] Loaded script from homeassistant.components.script
2018-10-09 08:40:16 INFO (MainThread) [homeassistant.loader] Loaded sun from homeassistant.components.sun
2018-10-09 08:40:16 INFO (MainThread) [homeassistant.setup] Setting up sun
2018-10-09 08:40:17 INFO (MainThread) [homeassistant.setup] Setup of domain sun took 0.2 seconds.
2018-10-09 08:40:17 INFO (MainThread) [homeassistant.loader] Loaded cast from homeassistant.components.cast
2018-10-09 08:40:17 INFO (MainThread) [homeassistant.setup] Setting up cast
2018-10-09 08:40:17 INFO (MainThread) [homeassistant.setup] Setup of domain cast took 0.0 seconds.
2018-10-09 08:40:17 INFO (MainThread) [homeassistant.loader] Loaded logbook from homeassistant.components.logbook
2018-10-09 08:40:17 INFO (MainThread) [homeassistant.loader] Loaded map from homeassistant.components.map
2018-10-09 08:40:17 INFO (MainThread) [homeassistant.setup] Setting up map
2018-10-09 08:40:17 INFO (MainThread) [homeassistant.setup] Setup of domain map took 0.0 seconds.
2018-10-09 08:40:17 INFO (MainThread) [homeassistant.loader] Loaded config from homeassistant.components.config
2018-10-09 08:40:17 INFO (MainThread) [homeassistant.loader] Loaded sensor from homeassistant.components.sensor
2018-10-09 08:40:17 INFO (MainThread) [homeassistant.loader] Loaded sensor.yr from homeassistant.components.sensor.yr
2018-10-09 08:40:17 INFO (MainThread) [homeassistant.setup] Setting up sensor
2018-10-09 08:40:17 INFO (MainThread) [homeassistant.loader] Loaded conversation from homeassistant.components.conversation
2018-10-09 08:40:17 INFO (MainThread) [homeassistant.loader] Loaded tts from homeassistant.components.tts
2018-10-09 08:40:17 INFO (MainThread) [homeassistant.loader] Loaded tts.google from homeassistant.components.tts.google
2018-10-09 08:40:17 INFO (MainThread) [homeassistant.loader] Loaded device_tracker from homeassistant.components.device_tracker
2018-10-09 08:40:17 INFO (MainThread) [homeassistant.loader] Loaded zone from homeassistant.components.zone
2018-10-09 08:40:17 INFO (MainThread) [homeassistant.loader] Loaded device_tracker.gpslogger from homeassistant.components.device_tracker.gpslogger
2018-10-09 08:40:17 INFO (MainThread) [homeassistant.loader] Loaded device_tracker.nmap_tracker from homeassistant.components.device_tracker.nmap_tracker
2018-10-09 08:40:17 INFO (MainThread) [homeassistant.loader] Loaded automation from homeassistant.components.automation
2018-10-09 08:40:17 INFO (MainThread) [homeassistant.components.sensor] Setting up sensor.yr
2018-10-09 08:40:17 INFO (MainThread) [homeassistant.setup] Setup of domain updater took 1.3 seconds.
2018-10-09 08:40:17 INFO (MainThread) [homeassistant.loader] Loaded media_player from homeassistant.components.media_player
2018-10-09 08:40:17 INFO (MainThread) [homeassistant.setup] Setting up zone
2018-10-09 08:40:17 INFO (MainThread) [homeassistant.setup] Setup of domain zone took 0.0 seconds.
2018-10-09 08:40:17 INFO (MainThread) [homeassistant.setup] Setting up cloud
2018-10-09 08:40:17 INFO (MainThread) [homeassistant.setup] Setup of domain cloud took 0.0 seconds.
2018-10-09 08:40:17 INFO (MainThread) [homeassistant.setup] Setting up script
2018-10-09 08:40:17 INFO (MainThread) [homeassistant.setup] Setup of domain script took 0.0 seconds.
2018-10-09 08:40:17 INFO (MainThread) [homeassistant.setup] Setting up logbook
2018-10-09 08:40:17 INFO (MainThread) [homeassistant.setup] Setup of domain logbook took 0.0 seconds.
2018-10-09 08:40:17 INFO (MainThread) [homeassistant.setup] Setting up config
2018-10-09 08:40:17 INFO (MainThread) [homeassistant.setup] Setting up conversation2018-10-09 08:40:17 INFO (MainThread) [homeassistant.setup] Setup of domain conversation took 0.1 seconds.
2018-10-09 08:40:17 INFO (MainThread) [homeassistant.setup] Setting up tts
2018-10-09 08:40:17 INFO (MainThread) [homeassistant.setup] Setting up automation
2018-10-09 08:40:17 INFO (MainThread) [homeassistant.setup] Setup of domain automation took 0.0 seconds.
2018-10-09 08:40:17 INFO (MainThread) [homeassistant.loader] Loaded config.config_entries from homeassistant.components.config.config_entries
2018-10-09 08:40:17 INFO (MainThread) [homeassistant.loader] Loaded config.core from homeassistant.components.config.core
2018-10-09 08:40:17 INFO (MainThread) [homeassistant.loader] Loaded config.customize from homeassistant.components.config.customize
2018-10-09 08:40:17 INFO (MainThread) [homeassistant.loader] Loaded config.device_registry from homeassistant.components.config.device_registry
2018-10-09 08:40:18 INFO (MainThread) [homeassistant.loader] Loaded config.entity_registry from homeassistant.components.config.entity_registry
2018-10-09 08:40:18 INFO (MainThread) [homeassistant.loader] Loaded config.group from homeassistant.components.config.group
2018-10-09 08:40:18 INFO (MainThread) [homeassistant.loader] Loaded config.hassbian from homeassistant.components.config.hassbian
2018-10-09 08:40:18 INFO (MainThread) [homeassistant.loader] Loaded config.auth from homeassistant.components.config.auth
2018-10-09 08:40:18 INFO (MainThread) [homeassistant.loader] Loaded config.script from homeassistant.components.config.script
2018-10-09 08:40:18 INFO (MainThread) [homeassistant.loader] Loaded config.automation from homeassistant.components.config.automation
2018-10-09 08:40:18 INFO (MainThread) [homeassistant.loader] Loaded config.auth_provider_homeassistant from homeassistant.components.config.auth_provider_homeassistant
2018-10-09 08:40:18 INFO (MainThread) [homeassistant.setup] Setting up media_player2018-10-09 08:40:18 INFO (MainThread) [homeassistant.setup] Setup of domain media_player took 0.0 seconds.
2018-10-09 08:40:18 INFO (MainThread) [homeassistant.setup] Setting up device_tracker
2018-10-09 08:40:18 INFO (MainThread) [homeassistant.loader] Loaded media_player.cast from homeassistant.components.media_player.cast
2018-10-09 08:40:18 INFO (MainThread) [homeassistant.components.media_player] Setting up media_player.cast
2018-10-09 08:40:18 INFO (MainThread) [homeassistant.setup] Setup of domain config took 0.7 seconds.
2018-10-09 08:40:18 INFO (MainThread) [homeassistant.setup] Setup of domain tts took 0.5 seconds.
2018-10-09 08:40:18 INFO (MainThread) [homeassistant.components.device_tracker] Setting up device_tracker.nmap_tracker
2018-10-09 08:40:18 INFO (SyncWorker_19) [homeassistant.components.device_tracker.nmap_tracker] Scanner initialized
2018-10-09 08:40:18 INFO (MainThread) [homeassistant.components.device_tracker] Setting up device_tracker.gpslogger
2018-10-09 08:40:18 INFO (SyncWorker_10) [homeassistant.components.device_tracker.nmap_tracker] Scanning...
2018-10-09 08:40:19 INFO (MainThread) [homeassistant.setup] Setup of domain device_tracker took 1.1 seconds.
2018-10-09 08:40:19 INFO (SyncWorker_5) [pychromecast] Querying device status
2018-10-09 08:40:19 INFO (SyncWorker_12) [pychromecast] Querying device status
2018-10-09 08:40:19 ERROR (SyncWorker_12) [pychromecast.socket_client] Failed to connect, retrying in 5.0s
2018-10-09 08:40:20 INFO (MainThread) [homeassistant.setup] Setup of domain sensor took 3.8 seconds.
2018-10-09 08:40:26 INFO (SyncWorker_10) [homeassistant.components.device_tracker.nmap_tracker] nmap scan successful
2018-10-09 09:07:54 WARNING (Thread-2) [pychromecast.socket_client] Heartbeat timeout, resetting connection
2018-10-09 09:08:24 ERROR (Thread-2) [pychromecast.socket_client] Failed to connect, retrying in 5.0s

This issue was moved by pvizeli from home-assistant/hassio#746.

[ghost]

@layanto commented on Oct 9, 2018, 12:09 AM UTC:

configuration.yaml:

homeassistant:
  # Name of the location where Home Assistant is running
  name: Home
  # Location required to calculate the time the sun rises and sets
  latitude: xxx
  longitude: xxx
  # Impacts weather/sunrise data (altitude above sea level in meters)
  elevation: xxx
  # metric for Metric, imperial for Imperial
  unit_system: metric
  # Pick yours from here: http://en.wikipedia.org/wiki/List_of_tz_database_time_zones
  time_zone: xxx
  # Customization file
  customize: !include customize.yaml
  auth_providers:
   - type: homeassistant
#   - type: trusted_networks

# Show links to resources in log and frontend
#introduction:

# Enables the frontend
frontend:

# Enables configuration UI
config:

# Uncomment this if you are using SSL/TLS, running in Docker container, etc.
http:
#   base_url: example.duckdns.org:8123
#  use_x_forwarded_for: true
#  trusted_proxies:
#    - 127.0.0.1
#    - 192.168.1.1
#    - ::1
  trusted_networks:
    - 127.0.0.1
    - ::1
    - 192.168.1.0/24
    - fd00::/8
  ip_ban_enabled: true
  login_attempts_threshold: 5

# Checks for available updates
# Note: This component will send some information about your system to
# the developers to assist with development of Home Assistant.
# For more information, please see:
# https://home-assistant.io/blog/2016/10/25/explaining-the-updater/
updater:
  # Optional, allows Home Assistant developers to focus on popular components.
  # include_used_components: true

# Discover some devices automatically
discovery:

# Allows you to issue voice commands from the frontend in enabled browsers
conversation:

# Enables support for tracking state changes over time
history:

# View all events in a logbook
logbook:

# Enables a map showing the location of tracked devices
map:

# Track the sun
sun:

# Weather prediction
sensor:
  - platform: yr

# Text to speech
tts:
  - platform: google

# Cloud
cloud:

group: !include groups.yaml
automation: !include automations.yaml
script: !include scripts.yaml

device_tracker:
  - platform: nmap_tracker
    hosts: 192.168.1.0/24
    home_interval: 15
    exclude:
      - 192.168.1.1
    new_device_defaults:
      track_new_devices: False
      hide_if_away: False
    scan_interval: 30

[ghost]

@layanto commented on Oct 9, 2018, 1:06 AM UTC:

Running hassio ha start returns ERROR
Found this https://community.home-assistant.io/t/hass-io-0-75-1-and-earlier-no-web-interface-on-port-8123-no-network-connection-for-docker-image-homeassistant/62909/2

Deleting .storage/core.config_entries and reboot host solved the problem. But I imagine this will occur again when Chromecast gets discovered again.

[ghost]

@layanto commented on Oct 9, 2018, 11:07 AM UTC:

I think it is caused by this software on my PC emulating Google cast https://www.airserver.com/PC

[ghost]

@pvizeli commented on Oct 9, 2018, 3:01 PM UTC:

You can remove discovery: from config and add hassio: look like chromecast locks the startup

[balloob]

CC @OttoWinter @awarecan

[OttoWinter]

Yes that would probably be because of the cast platform. The problem is that we're trying to connect to the chromecast here:

https://github.com/home-assistant/home-assistant/blob/e903f7ffdafc7f5e0797f654c9b8314529412775/homeassistant/components/media_player/cast.py#L380-L384

but if the connecting takes forever (could happen for many reasons), we await this forever.

And if I understand correctly, home assistant waits for the entire task queue to clear before starting up. As this one chromecast connection task is never finished, home assistant doesn't start up.

There was an attempt to limit the amount of time the connection could take before giving up (#16471), but that had other consequences that resulted in issues for some other cast users.

Thinking about this again, I guess the easiest solution would be to delay connecting to chromecast until after home assistant is started up already. But maybe my conclusion in the paragraph before is also wrong.

@balloob I know there is EVENT_HOMEASSISTANT_START, which we could use to delay connecting. But if the chromecast is added dynamically at runtime (for example through discovery), we would wait for that event forever because it already happened. Is there a way to check if EVENT_HOMEASSISTANT_START has already been fired before or if home assistant is already properly started up?

[balloob]

The bug here is that any connection that we make should have a timeout. So we should add a timeout here. Adding it after start is not preferred, as it triggers automations.

Here is how to detect if we have started or not:

https://github.com/home-assistant/home-assistant/blob/419725e1a9026afe63640426ac14ae5124d91cc1/homeassistant/components/automation/__init__.py#L251-L262

[awarecan]

Last time I try to add timeout on this function failed miserable, remembered?

Alternative solution is only add timeout when we are in the startup phase, but I am not sure if it will affect the device turned on after the startup.

 if self.hass.state == CoreState.not_running: 
  tries = 1
 else: 
  tries = None
 chromecast = await self.hass.async_add_job( 
     pychromecast._get_chromecast_from_host, ( 
         cast_info.host, cast_info.port, cast_info.uuid, 
         cast_info.model_name, cast_info.friendly_name 
     ), tries) 

Since I already returned my chromecast, I would not touch this again 😃

[layanto]

I disabled AirServer from emulating Google cast and no longer has this problem.
@pvizeli what does hassio: do in configuration.yaml?

[jpmii]

I've had this for awhile now too, someone mentioned it to me before but if you delete the config/.storage/core.config_entries file and then reboot, HA comes back up. You'll have to rediscover the chromecasts again and it will lock up every reboot but if you have Samba/SSH working it's easier than flashing a new Hassio image.

[reprz]

I´m having this issue now. Some errors in logs about Chromecast prior to reboot. After reboot I cannot connect to frontend and even SSH / Samba are down. I need to reflash again. This is pretty frustrating. My setup is RPI3 and I have two Chromecasts, This is a second reflash in one week. My Hassio just doesn´t start after reboot.

[emontnemery]

@balloob Why does pychromecast need to do blocking IO in SocketClient constructor, can't that just as well be handled by the normal (re)connect handling?

[balloob]

You are asking me about the rationale of a contribution of 3 years ago? 😝 I think at this point, you have a better understanding of pychromecast than me.

[emontnemery]

@layanto, @jpmii, @reprz Can you please give the fix in #21565 a try? Please note you also need to patch pychromecast with home-assistant-libs/pychromecast#271

[robbiet480]

@emontnemery As I said in #21565, that fix worked for me. I didn't even have to patch pychromecast!