From 9ba7f9ec8abf3f4cf3cd35a7e8d295b01cf81515 Mon Sep 17 00:00:00 2001 From: Tomaz Muraus Date: Tue, 19 Feb 2019 13:51:45 +0100 Subject: [PATCH 1/4] Make sure we also exclude "heartbeat_tick" log messages which are logged y kombu every 2 ms by default even when --debug flag / system.debug config option is not used. This way we avoid unnecessary noise when DEBUG level is used, but debug flag is not. --- st2common/st2common/logging/misc.py | 53 +++++++++++++++++++++++++++- st2common/st2common/service_setup.py | 5 +++ 2 files changed, 57 insertions(+), 1 deletion(-) diff --git a/st2common/st2common/logging/misc.py b/st2common/st2common/logging/misc.py index 7802b09931..db7d132d6a 100644 --- a/st2common/st2common/logging/misc.py +++ b/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,6 +107,8 @@ def set_log_level_for_all_loggers(level=logging.DEBUG): if not isinstance(logger, logging.Logger): continue + logger = add_filters_for_logger(logger=logger, filters=GLOBAL_FILTERS) + if hasattr(logger, 'addFilter'): logger.addFilter(LoggerFunctionNameExclusionFilter(exclusions=IGNORED_FUNCTION_NAMES)) @@ -107,6 +117,47 @@ def set_log_level_for_all_loggers(level=logging.DEBUG): 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 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): """ diff --git a/st2common/st2common/service_setup.py b/st2common/st2common/service_setup.py index bf82e00192..aace68f2a5 100644 --- a/st2common/st2common/service_setup.py +++ b/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() From 25263c6f5bb08958fd3fb498bcf6ea1d41282a62 Mon Sep 17 00:00:00 2001 From: Tomaz Muraus Date: Tue, 19 Feb 2019 13:59:59 +0100 Subject: [PATCH 2/4] Add changelog entry. --- CHANGELOG.rst | 7 +++++++ 1 file changed, 7 insertions(+) diff --git a/CHANGELOG.rst b/CHANGELOG.rst index 8b52e5d5c9..11aace2765 100644 --- a/CHANGELOG.rst +++ b/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 ~~~~~ From a2461dd7ea3ac7f27299499a39aec0363bd191f7 Mon Sep 17 00:00:00 2001 From: Tomaz Muraus Date: Tue, 19 Feb 2019 14:01:16 +0100 Subject: [PATCH 3/4] Remove duplicate filter add, add additional safety check. --- st2common/st2common/logging/misc.py | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/st2common/st2common/logging/misc.py b/st2common/st2common/logging/misc.py index db7d132d6a..0cf465b396 100644 --- a/st2common/st2common/logging/misc.py +++ b/st2common/st2common/logging/misc.py @@ -109,9 +109,6 @@ def set_log_level_for_all_loggers(level=logging.DEBUG): logger = add_filters_for_logger(logger=logger, filters=GLOBAL_FILTERS) - if hasattr(logger, 'addFilter'): - logger.addFilter(LoggerFunctionNameExclusionFilter(exclusions=IGNORED_FUNCTION_NAMES)) - if logger.name in SPECIAL_LOGGERS: set_log_level_for_all_handlers(logger=logger, level=SPECIAL_LOGGERS.get(logger.name)) else: @@ -150,6 +147,9 @@ def add_filters_for_logger(logger, filters): :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 From abeb1dcfad0ba43255ccc4310ba1ebf6c63c3488 Mon Sep 17 00:00:00 2001 From: Tomaz Muraus Date: Tue, 19 Feb 2019 15:59:31 +0100 Subject: [PATCH 4/4] Add a test case for exclusion of heartbeat_tick log messages. --- .../test_service_setup_log_level_filtering.py | 31 +++++- ...s.api.system_debug_true_logging_debug.conf | 99 +++++++++++++++++++ 2 files changed, 129 insertions(+), 1 deletion(-) create mode 100644 st2tests/st2tests/fixtures/conf/st2.tests.api.system_debug_true_logging_debug.conf diff --git a/st2common/tests/integration/test_service_setup_log_level_filtering.py b/st2common/tests/integration/test_service_setup_log_level_filtering.py index 432834d486..613b66243c 100644 --- a/st2common/tests/integration/test_service_setup_log_level_filtering.py +++ b/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 diff --git a/st2tests/st2tests/fixtures/conf/st2.tests.api.system_debug_true_logging_debug.conf b/st2tests/st2tests/fixtures/conf/st2.tests.api.system_debug_true_logging_debug.conf new file mode 100644 index 0000000000..736b62e81c --- /dev/null +++ b/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