Core: No web UI when bluetooth tracker is enabled

Created on 16 May 2019  路  19Comments  路  Source: home-assistant/core

Home Assistant release with the issue:

0.92.2

Last working Home Assistant release (if known):

Operating environment (Hass.io/Docker/Windows/etc.):

Haspbian (RPi 3 running Raspbian 9.9 with latest)

Component/platform:

https://www.home-assistant.io/components/bluetooth_tracker/

Description of problem:
After I got bluetooth tracker running and found some devices, I got no web UI after I restart HA. My steps were:

  • I have 3 tracking components initialized: owntracks (via UI -> Integrations) and mikrotik + bluetooth in configuration file
  • I got owntracks and mikrotik working, but not bluetooth
  • After sometime I found that HA code claims that there's no libbluetooth.so.3 available, so I just installed libbluetooth3 package
  • After HA restart I got 2 phones added into known_devices file
  • I decided to add these 2 devices into persons records, and restarted HA
  • After that I got no web UI running

I commented those 2 lines I added into persons previously - no luck.
Then I found that I have to comment bluetooth_tracker in device_tracker section configuration, only when I disable BT I get web UI running
I don't know what's the reason of that, how can I debug this better?

Problem-relevant configuration.yaml entries and (fill out even if it seems unimportant):

device_tracker:
  - platform: mikrotik
    host: router.home
    username: !secret router_user
    password: !secret router_pass
  #- platform: bluetooth_tracker

person:
  - name: Serge
    id: serge
    device_trackers:
      - device_tracker.serge_minote3
      #- device_tracker.mi_phone
  - name: Olya
    id: olya
    device_trackers:
      - device_tracker.olya_mi5
      #- device_tracker.olya

Commented device tracker lines are phones found by bluetooth tracker. Doesn't matter if those are commented or not, I decided to leave as is for now.

Traceback (if applicable):

