DEBUG logging enabled and cannot be disabled

[pjdubya]

The problem

Yesterday I was running 2023.11.3 with logger: enabled with default of info, and a few other specific services with debug enabled. The output was fairly minimal, as expected. Today after my container manager updated my HA to 2023.12.0 I've found that I have endless records pouring into my home-assistant.log, essentially all tagged as DEBUG, and from all kinds of services, both HA core and devices. Snippet of the log file is pasted below.

I've tried disabling logger completely in configuration.yaml and restarting HA, but even that isn't enough to stop the logging.

What version of Home Assistant Core has the issue?

2023.12.0

What was the last working version of Home Assistant Core?

2023.11.3

What type of installation are you running?

Home Assistant Container

Integration causing the issue

logger

Link to integration documentation on our website

https://www.home-assistant.io/integrations/logger/

Diagnostics information

No response

Example YAML snippet

logger is fully commented out in my configuration.yaml at this point and it is still outputting DEBUG data to the log

Anything in the logs that might be useful for us?

Snippet from my log (with a couple of pieces REDACTED)

2023-12-08 21:48:43.637 DEBUG (Recorder) [homeassistant.components.recorder.core] Processing task: CommitTask()
2023-12-08 21:48:43.638 DEBUG (Recorder) [homeassistant.components.recorder.pool.RecorderPool] Connection <sqlite3.Connection object at 0x7fa987b9de40> checked out from pool
2023-12-08 21:48:43.944 DEBUG (MainThread) [async_upnp_client.server] Sending SSDP packet, transport: None, socket: <socket.socket fd=54, family=2, type=2, proto=0, laddr=('0.0.0.0', 42527)>, target: ('REDACTED', 34278)
2023-12-08 21:48:44.211 DEBUG (Recorder) [homeassistant.components.recorder.pool.RecorderPool] Connection <sqlite3.Connection object at 0x7fa987b9de40> being returned to pool
2023-12-08 21:48:44.211 DEBUG (Recorder) [homeassistant.components.recorder.pool.RecorderPool] Connection <sqlite3.Connection object at 0x7fa987b9de40> rollback-on-return
2023-12-08 21:48:44.796 DEBUG (Thread-2 (_thread_main)) [roombapy.roomba] Received Roomba Data REDACTED: wifistat, b'{"state":{"reported":{"signal":{"rssi":-43,"snr":28}}}}'
2023-12-08 21:48:44.797 DEBUG (Thread-2 (_thread_main)) [roombapy.roomba] State updated to: Charging
2023-12-08 21:48:46.135 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] The current deadline value is 10 seconds.
2023-12-08 21:48:46.135 DEBUG (Thread-LeaseMaintainer) [google.cloud.pubsub_v1.subscriber._protocol.leaser] Snoozing lease management for 2.168300 seconds.

Additional information

No response

[home-assistant[bot]]

Hey there @home-assistant/core, mind taking a look at this issue as it has been labeled with an integration (logger) you are listed as a code owner for? Thanks!

Code owner commands

Code owners of `logger` can trigger bot actions by commenting: - `@home-assistant close` Closes the issue. - `@home-assistant rename Awesome new title` Renames the issue. - `@home-assistant reopen` Reopen the issue. - `@home-assistant unassign logger` Removes the current integration label and assignees on the issue, add the integration domain after the command. - `@home-assistant add-label needs-more-information` Add a label (needs-more-information, problem in dependency, problem in custom component) to the issue. - `@home-assistant remove-label needs-more-information` Remove a label (needs-more-information, problem in dependency, problem in custom component) on the issue.

_{^{(message by CodeOwnersMention)}}

---

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

[pjdubya]

I'm not sure if this is related to 2023.12 or not because I see now that it's tied to a python script that contains an instantiation of a logging object. I don't yet understand why the presence of a logger inside a pyscript script is somehow both tied to the main home-assistant.log file and enabling logging for all other services at the level I've set the script's logging to, but this is clearly the culprit. I therefore don't know if there's any actual bug in the HA logger.

In case anyone would like to try to reproduce this, I believe this should be sufficient to trigger it:

• enable pyscript
• create a test.py file with

import logging
log = logging.getLogger()
log.setLevel(logging.DEBUG)

Running the script does not seem to be necessary. pyscript tests scripts as they're saved, so it's possible that that's enough to cause the logging to be enabled. Deleting those lines and then saving the script again causes the logging to stop again. I'll need to investigate further why these are linked but for now it's probably safe to disregard this ticket.

[pjdubya]

FYI that part of the confusion in diagnosing this is that it seem that HA's "quick reload" to just reload the updated YAML doesn't seem to work for the logger. I've disabled the pyscript I mentioned above, then in the main configuration.yaml I set

logger: default: info

Then restarted HA to be in a fully known good state, and that worked as expected. Then I updated that default to debug, then a "quick reload" but the logs after that point don't contain DEBUG outputs, just INFO and higher. Selecting "Restart Home Assistant" though causes the DEBUG change to take effect. I would have expected that the "quick reload" would be sufficient to cause the previous HA logger to be stopped and restarted with the revised configuration. Let me know if you'd like me to open a fresh issue about that problem.

[MartinHjelmare]

The script is changing the logging level of the root logger. You should avoid using the root logger and use a logger that is specific to the module or package you're writing instead.

The logger integration doesn't support quick reload of YAML. It has services to change the logging level if you want to avoid restarting.