-
Notifications
You must be signed in to change notification settings - Fork 881
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
Cleanup Logging Configuration #4435
Cleanup Logging Configuration #4435
Conversation
3fed267
to
8a2c08e
Compare
2118764
to
7362945
Compare
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Great refactor overall. I left some comments inline.
One more possible improvement (which we can probably do later since this PR is already huge): most of the camelCase functions in log.py don't have many call sites and could be converted to snake_case.
Also, since we plan on keeping all the commits, for ease of later review, please add new commits that can later be squashed/rebased rather amending any current ones.
@@ -130,10 +130,6 @@ def setupLogging(cfg=None): | |||
setupBasicLogging() | |||
|
|||
|
|||
def getLogger(name="cloudinit"): |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
getLogger
will return the "cloudinit" logger if nothing is passed to it. That was getting reset in resetLogging()
, but now there is nothing resetting it.
Was that an oversight, or by "unused" (in the commit message) do you mean that the "cloudinit" logger has not been used yet? If so, lets add info to the commit message explaining that.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
do you mean that the "cloudinit" logger has not been used yet?
Correct
If so, lets add info to the commit message explaining that.
Will do
@@ -16,17 +16,13 @@ | |||
import os | |||
import sys | |||
import time | |||
|
|||
# Default basic format | |||
DEF_CON_FORMAT = "%(asctime)s - %(filename)s[%(levelname)s]: %(message)s" |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Even if only used twice, this definition seems more like a magic value, and we don't want one changing without the other, so I think it makes sense to keep it defined here. Though we could maybe rename to DEFAULT_LOG_FORMAT
or something.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Agreed and fixed
cloudinit/log.py
Outdated
# The default configuration includes an attempt at using /dev/log, | ||
# followed up by writing to a file. /dev/log will not exist in | ||
# very early boot, so an exception on that is expected. | ||
with suppress(Exception): |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
I know the old version used Exception
, but any chance we can add a more specific exception here?
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
I was thinking about that too. FileNotFound
looks to be the exception described in the comments:
>>> import logging.config
>>> logging.config.fileConfig("/tasoeinf")
Traceback (most recent call last):
File "<stdin>", line 1, in <module>
File "/usr/lib/python3.11/logging/config.py", line 65, in fileConfig
raise FileNotFoundError(f"{fname} doesn't exist")
FileNotFoundError: /tasoeinf doesn't exist
@@ -136,4 +128,33 @@ def resetLogging(): | |||
log.addHandler(logging.NullHandler()) | |||
|
|||
|
|||
resetLogging() | |||
def setup_backup_logging(): |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Do we have tests for the old patcher behavior? If not, let's make sure this is tested and works as expected.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Indirectly, yes.
Some of our unit tests depend on caplog picking up stderr output which formerly got set up by patcher.patch_logging()
, and now gets set up by setup_backup_logging()
.
This can be seen by running unit tests against main with the following diff:
git diff | cat
diff --git a/cloudinit/cmd/main.py b/cloudinit/cmd/main.py
index 21e994776..963b395c6 100755
--- a/cloudinit/cmd/main.py
+++ b/cloudinit/cmd/main.py
@@ -26,7 +26,6 @@ from typing import Tuple
from cloudinit import patcher
from cloudinit.config.modules import Modules
-patcher.patch_logging()
from cloudinit.config.schema import validate_cloudconfig_schema
from cloudinit import log as logging
Which yields:
================================================================================== short test summary info ===================================================================================
FAILED tests/unittests/config/test_schema.py::TestMain::test_main_absent_config_file - assert 'Error: Config file NOT_A_FILE does not exist\n' == '--- Logging error ---\nTraceback (most recent call last):\n File "/usr/lib/python3.11/logging/__init__.py", line 1113, in em...
FAILED tests/unittests/config/test_schema.py::TestMain::test_main_system_userdata_requires_root - assert 'Error:\nUnable to read system userdata or vendordata as non-root user. Try using sudo.\n' == '--- Logging error ---\nTraceback (most recent call last):\n File "/usr/lib/python3...
FAILED tests/unittests/config/test_schema.py::TestHandleSchemaArgs::test_handle_schema_args_annotate_deprecated_config[True-#cloud-config\npackages:\n- htop\napt_update: true # D1\napt_upgrade: true # D2\napt_reboot_if_required: true # D3\n\n# Deprecations: -------------\n# D1: Default: ``false``. Deprecated in version 22.2. Use ``package_update`` instead.\n# D2: Default: ``false``. Deprecated in version 22.2. Use ``package_upgrade`` instead.\n# D3: Default: ``false``. Deprecated in version 22.2. Use ``package_reboot_if_required`` instead.\n\nValid cloud-config: {cfg_file}\n] - assert not '--- Logging error ---\nTraceback (most recent call last):\n File "/usr/lib/python3.11/logging/__init__.py", line 1113, in emit\n stream.write(msg + self.terminator)\nVal...
FAILED tests/unittests/config/test_schema.py::TestHandleSchemaArgs::test_handle_schema_args_annotate_deprecated_config[False-Cloud config schema deprecations: apt_reboot_if_required: Default: ``false``. Deprecated in version 22.2. Use ``package_reboot_if_required`` instead., apt_update: Default: ``false``. Deprecated in version 22.2. Use ``package_update`` instead., apt_upgrade: Default: ``false``. Deprecated in version 22.2. Use ``package_upgrade`` instead. Valid cloud-config: {cfg_file}\n] - assert not '--- Logging error ---\nTraceback (most recent call last):\n File "/usr/lib/python3.11/logging/__init__.py", line 1113, in emit\n stream.write(msg + self.terminator)\nVal...
FAILED tests/unittests/config/test_schema.py::TestHandleSchemaArgs::test_handle_schema_args_jinja_with_errors[root_annotate_unique_errors_no_exception] - assert '' == '--- Logging error ---\nTraceback (most recent call last):\n File "/usr/lib/python3.11/logging/__init__.py", line 1113, in emit\n stream.write(msg + self.terminator)\nV...
FAILED tests/unittests/config/test_schema.py::TestHandleSchemaArgs::test_handle_schema_args_jinja_with_errors[root_no_annotate_exception_with_unique_errors] - assert "Error: Cloud config schema errors: hostname: 123 is not of type 'string'\n\nError: Invalid cloud-config schema: user-data\n\n" == '--- Logging error ---\nTraceback (most recent ...
================================================ 6 failed, 4870 passed, 4 skipped, 1 deselected, 1 xfailed, 281 warnings in 122.15s (0:02:02) ================================================
I would expect these to also fail against this branch too if this implementation was incorrect.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Just to be sure, I double checked this on an instance.
# first create an instance named me, then
lxc storage create small btrfs
lxc storage set small volume.size=100KiB
lxc storage volume create small smallvol
lxc storage volume attach small smallvol me /small
lxc shell me
cloud-init clean --logs
touch /small/cloud-init.log
cd /var/log
rm cloud-init.log
ln -s /small/cloud-init.log
cloud-init init --local
# keep going through services until you see fallback logs show up
Small snippet:
root@me:/var/log# cloud-init init
Cloud-init v. 23.3.1 running 'init' at Wed, 20 Sep 2023 13:37:12 +0000. Up 179.86 seconds.
ci-info: +++++++++++++++++++++++++++++++++++++++++++++Net device info++++++++++++++++++++++++++++++++++++++++++++++
ci-info: +--------+------+-------------------------------------------+---------------+--------+-------------------+
ci-info: | Device | Up | Address | Mask | Scope | Hw-Address |
ci-info: +--------+------+-------------------------------------------+---------------+--------+-------------------+
ci-info: | eth0 | True | 10.197.203.247 | 255.255.255.0 | global | 00:16:3e:df:1d:bf |
ci-info: | eth0 | True | fd42:eaab:10a1:ad48:216:3eff:fedf:1dbf/64 | . | global | 00:16:3e:df:1d:bf |
ci-info: | eth0 | True | fe80::216:3eff:fedf:1dbf/64 | . | link | 00:16:3e:df:1d:bf |
ci-info: | lo | True | 127.0.0.1 | 255.0.0.0 | host | . |
ci-info: | lo | True | ::1/128 | . | host | . |
ci-info: +--------+------+-------------------------------------------+---------------+--------+-------------------+
ci-info: +++++++++++++++++++++++++++++++Route IPv4 info+++++++++++++++++++++++++++++++
ci-info: +-------+--------------+--------------+-----------------+-----------+-------+
ci-info: | Route | Destination | Gateway | Genmask | Interface | Flags |
ci-info: +-------+--------------+--------------+-----------------+-----------+-------+
ci-info: | 0 | 0.0.0.0 | 10.197.203.1 | 0.0.0.0 | eth0 | UG |
ci-info: | 1 | 10.197.203.0 | 0.0.0.0 | 255.255.255.0 | eth0 | U |
ci-info: | 2 | 10.197.203.1 | 0.0.0.0 | 255.255.255.255 | eth0 | UH |
ci-info: +-------+--------------+--------------+-----------------+-----------+-------+
ci-info: ++++++++++++++++++++++++++++++++++Route IPv6 info++++++++++++++++++++++++++++++++++
ci-info: +-------+--------------------------+--------------------------+-----------+-------+
ci-info: | Route | Destination | Gateway | Interface | Flags |
ci-info: +-------+--------------------------+--------------------------+-----------+-------+
ci-info: | 0 | fd42:eaab:10a1:ad48::/64 | :: | eth0 | U |
ci-info: | 1 | fe80::/64 | :: | eth0 | U |
ci-info: | 2 | ::/0 | fe80::216:3eff:fede:84e6 | eth0 | UGe |
ci-info: | 4 | local | :: | eth0 | U |
ci-info: | 5 | local | :: | eth0 | U |
ci-info: | 6 | multicast | :: | eth0 | U |
ci-info: +-------+--------------------------+--------------------------+-----------+-------+
FALLBACK: 2023-09-20 13:37:13,110 - util.py[DEBUG]: Attempting to load yaml from string of length 18 with allowed root types (<class 'dict'>,)
FALLBACK: 2023-09-20 13:37:13,112 - cloud_config.py[DEBUG]: Merging by applying [('dict', ['replace']), ('list', []), ('str', [])]
FALLBACK: 2023-09-20 13:37:13,114 - __init__.py[DEBUG]: Calling handler CloudConfigPartHandler: [['text/cloud-config', 'text/cloud-config-jsonp']] (__end__, None, 3) with frequency once-per-instance
FALLBACK: 2023-09-20 13:37:13,116 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/me/vendor-cloud-config.txt - wb: [600] 53 bytes
FALLBACK: 2023-09-20 13:37:13,118 - __init__.py[DEBUG]: Calling handler ShellScriptPartHandler: [['text/x-shellscript']] (__end__, None, 2) with frequency once-per-instance
FALLBACK: 2023-09-20 13:37:13,119 - __init__.py[DEBUG]: Calling handler ShellScriptByFreqPartHandler: [['text/x-shellscript-per-boot']] (__end__, None, 2) with frequency once-per-instance
FALLBACK: 2023-09-20 13:37:13,120 - __init__.py[DEBUG]: Calling handler ShellScriptByFreqPartHandler: [['text/x-shellscript-per-instance']] (__end__, None, 2) with frequency once-per-instance
FALLBACK: 2023-09-20 13:37:13,122 - __init__.py[DEBUG]: Calling handler ShellScriptByFreqPartHandler: [['text/x-shellscript-per-once']] (__end__, None, 2) with frequency once-per-instance
FALLBACK: 2023-09-20 13:37:13,123 - __init__.py[DEBUG]: Calling handler BootHookPartHandler: [['text/cloud-boothook']] (__end__, None, 2) with frequency once-per-instance
FALLBACK: 2023-09-20 13:37:13,125 - __init__.py[DEBUG]: Calling handler JinjaTemplatePartHandler: [['text/jinja2']] (__end__, None, 3) with frequency once-per-instance
FALLBACK: 2023-09-20 13:37:13,126 - handlers.py[DEBUG]: finish: init-network/consume-vendor-data: SUCCESS: reading and applying vendor-data
FALLBACK: 2023-09-20 13:37:13,128 - handlers.py[DEBUG]: start: init-network/consume-vendor-data2: reading and applying vendor-data2
FALLBACK: 2023-09-20 13:37:13,130 - stages.py[DEBUG]: no vendordata2 from datasource
FALLBACK: 2023-09-20 13:37:13,131 - handlers.py[DEBUG]: finish: init-network/consume-vendor-data2: SUCCESS: reading and applying vendor-data2
FALLBACK: 2023-09-20 13:37:13,133 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg (quiet=False)
FALLBACK: 2023-09-20 13:37:13,134 - util.py[DEBUG]: Read 3758 bytes from /etc/cloud/cloud.cfg
Also saw these fallback logs get redirected to cloud-init-output.log
+1
logging.Handler.handleError = handleError | ||
|
||
|
||
def configure_root_logger(): |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
This is WAY nicer than before 😃
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
😃
@@ -16,7 +17,7 @@ | |||
from cloudinit.sources import DataSource, DataSourceNotFoundException | |||
from cloudinit.stages import Init | |||
|
|||
LOG = log.getLogger(__name__) | |||
LOG = logging.getLogger(__name__) |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Missed removing the log
import on this one
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Nope! log
gets used on line 250.
@@ -4,6 +4,7 @@ | |||
"""Debug network config format conversions.""" | |||
import argparse | |||
import json | |||
import logging |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
If this is the only change, did we just have broken code in this module previously?
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Nice catch, it looks like the rest of this change slipped into a separate commit. I'll fix that.
Thanks for the review @TheRealFalcon. I believe that I've addressed all of your comments.
I was thinking about that too. I'll include a separate PR for that.
I added the logging exception change as a separate logical commit, and the rest were included using |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
LGTM!
I'll leave it to you to merge. Let's wait until after we're sure how we want to handle these sorts of commits in the ChangeLog.
Thanks for the review. Per our discussion out of band, I'll update the commit messages to include the PR number and then (after autosquashing the fixups), I'll do a rebase and merge. |
cloudinit.log: Use more appropriate exception (canonical#4435) cloud-init's logging code has for a long time caught and ignored a bare Exception. Use a more specific exception for the expected case that this handles.
cloudinit.log: Don't configure NullHandler (canonical#4435) NullHandler hasn't been required to prevent the logging warnings since commit 5a27d4018 landed in Python, which was released in Python 3.2.
cloudinit.log: Remove unused getLogger wrapper (canonical#4435) This wrapper provided a default logger with name "cloudinit" when called without arguments. This behavior was never used and can safely be removed.
Simplify root logger configuration (canonical#4435) The root logger gets configured at various stages of cloudinit execution. Some changes occur while importing cloudinit.log, which causes side effects in any project using cloudinit as a library (Ubuntu Pro, etc). These modifications do not require change during runtime and can take place as an early setup task in cloudinit.cmd.main::main(). Simplify this code, relocate logger configuration code to a function in cloudinit.log, set the callsite in cloudinit.cmd.main::main(). Also add context to logging configuration code.
cloudinit.log: Remove unnecessary module function and variables (canonical#4435)
cloudinit.log: Standardize use of cloudinit's logging module (canonical#4435) cloud-init's log module implements a wrapper for logging.getLogger, however this module is not consistently used across the codebase. Furthermore most of these invocations choose to alias cloudinit.log module to logging. Shadowing a standard library module, and especially doing so inconsistently across the codebase, is not best practice. Since this wrapper doesn't add value, replace all invocations with the standard library call. Also standardize logger names to use logging.getLogger(__name__).
Remove unnecessary logging wrapper in Cloud class (canonical#4435) Cloud.cycle_logging() is only called once in the codebase, and its only benefit is turning two function calls into a single call. Remove it.
Cloud.cycle_logging() is only called once in the codebase, and its only benefit is turning two function calls into a single call. Remove it.
…al#4435) cloud-init's log module implements a wrapper for logging.getLogger, however this module is not consistently used across the codebase. Furthermore most of these invocations choose to alias cloudinit.log module to logging. Shadowing a standard library module, and especially doing so inconsistently across the codebase, is not best practice. Since this wrapper doesn't add value, replace all invocations with the standard library call. Also standardize logger names to use logging.getLogger(__name__).
This wrapper provided a default logger with name "cloudinit" when called without arguments. This behavior was never used and can safely be removed.
As a reference for others, here is an unsquashed copy of this branch before autosquashing Then steps taken:
|
The root logger gets configured at various stages of cloudinit execution. Some changes occur while importing cloudinit.log, which causes side effects in any project using cloudinit as a library (Ubuntu Pro, etc). These modifications do not require change during runtime and can take place as an early setup task in cloudinit.cmd.main::main(). Simplify this code, relocate logger configuration code to a function in cloudinit.log, set the callsite in cloudinit.cmd.main::main(). Also add context to logging configuration code.
NullHandler hasn't been required to prevent the logging warnings since commit 5a27d4018 landed in Python, which was released in Python 3.2.
7487342
to
3a9c178
Compare
cloud-init's logging code has for a long time caught and ignored a bare Exception. Use a more specific exception for the expected case that this handles.
@TheRealFalcon I botched one of the |
The root logger gets configured at various stages of cloudinit execution. Some changes occur while importing cloudinit.log, which causes side effects in any project using cloudinit as a library (Ubuntu Pro, etc). These modifications do not require change during runtime and can take place as an early setup task in cloudinit.cmd.main::main(). Simplify this code, relocate logger configuration code to a function in cloudinit.log, set the callsite in cloudinit.cmd.main::main(). Also add context to logging configuration code.
NullHandler hasn't been required to prevent the logging warnings since commit 5a27d4018 landed in Python, which was released in Python 3.2.
cloud-init's logging code has for a long time caught and ignored a bare Exception. Use a more specific exception for the expected case that this handles.
4adaa91
to
b13037c
Compare
Cloud.cycle_logging() is only called once in the codebase, and its only benefit is turning two function calls into a single call. Remove it.
cloud-init's log module implements a wrapper for logging.getLogger, however this module is not consistently used across the codebase. Furthermore most of these invocations choose to alias cloudinit.log module to logging. Shadowing a standard library module, and especially doing so inconsistently across the codebase, is not best practice. Since this wrapper doesn't add value, replace all invocations with the standard library call. Also standardize logger names to use logging.getLogger(__name__).
This wrapper provided a default logger with name "cloudinit" when called without arguments. This behavior was never used and can safely be removed.
The root logger gets configured at various stages of cloudinit execution. Some changes occur while importing cloudinit.log, which causes side effects in any project using cloudinit as a library (Ubuntu Pro, etc). These modifications do not require change during runtime and can take place as an early setup task in cloudinit.cmd.main::main(). Simplify this code, relocate logger configuration code to a function in cloudinit.log, set the callsite in cloudinit.cmd.main::main(). Also add context to logging configuration code.
NullHandler hasn't been required to prevent the logging warnings since commit 5a27d4018 landed in Python, which was released in Python 3.2.
Please merge as individual commits.
Additional Context
cloud-init's log module implements a wrapper for logging.getLogger,
however this module is not consistently used across the codebase. Furthermore
most of these invocations choose to alias cloudinit.log module to logging.
Shadowing a standard library module, and especially doing so inconsistently
across the codebase, is not best practice. Since this wrapper doesn't add
value, replace all invocations with the standard library call.
Delete unnecessary log module wrapper.
Also standardize logger names to use
logging.getLogger(__name__)
.