Don't include log messages with log level "AUDIT" in regular service log file

CHANGELOG.rst

@@ -21,7 +21,16 @@ Added
 Changed
 ~~~~~~~
 
-* Changed the ``inquiries`` API path from ``/exp`` to ``/api/v1`` #4495
+* Changed the ``inquiries`` API path from ``/exp`` to ``/api/v1``. #4495
+* Update logging code so we exclude log messages with log level ``AUDIT`` from a default service
+  log file (e.g. ``st2api.log``). Log messages with level ``AUDIT`` are already logged in a
+  dedicated service audit log file (e.g. ``st2api.audit.log``) so there is no need for them to also
+  be duplicated and included in regular service log file.
+
+  NOTE: To aid with debugging, audit log messages are also included in a regular log file when log
+  level is set to ``DEBUG`` or ``system.debug`` config option is set to ``True``.
+
+  Reported by Nick Maludy. (improvement) #4538 #4502
 
 Fixed
 ~~~~~

st2common/st2common/log.py

@@ -46,6 +46,9 @@
     'ignore_statsd_log_messages'
 ]
 
+# NOTE: We set AUDIT to the highest log level which means AUDIT log messages will always be
+# included (e.g. also if log level is set to INFO). To avoid that, we need to explicitly filter
+# out AUDIT log level in service setup code.
 logging.AUDIT = logging.CRITICAL + 10
 logging.addLevelName(logging.AUDIT, 'AUDIT')
 

st2common/st2common/service_setup.py

@@ -22,6 +22,7 @@
 import os
 import sys
 import traceback
+import logging as stdlib_logging
 
 from oslo_config import cfg
 
@@ -35,6 +36,7 @@
 from st2common.models.utils.profiling import enable_profiling
 from st2common import triggers
 from st2common.rbac.migrations import run_all as run_all_rbac_migrations
+from st2common.logging.filters import LogLevelFilter
 
 # Note: This is here for backward compatibility.
 # Function has been moved in a standalone module to avoid expensive in-direct
@@ -112,6 +114,20 @@ def setup(service, config, setup_db=True, register_mq_exchanges=True,
         else:
             raise e
 
+    exclude_log_levels = [stdlib_logging.AUDIT]
+    handlers = stdlib_logging.getLoggerClass().manager.root.handlers
+
+    for handler in handlers:
+        # If log level is not set to DEBUG we filter out "AUDIT" log messages. This way we avoid
+        # duplicate "AUDIT" messages in production deployments where default service log level is
+        # set to "INFO" and we already log messages with level AUDIT to a special dedicated log
+        # file.
+        ignore_audit_log_messages = (handler.level >= stdlib_logging.INFO and
+                                     handler.level < stdlib_logging.AUDIT)
+        if not is_debug_enabled and ignore_audit_log_messages:
+            LOG.debug('Excluding log messages with level "AUDIT" for handler "%s"' % (handler))
+            handler.addFilter(LogLevelFilter(log_levels=exclude_log_levels))
+
     if not is_debug_enabled:
         # NOTE: statsd logger logs everything by default under INFO so we ignore those log
         # messages unless verbose / debug mode is used

st2common/tests/integration/test_service_setup_log_level_filtering.py

@@ -0,0 +1,123 @@
+# Licensed to the StackStorm, Inc ('StackStorm') under one or more
+# contributor license agreements.  See the NOTICE file distributed with
+# this work for additional information regarding copyright ownership.
+# The ASF licenses this file to You under the Apache License, Version 2.0
+# (the "License"); you may not use this file except in compliance with
+# the License.  You may obtain a copy of the License at
+#
+#     http://www.apache.org/licenses/LICENSE-2.0
+#
+# Unless required by applicable law or agreed to in writing, software
+# distributed under the License is distributed on an "AS IS" BASIS,
+# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+# See the License for the specific language governing permissions and
+# limitations under the License.
+
+from __future__ import absolute_import
+
+import os
+import sys
+import signal
+
+import eventlet
+from eventlet.green import subprocess
+
+from st2tests.base import IntegrationTestCase
+from st2tests.fixturesloader import get_fixtures_base_path
+
+__all__ = [
+    'ServiceSetupLogLevelFilteringTestCase'
+]
+
+BASE_DIR = os.path.dirname(os.path.abspath(__file__))
+
+FIXTURES_DIR = get_fixtures_base_path()
+
+ST2_CONFIG_INFO_LL_PATH = os.path.join(FIXTURES_DIR, 'conf/st2.tests.api.info_log_level.conf')
+ST2_CONFIG_INFO_LL_PATH = os.path.abspath(ST2_CONFIG_INFO_LL_PATH)
+
+ST2_CONFIG_DEBUG_LL_PATH = os.path.join(FIXTURES_DIR, 'conf/st2.tests.api.debug_log_level.conf')
+ST2_CONFIG_DEBUG_LL_PATH = os.path.abspath(ST2_CONFIG_DEBUG_LL_PATH)
+
+ST2_CONFIG_AUDIT_LL_PATH = os.path.join(FIXTURES_DIR, 'conf/st2.tests.api.audit_log_level.conf')
+ST2_CONFIG_AUDIT_LL_PATH = os.path.abspath(ST2_CONFIG_AUDIT_LL_PATH)
+
+ST2_CONFIG_SYSTEM_DEBUG_PATH = os.path.join(FIXTURES_DIR,
+                                            'conf/st2.tests.api.system_debug_true.conf')
+ST2_CONFIG_SYSTEM_DEBUG_PATH = os.path.abspath(ST2_CONFIG_SYSTEM_DEBUG_PATH)
+
+PYTHON_BINARY = sys.executable
+
+ST2API_BINARY = os.path.join(BASE_DIR, '../../../st2api/bin/st2api')
+ST2API_BINARY = os.path.abspath(ST2API_BINARY)
+
+CMD = [PYTHON_BINARY, ST2API_BINARY, '--config-file']
+
+
+class ServiceSetupLogLevelFilteringTestCase(IntegrationTestCase):
+    def test_audit_log_level_is_filtered_if_log_level_is_not_debug_or_audit(self):
+        # 1. INFO log level - audit messages should not be included
+        process = self._start_process(config_path=ST2_CONFIG_INFO_LL_PATH)
+        self.add_process(process=process)
+
+        # Give it some time to start up
+        eventlet.sleep(3)
+        process.send_signal(signal.SIGKILL)
+
+        # First 3 log lines are debug messages about the environment which are always logged
+        stdout = '\n'.join(process.stdout.read().decode('utf-8').split('\n')[3:])
+
+        self.assertTrue('INFO [-]' in stdout)
+        self.assertTrue('DEBUG [-]' not in stdout)
+        self.assertTrue('AUDIT [-]' not in stdout)
+
+        # 2. DEBUG log level - audit messages should be included
+        process = self._start_process(config_path=ST2_CONFIG_DEBUG_LL_PATH)
+        self.add_process(process=process)
+
+        # Give it some time to start up
+        eventlet.sleep(5)
+        process.send_signal(signal.SIGKILL)
+
+        # First 3 log lines are debug messages about the environment which are always logged
+        stdout = '\n'.join(process.stdout.read().decode('utf-8').split('\n')[3:])
+
+        self.assertTrue('INFO [-]' in stdout)
+        self.assertTrue('DEBUG [-]' in stdout)
+        self.assertTrue('AUDIT [-]' in stdout)
+
+        # 3. AUDIT log level - audit messages should be included
+        process = self._start_process(config_path=ST2_CONFIG_AUDIT_LL_PATH)
+        self.add_process(process=process)
+
+        # Give it some time to start up
+        eventlet.sleep(5)
+        process.send_signal(signal.SIGKILL)
+
+        # First 3 log lines are debug messages about the environment which are always logged
+        stdout = '\n'.join(process.stdout.read().decode('utf-8').split('\n')[3:])
+
+        self.assertTrue('INFO [-]' not in stdout)
+        self.assertTrue('DEBUG [-]' not in stdout)
+        self.assertTrue('AUDIT [-]' in stdout)
+
+        # 2. INFO log level but system.debug set to True
+        process = self._start_process(config_path=ST2_CONFIG_SYSTEM_DEBUG_PATH)
+        self.add_process(process=process)
+
+        # Give it some time to start up
+        eventlet.sleep(5)
+        process.send_signal(signal.SIGKILL)
+
+        # First 3 log lines are debug messages about the environment which are always logged
+        stdout = '\n'.join(process.stdout.read().decode('utf-8').split('\n')[3:])
+
+        self.assertTrue('INFO [-]' in stdout)
+        self.assertTrue('DEBUG [-]' in stdout)
+        self.assertTrue('AUDIT [-]' in stdout)
+
+    def _start_process(self, config_path):
+        cmd = CMD + [config_path]
+        process = subprocess.Popen(cmd, stdout=subprocess.PIPE, stderr=subprocess.PIPE,
+                                   shell=False, preexec_fn=os.setsid)
+        return process

st2tests/st2tests/fixtures/conf/logging.api.audit.conf

@@ -0,0 +1,44 @@
+[loggers]
+keys=root
+
+[handlers]
+keys=consoleHandler, fileHandler, auditHandler
+
+[formatters]
+keys=simpleConsoleFormatter, verboseConsoleFormatter, gelfFormatter
+
+[logger_root]
+level=AUDIT
+handlers=consoleHandler, fileHandler, auditHandler
+
+[handler_consoleHandler]
+class=StreamHandler
+level=AUDIT
+formatter=simpleConsoleFormatter
+args=(sys.stdout,)
+
+[handler_fileHandler]
+class=st2common.log.FormatNamedFileHandler
+level=AUDIT
+formatter=verboseConsoleFormatter
+args=("/tmp/st2api.{timestamp}.log",)
+
+[handler_auditHandler]
+class=st2common.log.FormatNamedFileHandler
+level=AUDIT
+formatter=gelfFormatter
+args=("/tmp/st2api.audit.{timestamp}.log",)
+
+[formatter_simpleConsoleFormatter]
+class=st2common.logging.formatters.ConsoleLogFormatter
+format=%(asctime)s %(levelname)s [-] %(message)s
+datefmt=
+
+[formatter_verboseConsoleFormatter]
+class=st2common.logging.formatters.ConsoleLogFormatter
+format=%(asctime)s %(thread)s %(levelname)s %(module)s [-] %(message)s
+datefmt=
+
+[formatter_gelfFormatter]
+class=st2common.logging.formatters.GelfLogFormatter
+format=%(message)s

st2tests/st2tests/fixtures/conf/logging.api.debug.conf

@@ -0,0 +1,44 @@
+[loggers]
+keys=root
+
+[handlers]
+keys=consoleHandler, fileHandler, auditHandler
+
+[formatters]
+keys=simpleConsoleFormatter, verboseConsoleFormatter, gelfFormatter
+
+[logger_root]
+level=DEBUG
+handlers=consoleHandler, fileHandler, auditHandler
+
+[handler_consoleHandler]
+class=StreamHandler
+level=DEBUG
+formatter=simpleConsoleFormatter
+args=(sys.stdout,)
+
+[handler_fileHandler]
+class=st2common.log.FormatNamedFileHandler
+level=DEBUG
+formatter=verboseConsoleFormatter
+args=("/tmp/st2api.{timestamp}.log",)
+
+[handler_auditHandler]
+class=st2common.log.FormatNamedFileHandler
+level=AUDIT
+formatter=gelfFormatter
+args=("/tmp/st2api.audit.{timestamp}.log",)
+
+[formatter_simpleConsoleFormatter]
+class=st2common.logging.formatters.ConsoleLogFormatter
+format=%(asctime)s %(levelname)s [-] %(message)s
+datefmt=
+
+[formatter_verboseConsoleFormatter]
+class=st2common.logging.formatters.ConsoleLogFormatter
+format=%(asctime)s %(thread)s %(levelname)s %(module)s [-] %(message)s
+datefmt=
+
+[formatter_gelfFormatter]
+class=st2common.logging.formatters.GelfLogFormatter
+format=%(message)s

st2tests/st2tests/fixtures/conf/logging.api.info.conf

@@ -0,0 +1,44 @@
+[loggers]
+keys=root
+
+[handlers]
+keys=consoleHandler, fileHandler, auditHandler
+
+[formatters]
+keys=simpleConsoleFormatter, verboseConsoleFormatter, gelfFormatter
+
+[logger_root]
+level=INFO
+handlers=consoleHandler, fileHandler, auditHandler
+
+[handler_consoleHandler]
+class=StreamHandler
+level=INFO
+formatter=simpleConsoleFormatter
+args=(sys.stdout,)
+
+[handler_fileHandler]
+class=st2common.log.FormatNamedFileHandler
+level=INFO
+formatter=verboseConsoleFormatter
+args=("/tmp/st2api.{timestamp}.log",)
+
+[handler_auditHandler]
+class=st2common.log.FormatNamedFileHandler
+level=AUDIT
+formatter=gelfFormatter
+args=("/tmp/st2api.audit.{timestamp}.log",)
+
+[formatter_simpleConsoleFormatter]
+class=st2common.logging.formatters.ConsoleLogFormatter
+format=%(asctime)s %(levelname)s [-] %(message)s
+datefmt=
+
+[formatter_verboseConsoleFormatter]
+class=st2common.logging.formatters.ConsoleLogFormatter
+format=%(asctime)s %(thread)s %(levelname)s %(module)s [-] %(message)s
+datefmt=
+
+[formatter_gelfFormatter]
+class=st2common.logging.formatters.GelfLogFormatter
+format=%(message)s