Always ignore kombu library "heartbeat_tick" debug log messages

CHANGELOG.rst

@@ -47,6 +47,13 @@ Changed
   #4481 (bug fix)
 * Add retries to scheduler to handle temporary hiccup in DB connection. Refactor scheduler
   service to return proper exit code when there is a failure. #4539 (bug fix)
+* Update service setup code so we always ignore ``kombu`` library ``heartbeat_tick`` debug log
+  messages.
+
+  Previously if ``DEBUG`` log level was set in service logging config file, but ``--debug``
+  service CLI flag / ``system.debug = True`` config option was not used, those messages were
+  still logged which caused a lot of noise which made actual useful log messages hard to find.
+  (improvement) #4557
 
 Fixed
 ~~~~~

st2common/st2common/logging/misc.py

@@ -22,8 +22,11 @@
 
 __all__ = [
     'reopen_log_files',
+
     'set_log_level_for_all_handlers',
-    'set_log_level_for_all_loggers'
+    'set_log_level_for_all_loggers',
+
+    'add_global_filters_for_all_loggers'
 ]
 
 LOG = logging.getLogger(__name__)
@@ -40,6 +43,11 @@
     'heartbeat_tick'
 ]
 
+# List of global filters which apply to all the loggers
+GLOBAL_FILTERS = [
+    LoggerFunctionNameExclusionFilter(exclusions=IGNORED_FUNCTION_NAMES)
+]
+
 
 def reopen_log_files(handlers):
     """
@@ -99,14 +107,57 @@ def set_log_level_for_all_loggers(level=logging.DEBUG):
         if not isinstance(logger, logging.Logger):
             continue
 
-        if hasattr(logger, 'addFilter'):
-            logger.addFilter(LoggerFunctionNameExclusionFilter(exclusions=IGNORED_FUNCTION_NAMES))
+        logger = add_filters_for_logger(logger=logger, filters=GLOBAL_FILTERS)
 
         if logger.name in SPECIAL_LOGGERS:
             set_log_level_for_all_handlers(logger=logger, level=SPECIAL_LOGGERS.get(logger.name))
         else:
             set_log_level_for_all_handlers(logger=logger, level=level)
 
+    return loggers
+
+
+def add_global_filters_for_all_loggers():
+    """
+    Add global filters to all the loggers.
+
+    This way we ensure "spamy" messages like heartbeat_tick are excluded also when --debug flag /
+    system.debug config option is not set, but log level is set to DEBUG.
+    """
+    root_logger = logging.getLogger()
+    loggers = list(logging.Logger.manager.loggerDict.values())
+    loggers += [root_logger]
+
+    for logger in loggers:
+        if not isinstance(logger, logging.Logger):
+            continue
+
+        logger = add_filters_for_logger(logger=logger, filters=GLOBAL_FILTERS)
+
+    return loggers
+
+
+def add_filters_for_logger(logger, filters):
+    """
+    Add provided exclusion filters to the provided logger instance.
+
+    :param logger: Logger class instance.
+    :type logger: :class:`logging.Filter`
+
+    :param filter: List of Logger filter instances.
+    :type filter: ``list`` of :class:`logging.Filter`
+    """
+    if not isinstance(logger, logging.Logger):
+        return logger
+
+    if not hasattr(logger, 'addFilter'):
+        return logger
+
+    for logger_filter in filters:
+        logger.addFilter(logger_filter)
+
+    return logger
+
 
 def get_logger_name_for_module(module, exclude_module_name=False):
     """

st2common/st2common/service_setup.py

@@ -37,6 +37,7 @@
 from st2common import triggers
 from st2common.rbac.migrations import run_all as run_all_rbac_migrations
 from st2common.logging.filters import LogLevelFilter
+from st2common.logging.misc import add_global_filters_for_all_loggers
 
 # Note: This is here for backward compatibility.
 # Function has been moved in a standalone module to avoid expensive in-direct
@@ -137,6 +138,10 @@ def setup(service, config, setup_db=True, register_mq_exchanges=True,
 
     if is_debug_enabled:
         enable_debugging()
+    else:
+        # Add global ignore filters, such as "heartbeat_tick" messages which are logged every 2
+        # ms which cause too much noise
+        add_global_filters_for_all_loggers()
 
     if cfg.CONF.profile:
         enable_profiling()

st2common/tests/integration/test_service_setup_log_level_filtering.py

@@ -46,6 +46,9 @@
                                             'conf/st2.tests.api.system_debug_true.conf')
 ST2_CONFIG_SYSTEM_DEBUG_PATH = os.path.abspath(ST2_CONFIG_SYSTEM_DEBUG_PATH)
 
