diff --git a/doc/ref/configuration/logging/index.rst b/doc/ref/configuration/logging/index.rst index 894fbc7353..fa1d87fbf3 100644 --- a/doc/ref/configuration/logging/index.rst +++ b/doc/ref/configuration/logging/index.rst @@ -238,6 +238,19 @@ 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 + +``log_fmt_jid`` +------------------- + +Default: ``[JID: %(jid)s]`` + +The format of the JID when added to logging messages. + +.. code-block:: yaml + + log_fmt_jid: '[JID: %(jid)s]' + External Logging Handlers ------------------------- diff --git a/doc/topics/releases/fluorine.rst b/doc/topics/releases/fluorine.rst index c26d08a46d..1c8a3d4150 100644 --- a/doc/topics/releases/fluorine.rst +++ b/doc/topics/releases/fluorine.rst @@ -873,3 +873,25 @@ for viewing minions, runners, and jobs as well as running execution modules and runners of a running Salt system through a REST API that returns JSON. See Salt-API_ documentation. .. _Salt-API: https://docs.saltstack.com/en/latest/topics/netapi/index.html + +Logging Changes +=============== + +Include Job ID (JID) in Minion and Master Logs +---------------------------------------------- + +The Job ID (JID) can now be optionally included in both the minion and master logs +by including ``jid`` in either the ``log_fmt_console`` or ``log_fmt_logfile`` +configuration option: + +.. code-block:: yaml + + log_fmt_console: "[%(levelname)-8s] %(jid)s %(message)s" + +The will cause the JID to be included in any log entries that are related to a +particular Salt job. The JID will be included using the default format, +``[JID: %(jid)s]`` but can be overriden with the ``log_fmt_jid`` configuration item. + +.. code-block:: yaml + + log_fmt_jid: "[JID: %(jid)s]" diff --git a/salt/config/__init__.py b/salt/config/__init__.py index 2458240753..76fbcdba11 100644 --- a/salt/config/__init__.py +++ b/salt/config/__init__.py @@ -53,6 +53,7 @@ _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_JID = "[JID: %(jid)s]" _DFLT_REFSPECS = ['+refs/heads/*:refs/remotes/origin/*', '+refs/tags/*:refs/tags/*'] DEFAULT_INTERVAL = 60 @@ -1381,6 +1382,7 @@ DEFAULT_MINION_OPTS = { 'log_datefmt_logfile': _DFLT_LOG_DATEFMT_LOGFILE, 'log_fmt_console': _DFLT_LOG_FMT_CONSOLE, 'log_fmt_logfile': _DFLT_LOG_FMT_LOGFILE, + 'log_fmt_jid': _DFLT_LOG_FMT_JID, 'log_granular_levels': {}, 'log_rotate_max_bytes': 0, 'log_rotate_backup_count': 0, @@ -1710,6 +1712,7 @@ DEFAULT_MASTER_OPTS = { 'log_datefmt_logfile': _DFLT_LOG_DATEFMT_LOGFILE, 'log_fmt_console': _DFLT_LOG_FMT_CONSOLE, 'log_fmt_logfile': _DFLT_LOG_FMT_LOGFILE, + 'log_fmt_jid': _DFLT_LOG_FMT_JID, 'log_granular_levels': {}, 'log_rotate_max_bytes': 0, 'log_rotate_backup_count': 0, @@ -1904,6 +1907,7 @@ DEFAULT_CLOUD_OPTS = { 'log_datefmt_logfile': _DFLT_LOG_DATEFMT_LOGFILE, 'log_fmt_console': _DFLT_LOG_FMT_CONSOLE, 'log_fmt_logfile': _DFLT_LOG_FMT_LOGFILE, + 'log_fmt_jid': _DFLT_LOG_FMT_JID, 'log_granular_levels': {}, 'log_rotate_max_bytes': 0, 'log_rotate_backup_count': 0, diff --git a/salt/log/setup.py b/salt/log/setup.py index 4c6d5dd8fd..f4e5f922c6 100644 --- a/salt/log/setup.py +++ b/salt/log/setup.py @@ -48,6 +48,7 @@ from salt.log.handlers import (TemporaryLoggingHandler, QueueHandler) from salt.log.mixins import LoggingMixInMeta, NewStyleClassMixIn +from salt.utils.ctx import RequestContext LOG_LEVELS = { 'all': logging.NOTSET, @@ -305,6 +306,18 @@ class SaltLoggingClass(six.with_metaclass(LoggingMixInMeta, LOGGING_LOGGER_CLASS def _log(self, level, msg, args, exc_info=None, extra=None, # pylint: disable=arguments-differ exc_info_on_loglevel=None): # If both exc_info and exc_info_on_loglevel are both passed, let's fail + if extra is None: + extra = {} + + current_jid = RequestContext.current.get('data', {}).get('jid', None) + log_fmt_jid = RequestContext.current.get('opts', {}).get('log_fmt_jid', 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 + if exc_info and exc_info_on_loglevel: raise RuntimeError( 'Only one of \'exc_info\' and \'exc_info_on_loglevel\' is ' @@ -335,6 +348,12 @@ class SaltLoggingClass(six.with_metaclass(LoggingMixInMeta, LOGGING_LOGGER_CLASS func=None, extra=None, sinfo=None): # Let's remove exc_info_on_loglevel from extra exc_info_on_loglevel = extra.pop('exc_info_on_loglevel') + + jid = extra.pop('jid', '') + if jid: + log_fmt_jid = extra.pop('log_fmt_jid') + jid = log_fmt_jid % {'jid': jid} + if not extra: # If nothing else is in extra, make it None extra = None @@ -393,6 +412,7 @@ class SaltLoggingClass(six.with_metaclass(LoggingMixInMeta, LOGGING_LOGGER_CLASS logrecord.exc_info_on_loglevel_formatted = None logrecord.exc_info_on_loglevel = exc_info_on_loglevel + logrecord.jid = jid return logrecord # pylint: enable=C0103 diff --git a/salt/master.py b/salt/master.py index 650dda3ead..dff9a27adf 100644 --- a/salt/master.py +++ b/salt/master.py @@ -8,6 +8,7 @@ involves preparing the three listeners and the workers needed by the master. from __future__ import absolute_import, with_statement, print_function, unicode_literals import copy import ctypes +import functools import os import re import sys @@ -90,6 +91,9 @@ try: except ImportError: HAS_HALITE = False +from tornado.stack_context import StackContext +from salt.utils.ctx import RequestContext + log = logging.getLogger(__name__) @@ -1106,7 +1110,15 @@ class MWorker(salt.utils.process.SignalHandlingMultiprocessingProcess): if self.opts['master_stats']: start = time.time() self.stats[cmd]['runs'] += 1 - ret = self.aes_funcs.run_func(data['cmd'], data) + + def run_func(data): + return self.aes_funcs.run_func(data['cmd'], data) + + with StackContext(functools.partial(RequestContext, + {'data': data, + 'opts': self.opts})): + ret = run_func(data) + if self.opts['master_stats']: self._post_stats(start, cmd) return ret diff --git a/salt/minion.py b/salt/minion.py index 67a213890f..bb3fd78a44 100644 --- a/salt/minion.py +++ b/salt/minion.py @@ -4,6 +4,7 @@ Routines to set up a minion ''' # Import python libs from __future__ import absolute_import, print_function, with_statement, unicode_literals +import functools import os import re import sys @@ -33,6 +34,8 @@ else: from salt.ext.six.moves import range from salt.utils.zeromq import zmq, ZMQDefaultLoop, install_zmq, ZMQ_VERSION_INFO +from salt.utils.ctx import RequestContext + # pylint: enable=no-name-in-module,redefined-builtin import tornado @@ -1541,11 +1544,16 @@ class Minion(MinionBase): get_proc_dir(opts['cachedir'], uid=uid) ) - with tornado.stack_context.StackContext(minion_instance.ctx): + def run_func(minion_instance, opts, data): if isinstance(data['fun'], tuple) or isinstance(data['fun'], list): - Minion._thread_multi_return(minion_instance, opts, data) + return Minion._thread_multi_return(minion_instance, opts, data) else: - Minion._thread_return(minion_instance, opts, data) + return Minion._thread_return(minion_instance, opts, data) + + with tornado.stack_context.StackContext(functools.partial(RequestContext, + {'data': data, 'opts': opts})): + with tornado.stack_context.StackContext(minion_instance.ctx): + run_func(minion_instance, opts, data) @classmethod def _thread_return(cls, minion_instance, opts, data): diff --git a/salt/utils/ctx.py b/salt/utils/ctx.py new file mode 100644 index 0000000000..6b772172a8 --- /dev/null +++ b/salt/utils/ctx.py @@ -0,0 +1,52 @@ +# -*- coding: utf-8 -*- + +# Import python libs +from __future__ import absolute_import, with_statement, print_function, unicode_literals +import threading + + +class ClassProperty(property): + ''' + Use a classmethod as a property + http://stackoverflow.com/a/1383402/1258307 + ''' + def __get__(self, cls, owner): + return self.fget.__get__(None, owner)() # pylint: disable=no-member + + +class RequestContext(object): + ''' + A context manager that saves some per-thread state globally. + Intended for use with Tornado's StackContext. + https://gist.github.com/simon-weber/7755289 + Simply import this class into any module and access the current request handler by this + class's class method property 'current'. If it returns None, there's no active request. + .. code:: python + from raas.utils.ctx import RequestContext + current_request_handler = RequestContext.current + ''' + + _state = threading.local() + _state.current_request = {} + + def __init__(self, current_request): + self._current_request = current_request + + @ClassProperty + @classmethod + def current(cls): + if not hasattr(cls._state, 'current_request'): + return {} + return cls._state.current_request + + def __enter__(self): + self._prev_request = self.__class__.current + self.__class__._state.current_request = self._current_request + + def __exit__(self, *exc): + self.__class__._state.current_request = self._prev_request + del self._prev_request + return False + + def __call__(self): + return self diff --git a/salt/utils/decorators/jinja.py b/salt/utils/decorators/jinja.py index f61efb2ac1..22d68369cf 100644 --- a/salt/utils/decorators/jinja.py +++ b/salt/utils/decorators/jinja.py @@ -5,7 +5,8 @@ Jinja-specific decorators from __future__ import absolute_import, print_function, unicode_literals # Import Python libs -import logging +# Ensure we're using the custom logging from Salt +import salt.log.setup as logging log = logging.getLogger(__name__) diff --git a/tests/integration/logging/__init__.py b/tests/integration/logging/__init__.py new file mode 100644 index 0000000000..40a96afc6f --- /dev/null +++ b/tests/integration/logging/__init__.py @@ -0,0 +1 @@ +# -*- coding: utf-8 -*- diff --git a/tests/integration/logging/test_jid_logging.py b/tests/integration/logging/test_jid_logging.py new file mode 100644 index 0000000000..fb08a3580e --- /dev/null +++ b/tests/integration/logging/test_jid_logging.py @@ -0,0 +1,34 @@ +# -*- coding: utf-8 -*- + +# Import Python libs +from __future__ import absolute_import, print_function, unicode_literals + +# Import Salt Testing libs +from tests.support.case import ModuleCase +from tests.support.unit import skipIf +from tests.support.helpers import TestsLoggingHandler + +import logging +import salt.ext.six as six + + +@skipIf(six.PY3, 'Runtest Log Hander Disabled for PY3, #41836') +class LoggingJIDsTest(ModuleCase): + ''' + Validate that JIDs appear in LOGs + ''' + def setUp(self): + ''' + Set up + ''' + log_format = '[%(levelname)-8s] %(jid)s %(message)s' + self.handler = TestsLoggingHandler(format=log_format, + level=logging.DEBUG) + + def test_jid_in_logs(self): + ''' + Test JID in log_format + ''' + with self.handler: + self.run_function('test.ping') + assert any('JID' in s for s in self.handler.messages) is True, 'JID not found in log messages' diff --git a/tests/runtests.py b/tests/runtests.py index dbd10340fa..a5626972ce 100755 --- a/tests/runtests.py +++ b/tests/runtests.py @@ -182,6 +182,9 @@ TEST_SUITES = { 'sdb': {'display_name': 'Sdb', 'path': 'integration/sdb'}, + 'logging': + {'display_name': 'Logging', + 'path': 'integration/logging'}, } @@ -513,6 +516,13 @@ class SaltTestsuiteParser(SaltCoverageTestingParser): default=False, help='Run scheduler integration tests' ) + self.test_selection_group.add_option( + '--logging', + dest='logging', + action='store_true', + default=False, + help='Run logging integration tests' + ) def validate_options(self): if self.options.cloud_provider or self.options.external_api: