Define TRACE logging level

TRACE is a logging keyword that is understood by most logging
tools. OpenStack has repurposed this in the past to not be TRACE
logging but instead be used whenever a Stacktrace was dumped. This
was already fixed in:
I8c618e7b8523bcc0e19a9b77c4d2d5984369a04a

Now in this review, we are adding a new TRACE level set to an
integer halfway between DEBUG and NOTSET which is currently 5.

One can also use LOG.trace for deep tracing of their code as well.
To make it easy for end users to import the TRACE level, added
public constants for all the log levels from logging module. Several
projects import logging just for the constants, this will help
them as well.

Please see the logging guidelines for more info:
https://github.com/openstack/openstack-specs/blob/master/specs/log-guidelines.rst

Change-Id: Ica0e78da5a57c246b3b7499a6ce8c6f410cd6a80

oslo_log/handlers.py

@@ -69,6 +69,7 @@ class RFCSysLogHandler(logging.handlers.SysLogHandler):
         return msg
 
 _AUDIT = logging.INFO + 1
+_TRACE = 5
 
 
 if syslog is not None:
@@ -102,6 +103,7 @@ if syslog is not None:
 
 class ColorHandler(logging.StreamHandler):
     LEVEL_COLORS = {
+        _TRACE: '\033[00;35m',  # MAGENTA
         logging.DEBUG: '\033[00;32m',  # GREEN
         logging.INFO: '\033[00;36m',  # CYAN
         _AUDIT: '\033[01;36m',  # BOLD CYAN

oslo_log/log.py

@@ -51,6 +51,18 @@ from oslo_log import _options
 from oslo_log import formatters
 from oslo_log import handlers
 
+CRITICAL = logging.CRITICAL
+FATAL = logging.FATAL
+ERROR = logging.ERROR
+WARNING = logging.WARNING
+WARN = logging.WARNING
+INFO = logging.INFO
+DEBUG = logging.DEBUG
+NOTSET = logging.NOTSET
+TRACE = handlers._TRACE
+
+logging.addLevelName(TRACE, 'TRACE')
+
 
 def _get_log_file_path(conf, binary=None):
     logfile = conf.log_file
@@ -77,6 +89,9 @@ class BaseLoggerAdapter(logging.LoggerAdapter):
     def handlers(self):
         return self.logger.handlers
 
+    def trace(self, msg, *args, **kwargs):
+        self.log(TRACE, msg, *args, **kwargs)
+
     def isEnabledFor(self, level):
         if _PY26:
             # This method was added in python 2.7 (and it does the exact

oslo_log/tests/unit/test_log.py

@@ -242,27 +242,37 @@ class LogLevelTestCase(BaseTestCase):
         levels = self.CONF.default_log_levels
         levels.append("nova-test=INFO")
         levels.append("nova-not-debug=WARN")
-        levels.append("nova-below-debug=5")
+        levels.append("nova-below-debug=7")
+        levels.append("nova-trace=TRACE")
         self.config(default_log_levels=levels,
                     verbose=True)
         log.setup(self.CONF, 'testing')
         self.log = log.getLogger('nova-test')
         self.log_no_debug = log.getLogger('nova-not-debug')
         self.log_below_debug = log.getLogger('nova-below-debug')
+        self.log_trace = log.getLogger('nova-trace')
 
     def test_is_enabled_for(self):
         self.assertTrue(self.log.isEnabledFor(logging.INFO))
         self.assertFalse(self.log_no_debug.isEnabledFor(logging.DEBUG))
         self.assertTrue(self.log_below_debug.isEnabledFor(logging.DEBUG))
-        self.assertTrue(self.log_below_debug.isEnabledFor(5))
+        self.assertTrue(self.log_below_debug.isEnabledFor(7))
+        self.assertTrue(self.log_trace.isEnabledFor(log.TRACE))
 
     def test_has_level_from_flags(self):
         self.assertEqual(logging.INFO, self.log.logger.getEffectiveLevel())
 
+    def test_has_level_from_flags_for_trace(self):
+        self.assertEqual(log.TRACE, self.log_trace.logger.getEffectiveLevel())
+
     def test_child_log_has_level_of_parent_flag(self):
         l = log.getLogger('nova-test.foo')
         self.assertEqual(logging.INFO, l.logger.getEffectiveLevel())
 
+    def test_child_log_has_level_of_parent_flag_for_trace(self):
+        l = log.getLogger('nova-trace.foo')
+        self.assertEqual(log.TRACE, l.logger.getEffectiveLevel())
+
 
 class JSONFormatterTestCase(LogTestBase):
     def setUp(self):
@@ -546,6 +556,20 @@ class InstanceRecordTestCase(LogTestBase):
         self.assertEqual(infoexpected, self.stream.getvalue())
 
 
+class TraceLevelTestCase(LogTestBase):
+    def setUp(self):
+        super(TraceLevelTestCase, self).setUp()
+        self.config(logging_context_format_string="%(message)s")
+        self.mylog = log.getLogger()
+        self._add_handler_with_cleanup(self.mylog)
+        self._set_log_level_with_cleanup(self.mylog, log.TRACE)
+
+    def test_trace_log_msg(self):
+        ctxt = _fake_context()
+        self.mylog.trace("my trace message", context=ctxt)
+        self.assertEqual('my trace message\n', self.stream.getvalue())
+
+
 class DomainTestCase(LogTestBase):
     def setUp(self):
         super(DomainTestCase, self).setUp()