+ST2_CONFIG_SYSTEM_LL_DEBUG_PATH = os.path.join(FIXTURES_DIR,
+    'conf/st2.tests.api.system_debug_true_logging_debug.conf')
+
 PYTHON_BINARY = sys.executable
 
 ST2API_BINARY = os.path.join(BASE_DIR, '../../../st2api/bin/st2api')
@@ -116,8 +119,34 @@ def test_audit_log_level_is_filtered_if_log_level_is_not_debug_or_audit(self):
         self.assertTrue('DEBUG [-]' in stdout)
         self.assertTrue('AUDIT [-]' in stdout)
 
+    def test_kombu_heartbeat_tick_log_messages_are_excluded(self):
+        # 1. system.debug = True config option is set, verify heartbeat_tick message is not logged
+        process = self._start_process(config_path=ST2_CONFIG_SYSTEM_LL_DEBUG_PATH)
+        self.add_process(process=process)
+
+        # Give it some time to start up
+        eventlet.sleep(5)
+        process.send_signal(signal.SIGKILL)
+
+        stdout = '\n'.join(process.stdout.read().decode('utf-8').split('\n'))
+        self.assertTrue('heartbeat_tick' not in stdout)
+
+        # 2. system.debug = False, log level is set to debug
+        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)
+
+        stdout = '\n'.join(process.stdout.read().decode('utf-8').split('\n'))
+        self.assertTrue('heartbeat_tick' not in stdout)
+
     def _start_process(self, config_path):
         cmd = CMD + [config_path]
-        process = subprocess.Popen(cmd, stdout=subprocess.PIPE, stderr=subprocess.PIPE,
+        cwd = os.path.abspath(os.path.join(BASE_DIR, '../../../'))
+        cwd = os.path.abspath(cwd)
+        process = subprocess.Popen(cmd, cwd=cwd,
+                                   stdout=subprocess.PIPE, stderr=subprocess.PIPE,
                                    shell=False, preexec_fn=os.setsid)
         return process

st2tests/st2tests/fixtures/conf/st2.tests.api.system_debug_true_logging_debug.conf

@@ -0,0 +1,99 @@
+# Config file used by integration tests
+
+[database]
+db_name = st2-test
+
+[api]
+# Host and port to bind the API server.
+host = 127.0.0.1
+port = 9101
+logging = st2tests/st2tests/fixtures/conf/logging.api.debug.conf
+mask_secrets = False
+# allow_origin is required for handling CORS in st2 web UI.
+# allow_origin = http://myhost1.example.com:3000,http://myhost2.example.com:3000
+
+[sensorcontainer]
+logging = st2tests/conf/logging.sensorcontainer.conf
+sensor_node_name = sensornode1
+partition_provider = name:default
+
+[rulesengine]
+logging = st2reactor/conf/logging.rulesengine.conf
+
+[timersengine]
+logging = st2reactor/conf/logging.timersengine.conf
+
+[actionrunner]
+logging = st2actions/conf/logging.conf
+
+[auth]
+host = 127.0.0.1
+port = 9100
+use_ssl = False
+debug = False
+enable = False
+logging = st2tests/conf/logging.auth.conf
+
+mode = standalone
+backend = flat_file
+backend_kwargs = {"file_path": "st2auth/conf/htpasswd_dev"}
+
+# Base URL to the API endpoint excluding the version (e.g. http://myhost.net:9101/)
+api_url = http://127.0.0.1:9101/
+
+[system]
+debug = True
+# This way integration tests can write to this directory
+base_path = /tmp
+
+[garbagecollector]
+logging = st2reactor/conf/logging.garbagecollector.conf
+
+action_executions_ttl = 20
+action_executions_output_ttl = 10
+trigger_instances_ttl = 20
+purge_inquiries = True
+
+collection_interval = 1
+sleep_delay = 0.1
+
+[content]
+system_packs_base_path =
+packs_base_paths = st2tests/st2tests/fixtures/packs/
+
+[syslog]
+host = 127.0.0.1
+port = 514
+facility = local7
+protocol = udp
+
+[webui]
+# webui_base_url = https://mywebhost.domain
+
+[log]
+excludes = requests,paramiko
+redirect_stderr = False
+mask_secrets = False
+
+[system_user]
+user = stanley
+ssh_key_file = /home/vagrant/.ssh/stanley_rsa
+
+[messaging]
+url = amqp://guest:guest@127.0.0.1:5672/
+
+[ssh_runner]
+remote_dir = /tmp
+
+[resultstracker]
+logging = st2actions/conf/logging.resultstracker.conf
+query_interval = 0.1
+
+[notifier]
+logging = st2actions/conf/logging.notifier.conf
+
+[exporter]
+logging = st2exporter/conf/logging.exporter.conf
+
+[mistral]
+jitter_interval = 0