From 39dc5100da95724c5f817e978869135d0949e7e8 Mon Sep 17 00:00:00 2001 From: Joe Groocock Date: Mon, 20 Dec 2021 10:44:04 +0000 Subject: [PATCH 1/5] Log minion_id when it's available This should help disambiguate errors on busy masters when multiple minions are running jobs at once, especially in the case of errors whilst rendering pillars or bugs in custom code. Add JID/minion_id to console/file logs by default. Signed-off-by: Joe Groocock --- salt/_logging/__init__.py | 1 + salt/_logging/impl.py | 20 ++++++++++++++++++-- salt/config/__init__.py | 8 ++++++++ 3 files changed, 27 insertions(+), 2 deletions(-) diff --git a/salt/_logging/__init__.py b/salt/_logging/__init__.py index ea97b6ce9a84..7b177262e65d 100644 --- a/salt/_logging/__init__.py +++ b/salt/_logging/__init__.py @@ -15,6 +15,7 @@ DFLT_LOG_DATEFMT_LOGFILE, DFLT_LOG_FMT_CONSOLE, DFLT_LOG_FMT_JID, + DFLT_LOG_FMT_MINION_ID, DFLT_LOG_FMT_LOGFILE, LOG_COLORS, LOG_LEVELS, diff --git a/salt/_logging/impl.py b/salt/_logging/impl.py index c4de686f1976..48345e0e7306 100644 --- a/salt/_logging/impl.py +++ b/salt/_logging/impl.py @@ -100,10 +100,11 @@ # Default logging formatting options DFLT_LOG_FMT_JID = "[JID: %(jid)s]" +DFLT_LOG_FMT_MINION_ID = "[%(minion_id)s]" DFLT_LOG_DATEFMT = "%H:%M:%S" DFLT_LOG_DATEFMT_LOGFILE = "%Y-%m-%d %H:%M:%S" -DFLT_LOG_FMT_CONSOLE = "[%(levelname)-8s] %(message)s" -DFLT_LOG_FMT_LOGFILE = "%(asctime)s,%(msecs)03d [%(name)-17s:%(lineno)-4d][%(levelname)-8s][%(process)d] %(message)s" +DFLT_LOG_FMT_CONSOLE = "[%(levelname)-8s]%(jid)s%(minion_id)s %(message)s" +DFLT_LOG_FMT_LOGFILE = "%(asctime)s,%(msecs)03d [%(name)-17s:%(lineno)-4d][%(levelname)-8s][%(process)d]%(jid)s%(minion_id)s %(message)s" class SaltLogRecord(logging.LogRecord): @@ -262,6 +263,15 @@ def _log( if log_fmt_jid is not None: extra["log_fmt_jid"] = log_fmt_jid + current_minion_id = data.get("id", None) + log_fmt_minion_id = opts.get("log_fmt_minion_id", None) + + if current_minion_id is not None: + extra["minion_id"] = current_minion_id + + if log_fmt_minion_id is not None: + extra["log_fmt_minion_id"] = log_fmt_minion_id + # If both exc_info and exc_info_on_loglevel are both passed, let's fail if exc_info and exc_info_on_loglevel: raise LoggingRuntimeError( @@ -336,6 +346,11 @@ def makeRecord( log_fmt_jid = extra.pop("log_fmt_jid") jid = log_fmt_jid % {"jid": jid} + minion_id = extra.pop("minion_id", "") + if minion_id: + log_fmt_minion_id = extra.pop("log_fmt_minion_id") + minion_id = log_fmt_minion_id % {"minion_id": minion_id} + if not extra: # If nothing else is in extra, make it None extra = None @@ -385,6 +400,7 @@ def makeRecord( logrecord.exc_info_on_loglevel = exc_info_on_loglevel logrecord.jid = jid + logrecord.minion_id = minion_id return logrecord diff --git a/salt/config/__init__.py b/salt/config/__init__.py index f8aca19fa360..e55bca0c69ce 100644 --- a/salt/config/__init__.py +++ b/salt/config/__init__.py @@ -36,6 +36,7 @@ DFLT_LOG_DATEFMT_LOGFILE, DFLT_LOG_FMT_CONSOLE, DFLT_LOG_FMT_JID, + DFLT_LOG_FMT_MINION_ID, DFLT_LOG_FMT_LOGFILE, ) @@ -350,6 +351,10 @@ def _gather_buffer_space(): "log_fmt_console": str, # The format for a given log file "log_fmt_logfile": (tuple, str), + # The format for JIDs prior to formatting into log lines as %(jid)s + "log_fmt_jid": str, + # The format for minion_ids prior to formatting into log lines as %(jid)s + "log_fmt_minion_id": str, # A dictionary of logging levels "log_granular_levels": dict, # The maximum number of bytes a single log file may contain before @@ -1205,6 +1210,7 @@ def _gather_buffer_space(): "log_fmt_console": DFLT_LOG_FMT_CONSOLE, "log_fmt_logfile": DFLT_LOG_FMT_LOGFILE, "log_fmt_jid": DFLT_LOG_FMT_JID, + "log_fmt_minion_id": DFLT_LOG_FMT_MINION_ID, "log_granular_levels": {}, "log_rotate_max_bytes": 0, "log_rotate_backup_count": 0, @@ -1538,6 +1544,7 @@ def _gather_buffer_space(): "log_fmt_console": DFLT_LOG_FMT_CONSOLE, "log_fmt_logfile": DFLT_LOG_FMT_LOGFILE, "log_fmt_jid": DFLT_LOG_FMT_JID, + "log_fmt_minion_id": DFLT_LOG_FMT_MINION_ID, "log_granular_levels": {}, "log_rotate_max_bytes": 0, "log_rotate_backup_count": 0, @@ -1750,6 +1757,7 @@ def _gather_buffer_space(): "log_fmt_console": DFLT_LOG_FMT_CONSOLE, "log_fmt_logfile": DFLT_LOG_FMT_LOGFILE, "log_fmt_jid": DFLT_LOG_FMT_JID, + "log_fmt_minion_id": DFLT_LOG_FMT_MINION_ID, "log_granular_levels": {}, "log_rotate_max_bytes": 0, "log_rotate_backup_count": 0, From 231effa4ca8b89d4e1b7beae8188dcf02c5dda02 Mon Sep 17 00:00:00 2001 From: Barney Sowood Date: Thu, 16 Oct 2025 18:18:05 +0100 Subject: [PATCH 2/5] Update patch to add minion ID to master logs Updates the Cloudflare patch to add minion ID to master logs: * Reverts changes to the default log formats - as with the existing support for JID it should probably be up to user to set that rather than us changing the defaults and potentially causing breakage. * Updates code to get id and log_fmt_minion_id from context as data is no longer available in _log --- salt/_logging/__init__.py | 2 +- salt/_logging/impl.py | 23 +++++++++++++++-------- salt/config/__init__.py | 4 ++-- 3 files changed, 18 insertions(+), 11 deletions(-) diff --git a/salt/_logging/__init__.py b/salt/_logging/__init__.py index 7b177262e65d..a30dc0e2c571 100644 --- a/salt/_logging/__init__.py +++ b/salt/_logging/__init__.py @@ -15,8 +15,8 @@ DFLT_LOG_DATEFMT_LOGFILE, DFLT_LOG_FMT_CONSOLE, DFLT_LOG_FMT_JID, - DFLT_LOG_FMT_MINION_ID, DFLT_LOG_FMT_LOGFILE, + DFLT_LOG_FMT_MINION_ID, LOG_COLORS, LOG_LEVELS, LOG_VALUES_TO_LEVELS, diff --git a/salt/_logging/impl.py b/salt/_logging/impl.py index 48345e0e7306..7e744df8ec5e 100644 --- a/salt/_logging/impl.py +++ b/salt/_logging/impl.py @@ -1,8 +1,8 @@ """ - salt._logging.impl - ~~~~~~~~~~~~~~~~~~ +salt._logging.impl +~~~~~~~~~~~~~~~~~~ - Salt's logging implementation classes/functionality +Salt's logging implementation classes/functionality """ import atexit @@ -103,8 +103,8 @@ DFLT_LOG_FMT_MINION_ID = "[%(minion_id)s]" DFLT_LOG_DATEFMT = "%H:%M:%S" DFLT_LOG_DATEFMT_LOGFILE = "%Y-%m-%d %H:%M:%S" -DFLT_LOG_FMT_CONSOLE = "[%(levelname)-8s]%(jid)s%(minion_id)s %(message)s" -DFLT_LOG_FMT_LOGFILE = "%(asctime)s,%(msecs)03d [%(name)-17s:%(lineno)-4d][%(levelname)-8s][%(process)d]%(jid)s%(minion_id)s %(message)s" +DFLT_LOG_FMT_CONSOLE = "[%(levelname)-8s] %(message)s" +DFLT_LOG_FMT_LOGFILE = "%(asctime)s,%(msecs)03d [%(name)-17s:%(lineno)-4d][%(levelname)-8s][%(process)d] %(message)s" class SaltLogRecord(logging.LogRecord): @@ -257,15 +257,22 @@ def _log( .get("log_fmt_jid", None) ) + current_minion_id = ( + salt.utils.ctx.get_request_context().get("data", {}).get("id", None) + ) + + log_fmt_minion_id = ( + salt.utils.ctx.get_request_context() + .get("opts", {}) + .get("log_fmt_minion_id", None) + ) + if current_jid is not None: extra["jid"] = current_jid if log_fmt_jid is not None: extra["log_fmt_jid"] = log_fmt_jid - current_minion_id = data.get("id", None) - log_fmt_minion_id = opts.get("log_fmt_minion_id", None) - if current_minion_id is not None: extra["minion_id"] = current_minion_id diff --git a/salt/config/__init__.py b/salt/config/__init__.py index e55bca0c69ce..2c233a0d8835 100644 --- a/salt/config/__init__.py +++ b/salt/config/__init__.py @@ -36,8 +36,8 @@ DFLT_LOG_DATEFMT_LOGFILE, DFLT_LOG_FMT_CONSOLE, DFLT_LOG_FMT_JID, - DFLT_LOG_FMT_MINION_ID, DFLT_LOG_FMT_LOGFILE, + DFLT_LOG_FMT_MINION_ID, ) try: @@ -353,7 +353,7 @@ def _gather_buffer_space(): "log_fmt_logfile": (tuple, str), # The format for JIDs prior to formatting into log lines as %(jid)s "log_fmt_jid": str, - # The format for minion_ids prior to formatting into log lines as %(jid)s + # The format for minion_ids prior to formatting into log lines as %(minion_id)s "log_fmt_minion_id": str, # A dictionary of logging levels "log_granular_levels": dict, From 6aa393a700c337d675f4c7584c9ac57c80990c77 Mon Sep 17 00:00:00 2001 From: Barney Sowood Date: Fri, 17 Oct 2025 20:13:00 +0100 Subject: [PATCH 3/5] Add test and docs for jid and minion_id in logs Adds test for jid and minion_id in log format strings to ensure they appear correctly in the master log. Updates documentation to cover minion_id field and to recommend adding minion_id and jid to the log format config. --- doc/ref/configuration/logging/index.rst | 31 ++++- .../integration/_logging/test_jid_logging.py | 123 +++++++++++++----- 2 files changed, 122 insertions(+), 32 deletions(-) diff --git a/doc/ref/configuration/logging/index.rst b/doc/ref/configuration/logging/index.rst index d5d8f9cac6b7..08671ad3a1d4 100644 --- a/doc/ref/configuration/logging/index.rst +++ b/doc/ref/configuration/logging/index.rst @@ -184,6 +184,8 @@ formatting matches those used in :py:func:`time.strftime`. Default: ``[%(levelname)-8s] %(message)s`` +Recommended: ``[%(levelname)-8s]%(jid)s%(minion_id)s %(message)s`` + The format of the console logging messages. All standard python logging :py:class:`~logging.LogRecord` attributes can be used. Salt also provides these custom LogRecord attributes to colorize console log output: @@ -205,6 +207,11 @@ custom LogRecord attributes to colorize console log output: log_fmt_console: '[%(levelname)-8s] %(message)s' +.. note:: + + It is recommended to include ``%(jid)s`` and ``%(minion_id)s`` in the log + format to identify messages that relate to specific jobs and minions. + .. conf_log:: log_fmt_logfile ``log_fmt_logfile`` @@ -212,6 +219,8 @@ custom LogRecord attributes to colorize console log output: Default: ``%(asctime)s,%(msecs)03d [%(name)-17s][%(levelname)-8s] %(message)s`` +Recommended: ``%(asctime)s,%(msecs)03d [%(name)-17s:%(lineno)-4d][%(levelname)-8s][%(process)d]%(jid)s%(minion_id)s %(message)s`` + The format of the log file logging messages. All standard python logging :py:class:`~logging.LogRecord` attributes can be used. Salt also provides these custom LogRecord attributes that include padding and enclosing brackets @@ -227,6 +236,11 @@ these custom LogRecord attributes that include padding and enclosing brackets log_fmt_logfile: '%(asctime)s,%(msecs)03d [%(name)-17s][%(levelname)-8s] %(message)s' +.. note:: + + It is recommended to include ``%(jid)s`` and ``%(minion_id)s`` in the log + format to identify messages that relate to specific jobs and minions. + .. conf_log:: log_granular_levels ``log_granular_levels`` @@ -245,12 +259,11 @@ at the ``debug`` level, and sets a custom module to the ``all`` level: 'salt.modules': 'debug' 'salt.loader.saltmaster.ext.module.custom_module': 'all' -.. conf_log:: log_fmt_jid - You can determine what log call name to use here by adding ``%(module)s`` to the log format. Typically, it is the path of the file which generates the log without the trailing ``.py`` and with path separators replaced with ``.`` +.. conf_log:: log_fmt_jid ``log_fmt_jid`` ------------------- @@ -263,6 +276,20 @@ The format of the JID when added to logging messages. log_fmt_jid: '[JID: %(jid)s]' +.. conf_log:: log_fmt_minion_id + +``log_fmt_minion_id`` +---------------------- + +Default: ``[%(minion_id)s]`` + +The format of the minion ID when added to logging messages. + +.. code-block:: yaml + + log_fmt_minion_id: '[%(minion_id)s]' + + External Logging Handlers ------------------------- diff --git a/tests/pytests/integration/_logging/test_jid_logging.py b/tests/pytests/integration/_logging/test_jid_logging.py index 96ba76970535..2f71f4420310 100644 --- a/tests/pytests/integration/_logging/test_jid_logging.py +++ b/tests/pytests/integration/_logging/test_jid_logging.py @@ -1,32 +1,95 @@ -import logging +import pathlib + +import pytest +from saltfactories.utils import random_string from salt._logging import DFLT_LOG_FMT_JID -from tests.support.helpers import PRE_PYTEST_SKIP - -# Using the PRE_PYTEST_SKIP decorator since this test still fails on some platforms. -# Will investigate later. - - -@PRE_PYTEST_SKIP -def test_jid_in_logs(caplog, salt_call_cli): - """ - Test JID in log_format - """ - jid_formatted_str = DFLT_LOG_FMT_JID.split("%", maxsplit=1)[0] - formatter = logging.Formatter(fmt="%(jid)s %(message)s") - with caplog.at_level(logging.DEBUG): - previous_formatter = caplog.handler.formatter - try: - caplog.handler.setFormatter(formatter) - ret = salt_call_cli.run("test.ping") - assert ret.returncode == 0 - assert ret.data is True - - assert_error_msg = ( - "'{}' not found in log messages:\n>>>>>>>>>{}\n<<<<<<<<<".format( - jid_formatted_str, caplog.text - ) - ) - assert jid_formatted_str in caplog.text, assert_error_msg - finally: - caplog.handler.setFormatter(previous_formatter) +from salt._logging.impl import DFLT_LOG_FMT_MINION_ID + + +@pytest.fixture(scope="module") +def log_field_marker(): + """ + Marker to make identifying log fields possible without risk of matching + other instances of jid or minion_id in the log messages + """ + return "EXTRA_LOG_FIELD:" + + +@pytest.fixture(scope="module") +def logging_master(salt_master_factory, log_field_marker): + """ + A logging master fixture with JID and minion_id in log format + """ + log_format = ( + f"{log_field_marker}%(jid)s {log_field_marker}%(minion_id)s %(message)s" + ) + config_overrides = { + "log_level_logfile": "debug", + "log_fmt_logfile": log_format, + } + logging_master_factory = salt_master_factory.salt_master_daemon( + random_string("master-logging-"), + overrides=config_overrides, + extra_cli_arguments_after_first_start_failure=["--log-level=info"], + ) + with logging_master_factory.started(): + yield logging_master_factory + + +@pytest.fixture(scope="module") +def logging_master_logfile(logging_master): + """ + The logging master log file path + """ + assert logging_master.is_running() + return pathlib.Path(logging_master.config["log_file"]) + + +@pytest.fixture(scope="module") +def salt_cli(logging_master): + """ + A ``salt``` CLI fixture + """ + assert logging_master.is_running() + return logging_master.salt_cli(timeout=30) + + +@pytest.fixture(scope="module") +def logging_minion_id(logging_master): + """ + Random minion id for a salt-minion fixture + """ + return random_string("minion-logging-") + + +@pytest.fixture +def logging_minion(logging_master, logging_minion_id): + """ + A running salt-minion fixture connected to the logging master + """ + assert logging_master.is_running() + salt_minion_factory = logging_master.salt_minion_daemon( + logging_minion_id, + ) + with salt_minion_factory.started(): + yield salt_minion_factory + + +def test_jid_minion_id_in_logs( + logging_master_logfile, log_field_marker, salt_cli, logging_minion +): + """ + Test JID and minion_id appear in master log file in the expected format + """ + ret = salt_cli.run("test.ping", "-v", minion_tgt=logging_minion.id) + assert ret.returncode == 0 + assert "Executing job with jid" in ret.stdout + + jid_str = DFLT_LOG_FMT_JID % {"jid": ret.stdout.splitlines()[0].split()[-1]} + minion_id_str = DFLT_LOG_FMT_MINION_ID % {"minion_id": logging_minion.id} + + log_file_text = logging_master_logfile.read_text() + + assert f"{log_field_marker}{jid_str}" in log_file_text + assert f"{log_field_marker}{minion_id_str}" in log_file_text From a3aa1fd814d35ed79966ca4a8ea7f45bbd9e0492 Mon Sep 17 00:00:00 2001 From: Barney Sowood Date: Tue, 21 Oct 2025 08:14:23 +0100 Subject: [PATCH 4/5] Fix review issues Fixes review issues - Unecessary None default in .get() - Defining new fmt strings as optional --- salt/_logging/impl.py | 8 +++----- salt/config/__init__.py | 4 ++-- 2 files changed, 5 insertions(+), 7 deletions(-) diff --git a/salt/_logging/impl.py b/salt/_logging/impl.py index 7e744df8ec5e..8d0dc2a674f5 100644 --- a/salt/_logging/impl.py +++ b/salt/_logging/impl.py @@ -248,9 +248,7 @@ def _log( if extra is None: extra = {} - current_jid = ( - salt.utils.ctx.get_request_context().get("data", {}).get("jid", None) - ) + current_jid = salt.utils.ctx.get_request_context().get("data", {}).get("jid") log_fmt_jid = ( salt.utils.ctx.get_request_context() .get("opts", {}) @@ -258,13 +256,13 @@ def _log( ) current_minion_id = ( - salt.utils.ctx.get_request_context().get("data", {}).get("id", None) + salt.utils.ctx.get_request_context().get("data", {}).get("id") ) log_fmt_minion_id = ( salt.utils.ctx.get_request_context() .get("opts", {}) - .get("log_fmt_minion_id", None) + .get("log_fmt_minion_id") ) if current_jid is not None: diff --git a/salt/config/__init__.py b/salt/config/__init__.py index 2c233a0d8835..655fba93c001 100644 --- a/salt/config/__init__.py +++ b/salt/config/__init__.py @@ -352,9 +352,9 @@ def _gather_buffer_space(): # The format for a given log file "log_fmt_logfile": (tuple, str), # The format for JIDs prior to formatting into log lines as %(jid)s - "log_fmt_jid": str, + "log_fmt_jid": (type(None), str), # The format for minion_ids prior to formatting into log lines as %(minion_id)s - "log_fmt_minion_id": str, + "log_fmt_minion_id": (type(None), str), # A dictionary of logging levels "log_granular_levels": dict, # The maximum number of bytes a single log file may contain before From 7fd03577ac6f7889a8feb1a8a8e339efd9a7f4ed Mon Sep 17 00:00:00 2001 From: Barney Sowood Date: Tue, 21 Oct 2025 08:24:06 +0100 Subject: [PATCH 5/5] Add changelog --- changelog/68410.added.md | 3 +++ 1 file changed, 3 insertions(+) create mode 100644 changelog/68410.added.md diff --git a/changelog/68410.added.md b/changelog/68410.added.md new file mode 100644 index 000000000000..323288d157f6 --- /dev/null +++ b/changelog/68410.added.md @@ -0,0 +1,3 @@ +Add support for minion_id in log formats + +Adds support for including `%(minion_id)s` in log formats. Where id is available log messages on the master will have that data added to allow easier correlation of messages to minions.