diff --git a/changelog/68129.fixed.md b/changelog/68129.fixed.md new file mode 100644 index 000000000000..a3f4ac2eb5bf --- /dev/null +++ b/changelog/68129.fixed.md @@ -0,0 +1 @@ +Fixed ``ValueError: Formatting field not found in record: 'colorlevel'`` errors when ``log_fmt_console`` uses custom color attributes such as ``%(colorlevel)s`` or ``%(colormsg)s``. ``SaltLogRecord`` now always provides the ``color*`` attributes (uncolored by default) so that log records buffered by the temporary deferred stream handler can be formatted by a colorized console formatter once it is installed. diff --git a/salt/_logging/impl.py b/salt/_logging/impl.py index 8f6699f015e3..124633c0aa76 100644 --- a/salt/_logging/impl.py +++ b/salt/_logging/impl.py @@ -111,6 +111,19 @@ def __init__(self, *args, **kwargs): self.bracketname = f"[{str(self.name):<17}]" self.bracketlevel = f"[{str(self.levelname):<8}]" self.bracketprocess = f"[{str(self.process):>5}]" + # Always provide the color* attributes so that a formatter using + # ``%(colorlevel)s`` / ``%(colormsg)s`` / etc. does not blow up when + # formatting a record that was created before + # ``SaltColorLogRecord`` was installed as the active log record + # factory (for example, log records buffered by the temporary + # ``DeferredStreamHandler`` that are flushed once the console + # handler has been set up with a color format). These defaults + # have no color escapes; ``SaltColorLogRecord`` overrides them + # with colorized values. + self.colorname = self.bracketname + self.colorlevel = self.bracketlevel + self.colorprocess = self.bracketprocess + self.colormsg = self.getMessage() class SaltColorLogRecord(SaltLogRecord): diff --git a/tests/pytests/unit/_logging/test_impl.py b/tests/pytests/unit/_logging/test_impl.py new file mode 100644 index 000000000000..b4e5b6a28d17 --- /dev/null +++ b/tests/pytests/unit/_logging/test_impl.py @@ -0,0 +1,121 @@ +""" +Tests for salt._logging.impl. +""" + +import io +import logging + +import pytest + +from salt._logging.handlers import DeferredStreamHandler, StreamHandler +from salt._logging.impl import ( + SaltColorLogRecord, + SaltLogRecord, + get_log_record_factory, + set_log_record_factory, +) + + +@pytest.fixture +def restore_log_record_factory(): + original = get_log_record_factory() + try: + yield + finally: + set_log_record_factory(original) + + +@pytest.fixture +def restore_root_handlers(): + original = logging.root.handlers[:] + original_level = logging.root.level + try: + yield + finally: + logging.root.handlers[:] = original + logging.root.setLevel(original_level) + + +def test_salt_log_record_provides_color_attributes(): + """ + Regression test for #68129. + + ``SaltLogRecord`` must define the ``color*`` attributes so that a + formatter using ``%(colorlevel)s`` / ``%(colormsg)s`` / ``%(colorname)s`` + / ``%(colorprocess)s`` can format records produced by the plain + ``SaltLogRecord`` factory. Records that were buffered by the temporary + deferred stream handler before the color log record factory was + installed (for example, the records flushed by ``shutdown_temp_handler`` + once ``setup_console_handler`` has run with a color ``log_fmt_console``) + must not raise ``ValueError: Formatting field not found in record``. + """ + record = SaltLogRecord( + "salt.test", + logging.DEBUG, + __file__, + 1, + "hello %s", + ("world",), + None, + ) + assert hasattr(record, "colorname") + assert hasattr(record, "colorlevel") + assert hasattr(record, "colorprocess") + assert hasattr(record, "colormsg") + + fmt = logging.Formatter( + "%(colorlevel)s %(colorname)s %(colorprocess)s %(colormsg)s" + ) + # Must not raise -- the bug in #68129 manifested here as + # ``ValueError: Formatting field not found in record: 'colorlevel'``. + formatted = fmt.format(record) + assert "DEBUG" in formatted + assert "hello world" in formatted + + +def test_deferred_records_flushed_through_color_formatter( + restore_log_record_factory, restore_root_handlers +): + """ + Regression test for #68129. + + Simulate the real-world sequence: + + 1. The temporary ``DeferredStreamHandler`` buffers log records while + the plain ``SaltLogRecord`` factory is active. + 2. ``setup_console_handler`` installs ``SaltColorLogRecord`` as the + active factory and adds a console handler whose formatter uses + custom color attributes (``%(colorlevel)s``/``%(colormsg)s``). + 3. ``shutdown_temp_handler`` flushes the buffered records to the new + console handler via ``sync_with_handlers``. + + Before the fix, step 3 raised ``ValueError: Formatting field not found + in record: 'colorlevel'`` for every buffered record because those + records were ``SaltLogRecord`` instances created before the color + factory was installed. + """ + logging.root.handlers[:] = [] + logging.root.setLevel(logging.DEBUG) + + # Step 1: buffer a record using the plain factory. + set_log_record_factory(SaltLogRecord) + deferred = DeferredStreamHandler(io.StringIO()) + deferred.setLevel(logging.DEBUG) + deferred.setFormatter(logging.Formatter("%(message)s")) + logging.root.addHandler(deferred) + logger = logging.getLogger("test_68129_deferred") + logger.debug("buffered message") + + # Step 2: install the color factory and a color-format console handler. + set_log_record_factory(SaltColorLogRecord) + console_stream = io.StringIO() + console = StreamHandler(console_stream) + console.setLevel(logging.DEBUG) + console.setFormatter(logging.Formatter("%(colorlevel)s %(colormsg)s")) + logging.root.addHandler(console) + + # Step 3: sync the deferred handler's buffered records out. + deferred.sync_with_handlers(logging.root.handlers) + output = console_stream.getvalue() + assert "buffered message" in output + assert "DEBUG" in output