Additional information:
I found similar issue in hassio (https://github.com/home-assistant/hassio/issues/858), but decided to crosspost here as my env is haspbian, not hassio.
Any help how to debug that would be highly appreciated.
I see 0.93 is released, I checked release notes and found nothing related to bluetooth tracker, but I'll update HA tomorrow to latest and check if BT is fixed or not.

bluetooth_tracker
Source
picture sergeolkhovik

Most helpful comment

Any update on this one? With Google home BT presence not working due to Google API changes, would be nice if this one was resolved.

picture dicko72 on 7 Aug 2019
👍2

All 19 comments

Please post your log. Your HA is not fully started.

awarecan picture awarecan on 18 May 2019

Sure, here it is (level info, just uncommented that line with bluetooth tracker):

2019-05-21 23:09:50 INFO (MainThread) [homeassistant.setup] Setup of domain logger took 0.0 seconds.
2019-05-21 23:09:50 INFO (MainThread) [homeassistant.setup] Setting up http
2019-05-21 23:09:50 INFO (MainThread) [homeassistant.setup] Setup of domain http took 0.0 seconds.
2019-05-21 23:09:50 INFO (MainThread) [homeassistant.setup] Setting up system_log
2019-05-21 23:09:50 INFO (MainThread) [homeassistant.setup] Setup of domain system_log took 0.0 seconds.
2019-05-21 23:09:50 INFO (MainThread) [homeassistant.setup] Setting up recorder
2019-05-21 23:09:54 INFO (MainThread) [homeassistant.setup] Setup of domain recorder took 4.0 seconds.
2019-05-21 23:09:54 INFO (Thread-16) [homeassistant.loader] Loaded moon from homeassistant.components.moon
2019-05-21 23:09:55 INFO (MainThread) [homeassistant.setup] Setting up lovelace
2019-05-21 23:09:55 INFO (MainThread) [homeassistant.setup] Setup of domain lovelace took 0.2 seconds.
2019-05-21 23:09:55 INFO (MainThread) [homeassistant.setup] Setting up speedtestdotnet
2019-05-21 23:09:55 INFO (MainThread) [homeassistant.setup] Setup of domain speedtestdotnet took 0.0 seconds.
2019-05-21 23:09:55 INFO (Thread-9) [homeassistant.loader] Loaded kodi from homeassistant.components.kodi
2019-05-21 23:09:55 INFO (MainThread) [homeassistant.setup] Setting up shell_command
2019-05-21 23:09:55 INFO (MainThread) [homeassistant.setup] Setup of domain shell_command took 0.0 seconds.
2019-05-21 23:09:55 INFO (MainThread) [homeassistant.setup] Setting up apcupsd
2019-05-21 23:09:55 INFO (MainThread) [homeassistant.setup] Setting up upnp
2019-05-21 23:09:55 INFO (MainThread) [homeassistant.setup] Setting up person
2019-05-21 23:09:56 INFO (MainThread) [homeassistant.setup] Setting up esphome
2019-05-21 23:09:56 INFO (MainThread) [homeassistant.setup] Setup of domain esphome took 0.0 seconds.
2019-05-21 23:09:57 INFO (MainThread) [homeassistant.setup] Setting up alert
2019-05-21 23:09:57 INFO (MainThread) [homeassistant.setup] Setting up ffmpeg
2019-05-21 23:09:57 INFO (MainThread) [homeassistant.setup] Setting up input_select
2019-05-21 23:09:57 INFO (MainThread) [homeassistant.setup] Setting up updater
2019-05-21 23:09:57 INFO (MainThread) [homeassistant.setup] Setting up zone
2019-05-21 23:09:57 INFO (MainThread) [homeassistant.setup] Setup of domain zone took 0.0 seconds.
2019-05-21 23:09:58 INFO (MainThread) [homeassistant.setup] Setting up group
2019-05-21 23:09:58 INFO (MainThread) [homeassistant.setup] Setting up cast
2019-05-21 23:09:58 INFO (MainThread) [homeassistant.setup] Setup of domain cast took 0.0 seconds.
2019-05-21 23:09:58 INFO (Thread-19) [homeassistant.loader] Loaded openweathermap from homeassistant.components.openweathermap
2019-05-21 23:09:58 INFO (MainThread) [homeassistant.setup] Setting up wake_on_lan
2019-05-21 23:09:58 INFO (MainThread) [homeassistant.setup] Setup of domain wake_on_lan took 0.0 seconds.
2019-05-21 23:09:58 INFO (MainThread) [homeassistant.setup] Setting up sun
2019-05-21 23:09:58 INFO (MainThread) [homeassistant.setup] Setup of domain sun took 0.2 seconds.
2019-05-21 23:09:58 INFO (Thread-4) [homeassistant.loader] Loaded ping from homeassistant.components.ping
2019-05-21 23:09:58 INFO (MainThread) [homeassistant.setup] Setting up input_boolean
2019-05-21 23:09:58 INFO (MainThread) [homeassistant.setup] Setting up octoprint
2019-05-21 23:09:58 INFO (MainThread) [homeassistant.setup] Setup of domain upnp took 3.1 seconds.
2019-05-21 23:09:58 INFO (Thread-11) [homeassistant.loader] Loaded smtp from homeassistant.components.smtp
2019-05-21 23:09:59 INFO (MainThread) [homeassistant.setup] Setup of domain apcupsd took 3.6 seconds.
2019-05-21 23:09:59 INFO (MainThread) [homeassistant.setup] Setup of domain updater took 1.3 seconds.
2019-05-21 23:09:59 INFO (Thread-3) [homeassistant.loader] Loaded media_player from homeassistant.components.media_player
2019-05-21 23:09:59 INFO (Thread-12) [homeassistant.loader] Loaded darksky from homeassistant.components.darksky
2019-05-21 23:09:59 INFO (Thread-13) [homeassistant.loader] Loaded template from homeassistant.components.template
2019-05-21 23:09:59 INFO (MainThread) [homeassistant.setup] Setting up config
2019-05-21 23:10:00 INFO (MainThread) [homeassistant.setup] Setting up api
2019-05-21 23:10:00 INFO (MainThread) [homeassistant.setup] Setting up telegram_bot
2019-05-21 23:10:00 INFO (MainThread) [homeassistant.components.telegram_bot] Setting up telegram_bot.webhooks
2019-05-21 23:10:01 INFO (MainThread) [homeassistant.setup] Setting up system_health
2019-05-21 23:10:01 INFO (MainThread) [homeassistant.setup] Setup of domain system_health took 0.0 seconds.
2019-05-21 23:10:01 INFO (Thread-15) [homeassistant.loader] Loaded climate from homeassistant.components.climate
2019-05-21 23:10:01 INFO (Thread-20) [homeassistant.loader] Loaded cover from homeassistant.components.cover
2019-05-21 23:10:01 INFO (MainThread) [homeassistant.setup] Setup of domain alert took 3.6 seconds.
2019-05-21 23:10:01 INFO (Thread-2) [homeassistant.loader] Loaded fan from homeassistant.components.fan
2019-05-21 23:10:01 INFO (Thread-16) [homeassistant.loader] Loaded light from homeassistant.components.light
2019-05-21 23:10:01 INFO (MainThread) [homeassistant.setup] Setting up history
2019-05-21 23:10:01 INFO (MainThread) [homeassistant.setup] Setup of domain history took 0.0 seconds.
2019-05-21 23:10:01 INFO (MainThread) [homeassistant.setup] Setting up websocket_api
2019-05-21 23:10:01 INFO (MainThread) [homeassistant.setup] Setup of domain websocket_api took 0.0 seconds.
2019-05-21 23:10:01 INFO (MainThread) [homeassistant.setup] Setting up mqtt
2019-05-21 23:10:01 INFO (MainThread) [homeassistant.setup] Setup of domain mqtt took 0.0 seconds.
2019-05-21 23:10:01 INFO (Thread-14) [homeassistant.loader] Loaded google_translate from homeassistant.components.google_translate
2019-05-21 23:10:01 INFO (MainThread) [homeassistant.setup] Setting up webhook
2019-05-21 23:10:01 INFO (MainThread) [homeassistant.setup] Setup of domain webhook took 0.0 seconds.
2019-05-21 23:10:01 ERROR (Thread-10) [homeassistant.components.octoprint] Endpoint: printer Failed to update OctoPrint status.   Error: HTTPConnectionPool(host='x', port=80): Max retries exceeded with url: /api/printer (Caused by NewConnectionError('<urllib3.connection.HTTPConnection object at 0x68dc68f0>: Failed to establish a new connection: [Errno 113] No route to host',))
2019-05-21 23:10:02 INFO (MainThread) [homeassistant.setup] Setting up conversation
2019-05-21 23:10:02 INFO (MainThread) [homeassistant.setup] Setup of domain conversation took 0.0 seconds.
2019-05-21 23:10:02 INFO (MainThread) [homeassistant.setup] Setting up auth
2019-05-21 23:10:02 INFO (MainThread) [homeassistant.setup] Setup of domain auth took 0.0 seconds.
2019-05-21 23:10:02 INFO (Thread-5) [homeassistant.loader] Loaded telegram from homeassistant.components.telegram
2019-05-21 23:10:02 INFO (MainThread) [homeassistant.setup] Setup of domain ffmpeg took 4.8 seconds.
2019-05-21 23:10:02 INFO (MainThread) [homeassistant.setup] Setting up weather
2019-05-21 23:10:03 INFO (MainThread) [homeassistant.setup] Setting up binary_sensor
2019-05-21 23:10:03 INFO (MainThread) [homeassistant.setup] Setup of domain api took 3.1 seconds.
2019-05-21 23:10:03 INFO (MainThread) [homeassistant.setup] Setting up climate
2019-05-21 23:10:03 INFO (MainThread) [homeassistant.setup] Setup of domain climate took 0.0 seconds.
2019-05-21 23:10:03 INFO (MainThread) [homeassistant.setup] Setting up tts
2019-05-21 23:10:04 INFO (MainThread) [homeassistant.components.weather] Setting up weather.openweathermap
2019-05-21 23:10:04 INFO (Thread-4) [homeassistant.loader] Loaded command_line from homeassistant.components.command_line
2019-05-21 23:10:04 INFO (MainThread) [homeassistant.components.weather] Setting up weather.darksky
2019-05-21 23:10:04 INFO (MainThread) [homeassistant.components.binary_sensor] Setting up binary_sensor.template
2019-05-21 23:10:04 INFO (MainThread) [homeassistant.components.binary_sensor] Setting up binary_sensor.ping
2019-05-21 23:10:05 ERROR (Thread-10) [homeassistant.components.octoprint] Endpoint: job Failed to update OctoPrint status.   Error: HTTPConnectionPool(host='x', port=80): Max retries exceeded with url: /api/job (Caused by NewConnectionError('<urllib3.connection.HTTPConnection object at 0x68a05fd0>: Failed to establish a new connection: [Errno 113] No route to host',))
2019-05-21 23:10:05 INFO (MainThread) [homeassistant.components.binary_sensor] Setting up binary_sensor.ping
2019-05-21 23:10:05 INFO (MainThread) [homeassistant.components.binary_sensor] Setting up binary_sensor.mqtt
2019-05-21 23:10:05 INFO (MainThread) [homeassistant.components.binary_sensor] Setting up binary_sensor.apcupsd
2019-05-21 23:10:05 INFO (MainThread) [homeassistant.components.binary_sensor] Setting up binary_sensor.mqtt
2019-05-21 23:10:05 INFO (MainThread) [homeassistant.setup] Setup of domain config took 5.7 seconds.
2019-05-21 23:10:05 INFO (Thread-13) [homeassistant.loader] Loaded mjpeg from homeassistant.components.mjpeg
2019-05-21 23:10:05 INFO (MainThread) [homeassistant.components.climate] Setting up climate.esphome
2019-05-21 23:10:05 INFO (MainThread) [homeassistant.components.climate] Setting up climate.esphome
2019-05-21 23:10:05 INFO (MainThread) [homeassistant.components.climate] Setting up climate.esphome
2019-05-21 23:10:05 INFO (MainThread) [homeassistant.setup] Setting up notify
2019-05-21 23:10:07 INFO (MainThread) [homeassistant.setup] Setting up cloud
2019-05-21 23:10:10 INFO (MainThread) [homeassistant.setup] Setting up onboarding
2019-05-21 23:10:10 INFO (MainThread) [homeassistant.components.notify] Setting up notify.smtp
2019-05-21 23:10:10 INFO (MainThread) [homeassistant.components.notify] Setting up notify.kodi
2019-05-21 23:10:10 INFO (MainThread) [homeassistant.setup] Setting up media_player
2019-05-21 23:10:10 INFO (MainThread) [homeassistant.setup] Setup of domain media_player took 0.0 seconds.
2019-05-21 23:10:10 INFO (MainThread) [homeassistant.components.telegram_bot.webhooks] Set new telegram webhook x
2019-05-21 23:10:10 INFO (MainThread) [homeassistant.setup] Setup of domain telegram_bot took 10.5 seconds.
2019-05-21 23:10:11 WARNING (MainThread) [homeassistant.setup] Setup of person is taking over 10 seconds.
2019-05-21 23:10:11 INFO (Thread-9) [homeassistant.loader] Loaded uptime from homeassistant.components.uptime
2019-05-21 23:10:11 WARNING (MainThread) [homeassistant.setup] Setup of input_select is taking over 10 seconds.
2019-05-21 23:10:11 WARNING (MainThread) [homeassistant.setup] Setup of group is taking over 10 seconds.
2019-05-21 23:10:11 WARNING (MainThread) [homeassistant.setup] Setup of input_boolean is taking over 10 seconds.
2019-05-21 23:10:11 WARNING (MainThread) [homeassistant.setup] Setup of octoprint is taking over 10 seconds.
2019-05-21 23:10:11 INFO (MainThread) [homeassistant.setup] Setup of domain octoprint took 12.7 seconds.
2019-05-21 23:10:11 INFO (MainThread) [homeassistant.setup] Setting up zeroconf
2019-05-21 23:10:11 INFO (Thread-14) [homeassistant.loader] Loaded onvif from homeassistant.components.onvif
2019-05-21 23:10:11 INFO (MainThread) [homeassistant.components.media_player] Setting up media_player.cast
2019-05-21 23:10:11 INFO (MainThread) [homeassistant.components.binary_sensor] Setting up binary_sensor.octoprint
2019-05-21 23:10:11 INFO (Thread-13) [homeassistant.loader] Loaded systemmonitor from homeassistant.components.systemmonitor
2019-05-21 23:10:11 INFO (MainThread) [homeassistant.components.notify] Setting up notify.telegram
2019-05-21 23:10:11 INFO (MainThread) [homeassistant.setup] Setup of domain cloud took 4.7 seconds.
2019-05-21 23:10:12 INFO (MainThread) [homeassistant.setup] Setting up camera
2019-05-21 23:10:12 INFO (MainThread) [homeassistant.setup] Setup of domain onboarding took 1.7 seconds.
2019-05-21 23:10:12 ERROR (MainThread) [homeassistant.components.person] Duplicate user_id 4e95dca0d0834698ab74df4cbde57187 detected for person 0b8f3ddebf8a44529f7a741681b8b453
2019-05-21 23:10:12 INFO (MainThread) [homeassistant.setup] Setting up sensor
2019-05-21 23:10:12 INFO (MainThread) [homeassistant.setup] Setup of domain tts took 9.3 seconds.
2019-05-21 23:10:12 INFO (MainThread) [homeassistant.setup] Setup of domain input_select took 14.8 seconds.
2019-05-21 23:10:12 INFO (MainThread) [homeassistant.setup] Setup of domain input_boolean took 14.3 seconds.
2019-05-21 23:10:12 INFO (MainThread) [homeassistant.components.sensor] Setting up sensor.command_line
2019-05-21 23:10:12 INFO (MainThread) [homeassistant.components.sensor] Setting up sensor.template
2019-05-21 23:10:12 INFO (MainThread) [homeassistant.components.sensor] Setting up sensor.uptime
2019-05-21 23:10:12 INFO (MainThread) [homeassistant.components.sensor] Setting up sensor.darksky
2019-05-21 23:10:12 INFO (MainThread) [homeassistant.components.sensor] Setting up sensor.command_line
2019-05-21 23:10:12 INFO (MainThread) [homeassistant.components.sensor] Setting up sensor.openweathermap
2019-05-21 23:10:12 INFO (MainThread) [homeassistant.components.sensor] Setting up sensor.command_line
2019-05-21 23:10:12 INFO (MainThread) [homeassistant.components.sensor] Setting up sensor.moon
2019-05-21 23:10:12 INFO (MainThread) [homeassistant.components.sensor] Setting up sensor.systemmonitor
2019-05-21 23:10:12 INFO (MainThread) [homeassistant.components.sensor] Setting up sensor.command_line
2019-05-21 23:10:12 INFO (MainThread) [homeassistant.components.sensor] Setting up sensor.command_line
2019-05-21 23:10:12 INFO (MainThread) [homeassistant.components.sensor] Setting up sensor.mqtt
2019-05-21 23:10:12 INFO (MainThread) [homeassistant.components.sensor] Setting up sensor.mqtt
2019-05-21 23:10:12 INFO (MainThread) [homeassistant.components.sensor] Setting up sensor.mqtt
2019-05-21 23:10:12 INFO (MainThread) [homeassistant.components.sensor] Setting up sensor.mqtt
2019-05-21 23:10:12 INFO (MainThread) [homeassistant.components.sensor] Setting up sensor.mqtt
2019-05-21 23:10:12 INFO (MainThread) [homeassistant.components.sensor] Setting up sensor.mqtt
2019-05-21 23:10:12 INFO (MainThread) [homeassistant.components.sensor] Setting up sensor.mqtt
2019-05-21 23:10:12 INFO (MainThread) [homeassistant.components.sensor] Setting up sensor.mqtt
2019-05-21 23:10:12 INFO (MainThread) [homeassistant.components.sensor] Setting up sensor.apcupsd
2019-05-21 23:10:12 INFO (MainThread) [homeassistant.components.sensor] Setting up sensor.mqtt
2019-05-21 23:10:12 INFO (MainThread) [homeassistant.components.sensor] Setting up sensor.mqtt
2019-05-21 23:10:12 INFO (MainThread) [homeassistant.components.sensor] Setting up sensor.command_line
2019-05-21 23:10:12 INFO (MainThread) [homeassistant.components.sensor] Setting up sensor.command_line
2019-05-21 23:10:12 INFO (MainThread) [homeassistant.components.sensor] Setting up sensor.mqtt
2019-05-21 23:10:12 INFO (MainThread) [homeassistant.components.sensor] Setting up sensor.mqtt
2019-05-21 23:10:12 INFO (MainThread) [homeassistant.components.sensor] Setting up sensor.mqtt
2019-05-21 23:10:12 INFO (MainThread) [homeassistant.components.sensor] Setting up sensor.mqtt
2019-05-21 23:10:12 INFO (MainThread) [homeassistant.setup] Setting up frontend
2019-05-21 23:10:15 INFO (MainThread) [homeassistant.setup] Setup of domain zeroconf took 4.2 seconds.
2019-05-21 23:10:15 WARNING (MainThread) [homeassistant.components.weather] Setup of platform openweathermap is taking over 10 seconds.
2019-05-21 23:10:15 WARNING (MainThread) [homeassistant.components.weather] Setup of platform darksky is taking over 10 seconds.
2019-05-21 23:10:15 WARNING (MainThread) [homeassistant.components.binary_sensor] Setup of platform ping is taking over 10 seconds.
2019-05-21 23:10:15 WARNING (MainThread) [homeassistant.components.binary_sensor] Setup of platform mqtt is taking over 10 seconds.
2019-05-21 23:10:15 WARNING (MainThread) [homeassistant.components.binary_sensor] Setup of platform apcupsd is taking over 10 seconds.
2019-05-21 23:10:15 INFO (MainThread) [homeassistant.components.camera] Setting up camera.mjpeg
2019-05-21 23:10:15 INFO (MainThread) [homeassistant.components.camera] Setting up camera.mjpeg
2019-05-21 23:10:15 INFO (MainThread) [homeassistant.components.camera] Setting up camera.mjpeg
2019-05-21 23:10:15 INFO (Thread-11) [pychromecast] Querying device status
2019-05-21 23:10:15 INFO (Thread-3) [pychromecast] Querying device status
2019-05-21 23:10:15 INFO (Thread-4) [pychromecast] Querying device status
2019-05-21 23:10:15 INFO (MainThread) [homeassistant.setup] Setup of domain person took 19.9 seconds.
2019-05-21 23:10:16 INFO (MainThread) [homeassistant.components.camera] Setting up camera.onvif
2019-05-21 23:10:16 INFO (MainThread) [homeassistant.setup] Setup of domain frontend took 3.2 seconds.
2019-05-21 23:10:16 INFO (MainThread) [homeassistant.setup] Setup of domain group took 18.2 seconds.
2019-05-21 23:10:16 INFO (MainThread) [homeassistant.setup] Setup of domain weather took 13.5 seconds.
2019-05-21 23:10:16 INFO (MainThread) [homeassistant.components.notify] Setting up notify.group
2019-05-21 23:10:16 INFO (MainThread) [homeassistant.setup] Setting up logbook
2019-05-21 23:10:16 INFO (MainThread) [homeassistant.setup] Setup of domain logbook took 0.0 seconds.
2019-05-21 23:10:16 INFO (MainThread) [homeassistant.setup] Setting up map
2019-05-21 23:10:16 INFO (MainThread) [homeassistant.setup] Setup of domain map took 0.0 seconds.
2019-05-21 23:10:16 INFO (MainThread) [homeassistant.setup] Setting up switch
2019-05-21 23:10:17 INFO (MainThread) [homeassistant.setup] Setting up script
2019-05-21 23:10:18 INFO (MainThread) [homeassistant.setup] Setting up automation
2019-05-21 23:10:18 INFO (MainThread) [homeassistant.setup] Setting up cover
2019-05-21 23:10:18 INFO (MainThread) [homeassistant.setup] Setup of domain cover took 0.0 seconds.
2019-05-21 23:10:18 INFO (Thread-10) [homeassistant.loader] Loaded mikrotik from homeassistant.components.mikrotik
2019-05-21 23:10:18 INFO (MainThread) [homeassistant.setup] Setting up fan
2019-05-21 23:10:18 INFO (MainThread) [homeassistant.setup] Setup of domain fan took 0.0 seconds.
2019-05-21 23:10:18 INFO (MainThread) [homeassistant.setup] Setting up light
2019-05-21 23:10:18 INFO (MainThread) [homeassistant.setup] Setup of domain notify took 13.2 seconds.
2019-05-21 23:10:18 INFO (MainThread) [homeassistant.components.switch] Setting up switch.wake_on_lan
2019-05-21 23:10:18 INFO (MainThread) [homeassistant.components.switch] Setting up switch.template
2019-05-21 23:10:18 INFO (MainThread) [homeassistant.components.switch] Setting up switch.wake_on_lan
2019-05-21 23:10:18 INFO (MainThread) [homeassistant.components.switch] Setting up switch.wake_on_lan
2019-05-21 23:10:19 INFO (MainThread) [homeassistant.components.cover] Setting up cover.esphome
2019-05-21 23:10:19 INFO (MainThread) [homeassistant.components.cover] Setting up cover.esphome
2019-05-21 23:10:19 INFO (MainThread) [homeassistant.components.cover] Setting up cover.esphome
2019-05-21 23:10:19 INFO (MainThread) [homeassistant.components.fan] Setting up fan.esphome
2019-05-21 23:10:19 INFO (MainThread) [homeassistant.components.fan] Setting up fan.esphome
2019-05-21 23:10:19 INFO (MainThread) [homeassistant.components.fan] Setting up fan.esphome
2019-05-21 23:10:19 INFO (MainThread) [homeassistant.setup] Setup of domain light took 1.0 seconds.
2019-05-21 23:10:19 INFO (Thread-19) [homeassistant.loader] Loaded bluetooth_tracker from homeassistant.components.bluetooth_tracker
2019-05-21 23:10:19 INFO (MainThread) [homeassistant.setup] Setup of domain script took 1.9 seconds.
2019-05-21 23:10:19 INFO (MainThread) [homeassistant.components.light] Setting up light.esphome
2019-05-21 23:10:19 INFO (MainThread) [homeassistant.components.light] Setting up light.esphome
2019-05-21 23:10:19 INFO (MainThread) [homeassistant.components.light] Setting up light.esphome
2019-05-21 23:10:20 INFO (MainThread) [homeassistant.setup] Setting up device_tracker
2019-05-21 23:10:20 INFO (MainThread) [homeassistant.setup] Setup of domain automation took 1.8 seconds.
2019-05-21 23:10:21 INFO (MainThread) [homeassistant.components.device_tracker] Setting up device_tracker.mikrotik
2019-05-21 23:10:21 INFO (MainThread) [homeassistant.components.device_tracker] Setting up device_tracker.bluetooth_tracker
2019-05-21 23:10:21 INFO (MainThread) [homeassistant.components.alert] Alerting: 袣芯屑锌'褞褌械褉 褍胁褨屑泻薪褍褌芯: Dzeta
2019-05-21 23:10:22 INFO (Thread-8) [homeassistant.components.mikrotik.device_tracker] Connected to Mikrotik 951G-2HnD with IP x
2019-05-21 23:10:22 INFO (Thread-8) [homeassistant.components.mikrotik.device_tracker] Mikrotik x: Not a CAPSman controller. Trying local interfaces
2019-05-21 23:10:23 INFO (Thread-8) [homeassistant.components.mikrotik.device_tracker] Start polling Mikrotik (x) router...
2019-05-21 23:10:23 WARNING (MainThread) [homeassistant.components.sensor] Setup of platform darksky is taking over 10 seconds.
2019-05-21 23:10:23 INFO (MainThread) [homeassistant.setup] Setup of domain switch took 6.7 seconds.
2019-05-21 23:10:23 INFO (MainThread) [homeassistant.components.switch] Setting up switch.esphome
2019-05-21 23:10:23 INFO (MainThread) [homeassistant.components.switch] Setting up switch.esphome
2019-05-21 23:10:23 INFO (MainThread) [homeassistant.components.switch] Setting up switch.esphome
2019-05-21 23:10:25 INFO (MainThread) [homeassistant.setup] Setup of domain binary_sensor took 21.8 seconds.
2019-05-21 23:10:25 INFO (MainThread) [homeassistant.components.binary_sensor] Setting up binary_sensor.esphome
2019-05-21 23:10:25 INFO (MainThread) [homeassistant.components.binary_sensor] Setting up binary_sensor.esphome
2019-05-21 23:10:25 INFO (MainThread) [homeassistant.components.binary_sensor] Setting up binary_sensor.esphome
2019-05-21 23:10:25 INFO (MainThread) [homeassistant.components.binary_sensor] Setting up binary_sensor.octoprint
2019-05-21 23:10:26 WARNING (MainThread) [homeassistant.components.camera] Setup of platform onvif is taking over 10 seconds.
2019-05-21 23:10:33 INFO (MainThread) [homeassistant.setup] Setup of domain sensor took 20.4 seconds.
2019-05-21 23:10:33 INFO (MainThread) [homeassistant.components.sensor] Setting up sensor.esphome
2019-05-21 23:10:33 INFO (MainThread) [homeassistant.components.sensor] Setting up sensor.esphome
2019-05-21 23:10:33 INFO (MainThread) [homeassistant.components.sensor] Setting up sensor.esphome
2019-05-21 23:10:33 INFO (MainThread) [homeassistant.components.sensor] Setting up sensor.upnp
2019-05-21 23:10:33 INFO (MainThread) [homeassistant.components.sensor] Setting up sensor.speedtestdotnet
2019-05-21 23:10:33 INFO (MainThread) [homeassistant.components.sensor] Setting up sensor.octoprint
2019-05-21 23:10:40 INFO (MainThread) [homeassistant.setup] Setup of domain camera took 28.8 seconds.
2019-05-21 23:10:40 INFO (MainThread) [homeassistant.components.camera] Setting up camera.esphome
2019-05-21 23:10:40 INFO (MainThread) [homeassistant.components.camera] Setting up camera.esphome
2019-05-21 23:10:40 INFO (MainThread) [homeassistant.components.camera] Setting up camera.esphome
2019-05-21 23:10:41 INFO (MainThread) [homeassistant.components.esphome] Successfully connected to x
2019-05-21 23:10:41 INFO (MainThread) [homeassistant.components.esphome] Successfully connected to x
2019-05-21 23:10:43 WARNING (MainThread) [homeassistant.components.sensor] Setup of platform octoprint is taking over 10 seconds.
2019-05-21 23:10:44 INFO (MainThread) [homeassistant.components.esphome] Can't connect to ESPHome API for x: Error connecting to ('x', 6053): [Errno 113] Connect call failed ('x', 6053)
2019-05-21 23:10:44 INFO (MainThread) [homeassistant.components.esphome] Trying to reconnect in 2 seconds

As I understand, main functionality is up - the core can communicate with my ESPHome devices, cameras etc, but no UI. And I don't see anything helpful in this log.
Should I try some debug settings for logger? But I don't know which ones, setting up debug for entire logger will generate very large file.

Also I just updated to latest 0.93.1 and I see no success with bluetooth in new version either, even I see messages like 'Setting up frontend' and 'Setup of domain frontend took..'.

ss -ntl|grep 8123

.. returns nothing.

Also I compared log file of normal startup and personally see the only difference like:

INFO (MainThread) [homeassistant.setup] Setup of domain device_tracker took 60.1 seconds.
INFO (MainThread) [homeassistant.setup] Setting up mobile_app
INFO (MainThread) [homeassistant.setup] Setup of domain mobile_app took 0.0 seconds.
INFO (MainThread) [homeassistant.components.notify] Setting up notify.mobile_app
INFO (MainThread) [homeassistant.setup] Setting up default_config
INFO (MainThread) [homeassistant.setup] Setup of domain default_config took 0.0 seconds.
INFO (MainThread) [homeassistant.setup] Setting up owntracks
INFO (MainThread) [homeassistant.setup] Setup of domain owntracks took 0.0 seconds.
INFO (MainThread) [homeassistant.components.device_tracker] Setting up device_tracker.owntracks

So.. any ideas would be really helpful!
Thanks!

sergeolkhovik picture sergeolkhovik on 21 May 2019

Yes, you are right, I checked all paired [homeassistant.setup] log, the only orphan log is 

2019-05-21 23:10:20 INFO (MainThread) [homeassistant.setup] Setting up device_tracker

There should be a paired Setup of domain device_tracker took nn seconds log. If that log was not displayed that means one of your device_tracker platform setup blocked the start up process.

awarecan picture awarecan on 21 May 2019

So.. how can I debug this? Any ideas? Try with something like

logger:
   default: info
   #default: debug
   logs:
     homeassistant.components.bluetooth_tracker: debug

?

sergeolkhovik picture sergeolkhovik on 23 May 2019

Well, I tried both homeassistant.components.bluetooth_tracker and homeassistant.components.device_tracker set to debug, and I see nothing new in the log.
I checked /srv/homeassistant/lib/python3.5/site-packages/homeassistant/components/bluetooth_tracker/device_tracker.py file and I see it has only 2 calls to logger with debug level and those will happen on new device descovery etc, nothing related to HA initialization.
What I can do else?

sergeolkhovik picture sergeolkhovik on 23 May 2019
👍1

Had the same problem, disabling bluetooth_tracker solved it. Later I re-enabled it, but deleted almost all of the entries in known_devices.yaml and now it works. It seems that home-assistant fails to parse an entity (or entities) in the known devices, but doesn't log it correctly so that I can find out which one

pgilad picture pgilad on 11 Jun 2019

I updated to latest 0.94.1, commented out BT devices in known_devices.yaml, have 2 like this:

bt_xxxx:
  hide_if_away: false
  icon:
  mac: BT_F4:F5:DB:XX:XX:XX
  name: Mi Phone
  picture:
  track: true

and that didn't help. UI isn't loaded.
Have no more ideas why. Don't want to touch other devices - some of them are already in use.
What could be done else?

sergeolkhovik picture sergeolkhovik on 13 Jun 2019
👍1

I have the same issue. If I disable bluetooth tracker I get the web UI.
I renamed known_devices.yaml to let home-assistant recreate.
When re-enabling bluetooth tracker still get no UI.
No BT_devices are added when the file is recreated.
Bluetooth LE Tracker does not cause the issue

dicko72 picture dicko72 on 28 Jun 2019

Any update on this one? With Google home BT presence not working due to Google API changes, would be nice if this one was resolved.

dicko72 picture dicko72 on 7 Aug 2019
👍2

This is still an issue in Home Assistant version 0.100.3. Is there any way to get more logging info from the bluetooth tracker to gain some insight why it blocks HA boot?

Elmardus picture Elmardus on 28 Oct 2019

I've looked into this a bit further by copying the bluetooth_tracker component into the _custom_components_ folder, and adding debug logging to the device_tracker.py file.

The startup script manages to call the function discover_devices(). This then calls the function bluetooth.discover_devices() from the PyBluez library, with the following function call:

result = bluetooth.discover_devices( duration=8, lookup_names=True, flush_cache=True, lookup_class=False, device_id=device_id, )

This function hangs and never returns. I haven't yet managed to figure out why, since I'm not really sure of any way to debug it except for adding debug logging lines. Anybody who has some ideas?

Elmardus picture Elmardus on 11 Nov 2019

@Elmardus Python is a bit of a mystery to me. However I'm happy to be a tester if you need anything like that. 馃榾

dicko72 picture dicko72 on 11 Nov 2019

I have the same problem on 0.102.3. It seems to be not directly dependant on HASS version, as it does not work now on 0.101.3 either. However it used to work on 0.101.3 and just stopped working... Seems to be related to deeper Bluetooth layers. btmon seems to work fine...

dmak picture dmak on 27 Nov 2019

I have a similar problem (with 0.105.2) where startup takes 2-3 minutes (and during that time the web UI doesn't respond). I can turn on debugging and see all of the other components initialize and startup asynchronously but it seems the last thing to finish is the bluetooth tracker scanning for known devices. I never see a "setup of domain bluetooth_tracker" message, just the HA initialized one. Here's a snippet:

2020-02-21 12:52:31 INFO (SyncWorker_3) [homeassistant.loader] Loaded bluetooth_tracker from homeassistant.components.bluetooth_tracker
2020-02-21 12:52:31 DEBUG (MainThread) [homeassistant.components.bluetooth_tracker.device_tracker] Tracking new devices is set to True
2020-02-21 12:52:31 INFO (MainThread) [homeassistant.setup] Setting up camera
2020-02-21 12:52:31 INFO (MainThread) [homeassistant.setup] Setup of domain timer took 1.6 seconds.

... I left in some other initialization debugging to show other things are interleaving  ...

2020-02-21 12:52:31 INFO (MainThread) [homeassistant.setup] Setup of domain input_boolean took 1.4 seconds.
2020-02-21 12:52:31 DEBUG (MainThread) [homeassistant.components.bluetooth_tracker.device_tracker] Performing Bluetooth devices discovery and update
2020-02-21 12:52:40 INFO (Wemo HTTP Thread) [pywemo.subscribe] Received event from <WeMo Switch "Living Room">(10.0.1.151) - BinaryState 0
2020-02-21 12:52:40 INFO (Wemo HTTP Thread) [homeassistant.components.wemo.switch] Subscription update for Living Room
2020-02-21 12:52:40 INFO (Wemo HTTP Thread) [pywemo.subscribe] Received event from <WeMo Dimmer "Outdoor Lower Patio">(10.0.1.13) - BinaryState 0
2020-02-21 12:52:43 DEBUG (SyncWorker_6) [homeassistant.components.bluetooth_tracker.device_tracker] Bluetooth devices discovered = 1
2020-02-21 12:52:43 DEBUG (SyncWorker_5) [homeassistant.components.bluetooth_tracker.device_tracker] Scanning 34:AB:37:90:00:00
2020-02-21 12:52:48 DEBUG (SyncWorker_0) [homeassistant.components.bluetooth_tracker.device_tracker] Scanning 90:C7:D8:30:00:00

 .... everything from this point is sequential from the log, no more line trimming...

2020-02-21 12:52:49 INFO (SyncWorker_5) [pychromecast] Querying device status
2020-02-21 12:52:53 DEBUG (SyncWorker_7) [homeassistant.components.bluetooth_tracker.device_tracker] Scanning C4:2C:03:B9:00:00 ... MAC address anonymized ...
2020-02-21 12:52:58 DEBUG (SyncWorker_3) [homeassistant.components.bluetooth_tracker.device_tracker] Scanning E8:07:BF:41:00:00
2020-02-21 12:53:04 DEBUG (SyncWorker_4) [homeassistant.components.bluetooth_tracker.device_tracker] Scanning C0:28:8D:ED:00:00
2020-02-21 12:53:09 DEBUG (SyncWorker_2) [homeassistant.components.bluetooth_tracker.device_tracker] Scanning 40:83:DE:03:00:00
2020-02-21 12:53:14 DEBUG (SyncWorker_5) [homeassistant.components.bluetooth_tracker.device_tracker] Scanning C4:9D:ED:8E:00:00
2020-02-21 12:53:19 DEBUG (SyncWorker_1) [homeassistant.components.bluetooth_tracker.device_tracker] Scanning 40:4E:36:B9:00:00
2020-02-21 12:53:20 DEBUG (SyncWorker_6) [homeassistant.components.bluetooth_tracker.device_tracker] Scanning F8:E9:4E:F2:00:00
2020-02-21 12:53:25 DEBUG (SyncWorker_8) [homeassistant.components.bluetooth_tracker.device_tracker] Scanning 08:EB:ED:6C:00:00
2020-02-21 12:53:30 DEBUG (SyncWorker_9) [homeassistant.components.bluetooth_tracker.device_tracker] Scanning 00:23:01:05:00:00
2020-02-21 12:53:35 DEBUG (SyncWorker_0) [homeassistant.components.bluetooth_tracker.device_tracker] Scanning 3C:28:6D:DC:00:00
2020-02-21 12:53:41 DEBUG (SyncWorker_7) [homeassistant.components.bluetooth_tracker.device_tracker] Scanning 78:CA:39:CA:00:00
2020-02-21 12:53:41 DEBUG (SyncWorker_3) [homeassistant.components.bluetooth_tracker.device_tracker] Scanning BC:A9:20:8E:00:00
2020-02-21 12:53:46 DEBUG (SyncWorker_4) [homeassistant.components.bluetooth_tracker.device_tracker] Scanning D8:76:0A:00:00:00
2020-02-21 12:53:52 DEBUG (SyncWorker_2) [homeassistant.components.bluetooth_tracker.device_tracker] Scanning 74:81:14:A2:00:00
2020-02-21 12:53:57 DEBUG (SyncWorker_5) [homeassistant.components.bluetooth_tracker.device_tracker] Scanning 08:D4:6A:3C:00:00
2020-02-21 12:54:02 DEBUG (SyncWorker_1) [homeassistant.components.bluetooth_tracker.device_tracker] Scanning 90:2E:1C:4E:00:00
2020-02-21 12:54:07 DEBUG (SyncWorker_6) [homeassistant.components.bluetooth_tracker.device_tracker] Scanning 98:5F:D3:55:00:00
2020-02-21 12:54:12 DEBUG (SyncWorker_8) [homeassistant.components.bluetooth_tracker.device_tracker] Scanning 4C:74:BF:97:00:00
2020-02-21 12:54:17 INFO (MainThread) [homeassistant.bootstrap] Home Assistant initialized in 108.09s

It looks like some work was done recently to make that component asynchronous, but HA still waits for it to complete fully before starting up. Mine completes, it just waits to scan for a bunch of offline devices. It would be great if that were faster or truly asynchronous -- why wait for a bunch of devices that aren't going to be online?

Maybe the right change to request is not make the querying block the rest of startup, similar to how wemo and other trackers work? I'm not familiar enough with HA development to do that (yet).

trombonekenny picture trombonekenny on 21 Feb 2020

Referring to some of the comments at the bottom of this PR https://github.com/home-assistant/home-assistant/pull/26614

trombonekenny picture trombonekenny on 21 Feb 2020

There hasn't been any activity on this issue recently. Due to the high number of incoming GitHub notifications, we have to clean some of the old issues, as many of them have already been resolved with the latest updates.
Please make sure to update to the latest Home Assistant version and check if that solves the issue. Let us know if that works for you by adding a comment 馃憤
This issue now has been marked as stale and will be closed if no further activity occurs. Thank you for your contributions.

stale[bot] picture stale[bot] on 22 May 2020

I have enabled bluetooth_tracker and I already observed for HASS v0.109.3 when it does not start.

# journalctl -u homeassistant.service | egrep '(Home Assistant initialized|Starting Home Assistant)' | less
systemd[1]: Starting Home Assistant...
hass[3937]: 2020-05-27 01:57:30 INFO (MainThread) [homeassistant.bootstrap] Home Assistant initialized in 18.68s
hass[3937]: 2020-05-27 01:57:30 INFO (MainThread) [homeassistant.core] Starting Home Assistant
systemd[1]: Starting Home Assistant...
hass[16401]: 2020-05-27 16:26:13 INFO (MainThread) [homeassistant.bootstrap] Home Assistant initialized in 21.66s
hass[16401]: 2020-05-27 16:26:13 INFO (MainThread) [homeassistant.core] Starting Home Assistant
systemd[1]: Starting Home Assistant...
^^^ problem ^^^
systemd[1]: Starting Home Assistant...
^^^ problem ^^^
systemd[1]: Starting Home Assistant...
^^^ I have disabled bluetooth_tracker and it started OK
hass[25270]: 2020-05-28 01:59:51 INFO (MainThread) [homeassistant.bootstrap] Home Assistant initialized in 18.54s
hass[25270]: 2020-05-28 01:59:51 INFO (MainThread) [homeassistant.core] Starting Home Assistant
dmak picture dmak on 28 May 2020

There hasn't been any activity on this issue recently. Due to the high number of incoming GitHub notifications, we have to clean some of the old issues, as many of them have already been resolved with the latest updates.
Please make sure to update to the latest Home Assistant version and check if that solves the issue. Let us know if that works for you by adding a comment 馃憤
This issue now has been marked as stale and will be closed if no further activity occurs. Thank you for your contributions.

stale[bot] picture stale[bot] on 29 Aug 2020

HASS v0.111 allows UI to start despite from failing integration but this does not solve the problem.

dmak picture dmak on 31 Aug 2020
Was this page helpful?
0 / 5 - 0 ratings

Related issues

bdraco picture bdraco  路  3Comments
coolriku picture coolriku  路  3Comments
sh0rez picture sh0rez  路  3Comments
Elmardus picture Elmardus  路  3Comments
sogeniusio picture sogeniusio  路  3Comments