Merge pull request #48660 from garethgreenaway/jids_in_logs

[develop] Adding jids in master & minion logs

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
 -------------------------
 

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]"

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,

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

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

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):

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

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__)
 

tests/integration/logging/__init__.py

@@ -0,0 +1 @@
+# -*- coding: utf-8 -*-

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'

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: