0.111.0b0 Logger Levels Initially Ignored

[mynameisdaniel32]

The problem

Maybe an inevitable side effect of having everything start up together and faster (which is great!) but now getting logs flooded with INFO events on each startup until logger is started up, despite having my default set to WARN. Example below.

Environment

• Home Assistant Core release with the issue: 0.111.0b0
• Last working Home Assistant Core release (if known): 0.110.4
• Operating environment (Home Assistant/Supervised/Docker/venv): venv
• Integration causing this issue: Logger
• Link to integration documentation on our website:

Problem-relevant configuration.yaml

logger:
  default: warn
  logs:
    homeassistant.components.command_line.switch: fatal

Traceback/Error logs

2020-06-04 09:23:11 INFO (MainThread) [homeassistant.bootstrap] Config directory: /home/homeassistant/.homeassistant
2020-06-04 09:23:14 INFO (SyncWorker_4) [homeassistant.loader] Loaded apple_tv from custom_components.apple_tv
2020-06-04 09:23:14 INFO (SyncWorker_2) [homeassistant.loader] Loaded deepstack_object from custom_components.deepstack_object
2020-06-04 09:23:14 INFO (SyncWorker_1) [homeassistant.loader] Loaded plex_recently_added from custom_components.plex_recently_added
2020-06-04 09:23:14 INFO (SyncWorker_2) [homeassistant.loader] Loaded browser_mod from custom_components.browser_mod
2020-06-04 09:23:14 INFO (SyncWorker_0) [homeassistant.loader] Loaded hacs from custom_components.hacs
2020-06-04 09:23:14 INFO (SyncWorker_1) [homeassistant.loader] Loaded bom_forecast from custom_components.bom_forecast
2020-06-04 09:23:14 INFO (SyncWorker_4) [homeassistant.loader] Loaded persistent_notification from homeassistant.components.persistent_notification
2020-06-04 09:23:14 INFO (SyncWorker_3) [homeassistant.loader] Loaded homeassistant from homeassistant.components.homeassistant
2020-06-04 09:23:14 INFO (MainThread) [homeassistant.setup] Setting up persistent_notification
2020-06-04 09:23:14 INFO (MainThread) [homeassistant.setup] Setting up homeassistant
2020-06-04 09:23:14 INFO (MainThread) [homeassistant.setup] Setup of domain persistent_notification took 0.0 seconds.
2020-06-04 09:23:14 INFO (MainThread) [homeassistant.setup] Setup of domain homeassistant took 0.0 seconds.
2020-06-04 09:23:14 INFO (SyncWorker_0) [homeassistant.loader] Loaded binary_sensor from homeassistant.components.binary_sensor
2020-06-04 09:23:14 WARNING (MainThread) [homeassistant.loader] You are using a custom integration for browser_mod 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-04 09:23:14 INFO (SyncWorker_15) [homeassistant.loader] Loaded websocket_api from homeassistant.components.websocket_api
2020-06-04 09:23:14 INFO (SyncWorker_1) [homeassistant.loader] Loaded cert_expiry from homeassistant.components.cert_expiry
2020-06-04 09:23:14 INFO (SyncWorker_6) [homeassistant.loader] Loaded logger from homeassistant.components.logger
2020-06-04 09:23:14 INFO (SyncWorker_19) [homeassistant.loader] Loaded automation from homeassistant.components.automation
2020-06-04 09:23:14 INFO (SyncWorker_4) [homeassistant.loader] Loaded esphome from homeassistant.components.esphome
2020-06-04 09:23:14 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-04 09:23:14 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-04 09:23:14 INFO (SyncWorker_3) [homeassistant.loader] Loaded mqtt from homeassistant.components.mqtt
2020-06-04 09:23:14 INFO (SyncWorker_3) [homeassistant.loader] Loaded panel_iframe from homeassistant.components.panel_iframe
2020-06-04 09:23:14 INFO (SyncWorker_3) [homeassistant.loader] Loaded weather from homeassistant.components.weather
2020-06-04 09:23:14 INFO (SyncWorker_5) [homeassistant.loader] Loaded remote from homeassistant.components.remote
2020-06-04 09:23:14 INFO (SyncWorker_5) [homeassistant.loader] Loaded lovelace from homeassistant.components.lovelace
2020-06-04 09:23:14 INFO (SyncWorker_5) [homeassistant.loader] Loaded influxdb from homeassistant.components.influxdb
2020-06-04 09:23:14 INFO (SyncWorker_5) [homeassistant.loader] Loaded sensor from homeassistant.components.sensor
2020-06-04 09:23:14 INFO (SyncWorker_12) [homeassistant.loader] Loaded forked_daapd from homeassistant.components.forked_daapd
2020-06-04 09:23:14 INFO (SyncWorker_5) [homeassistant.loader] Loaded image_processing from homeassistant.components.image_processing
2020-06-04 09:23:14 INFO (SyncWorker_5) [homeassistant.loader] Loaded deconz from homeassistant.components.deconz
2020-06-04 09:23:14 INFO (SyncWorker_12) [homeassistant.loader] Loaded homekit from homeassistant.components.homekit
2020-06-04 09:23:14 INFO (SyncWorker_2) [homeassistant.loader] Loaded http from homeassistant.components.http
2020-06-04 09:23:14 INFO (SyncWorker_2) [homeassistant.loader] Loaded cover from homeassistant.components.cover
2020-06-04 09:23:14 INFO (SyncWorker_12) [homeassistant.loader] Loaded mobile_app from homeassistant.components.mobile_app
2020-06-04 09:23:14 INFO (SyncWorker_13) [homeassistant.loader] Loaded switch from homeassistant.components.switch
2020-06-04 09:23:14 INFO (SyncWorker_13) [homeassistant.loader] Loaded plex from homeassistant.components.plex
2020-06-04 09:23:14 INFO (SyncWorker_13) [homeassistant.loader] Loaded group from homeassistant.components.group
2020-06-04 09:23:14 INFO (SyncWorker_2) [homeassistant.loader] Loaded updater from homeassistant.components.updater
2020-06-04 09:23:14 INFO (SyncWorker_2) [homeassistant.loader] Loaded vacuum from homeassistant.components.vacuum
2020-06-04 09:23:14 INFO (SyncWorker_2) [homeassistant.loader] Loaded ios from homeassistant.components.ios
2020-06-04 09:23:14 INFO (SyncWorker_2) [homeassistant.loader] Loaded discovery from homeassistant.components.discovery
2020-06-04 09:23:14 INFO (SyncWorker_5) [homeassistant.loader] Loaded script from homeassistant.components.script
2020-06-04 09:23:14 INFO (SyncWorker_5) [homeassistant.loader] Loaded speedtestdotnet from homeassistant.components.speedtestdotnet
2020-06-04 09:23:14 INFO (SyncWorker_5) [homeassistant.loader] Loaded frontend from homeassistant.components.frontend
2020-06-04 09:23:14 INFO (SyncWorker_8) [homeassistant.loader] Loaded recorder from homeassistant.components.recorder
2020-06-04 09:23:14 INFO (SyncWorker_3) [homeassistant.loader] Loaded climate from homeassistant.components.climate
2020-06-04 09:23:14 INFO (SyncWorker_12) [homeassistant.loader] Loaded timer from homeassistant.components.timer
2020-06-04 09:23:14 INFO (SyncWorker_2) [homeassistant.loader] Loaded media_extractor from homeassistant.components.media_extractor
2020-06-04 09:23:14 INFO (SyncWorker_8) [homeassistant.loader] Loaded light from homeassistant.components.light
2020-06-04 09:23:14 INFO (SyncWorker_8) [homeassistant.loader] Loaded input_number from homeassistant.components.input_number
2020-06-04 09:23:14 INFO (SyncWorker_8) [homeassistant.loader] Loaded sonarr from homeassistant.components.sonarr
2020-06-04 09:23:14 INFO (SyncWorker_14) [homeassistant.loader] Loaded notify from homeassistant.components.notify
2020-06-04 09:23:14 INFO (SyncWorker_2) [homeassistant.loader] Loaded pi_hole from homeassistant.components.pi_hole
2020-06-04 09:23:14 INFO (SyncWorker_3) [homeassistant.loader] Loaded plant from homeassistant.components.plant
2020-06-04 09:23:14 INFO (SyncWorker_9) [homeassistant.loader] Loaded wled from homeassistant.components.wled
2020-06-04 09:23:14 INFO (SyncWorker_14) [homeassistant.loader] Loaded xiaomi_aqara from homeassistant.components.xiaomi_aqara
2020-06-04 09:23:14 INFO (SyncWorker_13) [homeassistant.loader] Loaded camera from homeassistant.components.camera
2020-06-04 09:23:14 INFO (SyncWorker_8) [homeassistant.loader] Loaded logbook from homeassistant.components.logbook
2020-06-04 09:23:14 INFO (SyncWorker_8) [homeassistant.loader] Loaded fan from homeassistant.components.fan
2020-06-04 09:23:14 INFO (SyncWorker_5) [homeassistant.loader] Loaded shopping_list from homeassistant.components.shopping_list
2020-06-04 09:23:14 INFO (SyncWorker_5) [homeassistant.loader] Loaded default_config from homeassistant.components.default_config
2020-06-04 09:23:14 INFO (SyncWorker_9) [homeassistant.loader] Loaded yeelight from homeassistant.components.yeelight
2020-06-04 09:23:14 INFO (SyncWorker_9) [homeassistant.loader] Loaded device_tracker from homeassistant.components.device_tracker
2020-06-04 09:23:14 INFO (SyncWorker_0) [homeassistant.loader] Loaded ffmpeg from homeassistant.components.ffmpeg
2020-06-04 09:23:14 INFO (SyncWorker_0) [homeassistant.loader] Loaded cloud from homeassistant.components.cloud
2020-06-04 09:23:14 INFO (SyncWorker_14) [homeassistant.loader] Loaded lifx from homeassistant.components.lifx
2020-06-04 09:23:14 INFO (SyncWorker_9) [homeassistant.loader] Loaded api from homeassistant.components.api
2020-06-04 09:23:14 INFO (SyncWorker_3) [homeassistant.loader] Loaded cast from homeassistant.components.cast
2020-06-04 09:23:14 INFO (SyncWorker_5) [homeassistant.loader] Loaded webhook from homeassistant.components.webhook
2020-06-04 09:23:14 INFO (SyncWorker_3) [homeassistant.loader] Loaded zone from homeassistant.components.zone
2020-06-04 09:23:14 INFO (SyncWorker_13) [homeassistant.loader] Loaded unifi from homeassistant.components.unifi
2020-06-04 09:23:14 INFO (SyncWorker_2) [homeassistant.loader] Loaded input_boolean from homeassistant.components.input_boolean
2020-06-04 09:23:14 INFO (SyncWorker_5) [homeassistant.loader] Loaded auth from homeassistant.components.auth
2020-06-04 09:23:14 INFO (SyncWorker_15) [homeassistant.loader] Loaded input_select from homeassistant.components.input_select
2020-06-04 09:23:14 INFO (SyncWorker_16) [homeassistant.loader] Loaded person from homeassistant.components.person
2020-06-04 09:23:14 INFO (SyncWorker_15) [homeassistant.loader] Loaded zeroconf from homeassistant.components.zeroconf
2020-06-04 09:23:14 INFO (SyncWorker_12) [homeassistant.loader] Loaded media_player from homeassistant.components.media_player
2020-06-04 09:23:14 INFO (SyncWorker_15) [homeassistant.loader] Loaded device_automation from homeassistant.components.device_automation
2020-06-04 09:23:14 INFO (SyncWorker_5) [homeassistant.loader] Loaded alexa from homeassistant.components.alexa
2020-06-04 09:23:14 INFO (SyncWorker_17) [homeassistant.loader] Loaded onboarding from homeassistant.components.onboarding
2020-06-04 09:23:14 INFO (SyncWorker_6) [homeassistant.loader] Loaded config from homeassistant.components.config
2020-06-04 09:23:14 INFO (SyncWorker_18) [homeassistant.loader] Loaded search from homeassistant.components.search
2020-06-04 09:23:14 INFO (SyncWorker_4) [homeassistant.loader] Loaded system_log from homeassistant.components.system_log
2020-06-04 09:23:14 INFO (SyncWorker_1) [homeassistant.loader] Loaded history from homeassistant.components.history
2020-06-04 09:23:14 INFO (SyncWorker_8) [homeassistant.loader] Loaded map from homeassistant.components.map
2020-06-04 09:23:14 INFO (SyncWorker_3) [homeassistant.loader] Loaded scene from homeassistant.components.scene
2020-06-04 09:23:14 INFO (SyncWorker_13) [homeassistant.loader] Loaded ssdp from homeassistant.components.ssdp
2020-06-04 09:23:14 INFO (SyncWorker_16) [homeassistant.loader] Loaded sun from homeassistant.components.sun
2020-06-04 09:23:14 INFO (SyncWorker_12) [homeassistant.loader] Loaded system_health from homeassistant.components.system_health
2020-06-04 09:23:14 INFO (SyncWorker_5) [homeassistant.loader] Loaded input_datetime from homeassistant.components.input_datetime
2020-06-04 09:23:14 INFO (SyncWorker_7) [homeassistant.loader] Loaded input_text from homeassistant.components.input_text
2020-06-04 09:23:14 INFO (MainThread) [homeassistant.bootstrap] Setting up {'logger', 'system_log'}
2020-06-04 09:23:14 INFO (MainThread) [homeassistant.setup] Setting up logger
2020-06-04 09:23:18 WARNING (MainThread) [homeassistant.loader] You are using a custom integration for bom_forecast 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-04 09:23:18 WARNING (MainThread) [homeassistant.loader] You are using a custom integration for plex_recently_added 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.

Additional information

[probot-home-assistant[bot]]

logger documentation logger source _{^{(message by IssueLinks)}}

[bdraco]

This is likely due to the fixes in #35633 that solved the lost log messages on startup and is unrelated to the earlier startup.

The logger configuration isn't activated until the logger integration is loaded so this seems like its working as designed but we shouldn't have info messages if verbose startup is off

[bdraco]

Actually with #35749 we can probably safely remove the respect_handler_level statement now

[bdraco]

diff --git a/homeassistant/util/logging.py b/homeassistant/util/logging.py
index 943e701a14..ed710f573f 100644
--- a/homeassistant/util/logging.py
+++ b/homeassistant/util/logging.py
@@ -77,9 +77,7 @@ def async_activate_log_queue_handler(hass: HomeAssistant) -> None:
         logging.root.removeHandler(handler)
         migrated_handlers.append(handler)

-    listener = logging.handlers.QueueListener(
-        simple_queue, *migrated_handlers, respect_handler_level=False
-    )
+    listener = logging.handlers.QueueListener(simple_queue, *migrated_handlers)

     listener.start()

This should fix it but it might cause a regression were we loose logger messages again. But that might not be an issue with the other fixes so more testing is needed

[bdraco]

Appears that the log message dropping problem doesn't regress and #35749 doesn't regress with respect_handler_level taken out.

I want to do some more testing to be sure before taking it out

[luca-angemi]

Tested your change on my system but logs are still filled with INFO events at startup.

[bdraco]

Tested your change on my system but logs are still filled with INFO events at startup.

Do you have verbose mode turned on?

[bdraco]

Looks like there is one more place we need to change

[luca-angemi]

if you mean my logger config, it's the following

logger:
  default: warning
  logs:
    homeassistant.loader: error
    homeassistant.components.tplink.switch: error
    homeassistant.components.media_player: error

[bdraco]

@luca-angemi Can you try the code in the linked PR #36444

[luca-angemi]

@bdraco tested!

All the INFO are gone. Only these types are remaining

2020-06-04 16:11:49 WARNING (MainThread) [homeassistant.loader] You are using a custom integration for hpprinter 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.

Is this because the loader logger component, loads later?

[bdraco]

Yes, that is expected.