From 701eeb20d892a6aaa478f717f904735aecc8d85d Mon Sep 17 00:00:00 2001 From: Tomaz Muraus Date: Tue, 13 Nov 2018 17:30:38 +0100 Subject: [PATCH 1/6] Don't print statsd log messages unless debug / verbose mode is used. NOTE: By default statsd client logs all the messages under INFO which causes a lot of noise. --- st2common/st2common/script_setup.py | 9 +++++++-- st2common/st2common/service_setup.py | 11 +++++++++-- 2 files changed, 16 insertions(+), 4 deletions(-) diff --git a/st2common/st2common/script_setup.py b/st2common/st2common/script_setup.py index 1b6458b62a..3d06dd9dcc 100644 --- a/st2common/st2common/script_setup.py +++ b/st2common/st2common/script_setup.py @@ -25,12 +25,12 @@ import logging as stdlib_logging from oslo_config import cfg - from st2common import log as logging from st2common.database_setup import db_setup from st2common.database_setup import db_teardown from st2common import triggers from st2common.logging.filters import LogLevelFilter +from st2common.logging.filters import LoggerNameExclusionFilter from st2common.transport.bootstrap_utils import register_exchanges_with_retry __all__ = [ @@ -77,7 +77,8 @@ def setup(config, setup_db=True, register_mq_exchanges=True, # Set up logging log_level = stdlib_logging.DEBUG - stdlib_logging.basicConfig(format='%(asctime)s %(levelname)s [-] %(message)s', level=log_level) + stdlib_logging.basicConfig(format='%(asctime)s %(levelname)s %(module)s [-] %(message)s', + level=log_level) if not cfg.CONF.verbose: # Note: We still want to print things at the following log levels: INFO, ERROR, CRITICAL @@ -87,6 +88,10 @@ def setup(config, setup_db=True, register_mq_exchanges=True, for handler in handlers: handler.addFilter(LogLevelFilter(log_levels=exclude_log_levels)) + # NOTE: statsd logger logs everything by default under INFO so we ignore those log + # messages unless verbose / debug mode is used + handler.addFilter(LoggerNameExclusionFilter(exclusions=['statsd'])) + # All other setup code which requires config to be parsed and logging to be correctly setup if setup_db: db_setup() diff --git a/st2common/st2common/service_setup.py b/st2common/st2common/service_setup.py index 71e9aa0d06..e7310888c1 100644 --- a/st2common/st2common/service_setup.py +++ b/st2common/st2common/service_setup.py @@ -98,9 +98,16 @@ def setup(service, config, setup_db=True, register_mq_exchanges=True, LOG.debug('Using logging config: %s', logging_config_path) + is_debug_enabled = (cfg.CONF.debug or cfg.CONF.system.debug) + + excluded_logger_names = list(cfg.CONF.log.excludes) + + if not is_debug_enabled: + excluded_logger_names.append('statsd') + try: logging.setup(logging_config_path, redirect_stderr=cfg.CONF.log.redirect_stderr, - excludes=cfg.CONF.log.excludes) + excludes=excluded_logger_names) except KeyError as e: tb_msg = traceback.format_exc() if 'log.setLevel' in tb_msg: @@ -110,7 +117,7 @@ def setup(service, config, setup_db=True, register_mq_exchanges=True, else: raise e - if cfg.CONF.debug or cfg.CONF.system.debug: + if is_debug_enabled: enable_debugging() if cfg.CONF.profile: From c19887e641eef0dcecf32bae9f7cbb7410c52e82 Mon Sep 17 00:00:00 2001 From: Tomaz Muraus Date: Tue, 13 Nov 2018 17:33:17 +0100 Subject: [PATCH 2/6] Update logger format string. --- st2common/st2common/script_setup.py | 3 +-- 1 file changed, 1 insertion(+), 2 deletions(-) diff --git a/st2common/st2common/script_setup.py b/st2common/st2common/script_setup.py index 3d06dd9dcc..76747db5df 100644 --- a/st2common/st2common/script_setup.py +++ b/st2common/st2common/script_setup.py @@ -77,8 +77,7 @@ def setup(config, setup_db=True, register_mq_exchanges=True, # Set up logging log_level = stdlib_logging.DEBUG - stdlib_logging.basicConfig(format='%(asctime)s %(levelname)s %(module)s [-] %(message)s', - level=log_level) + stdlib_logging.basicConfig(format='%(asctime)s %(levelname)s [-] %(message)s', level=log_level) if not cfg.CONF.verbose: # Note: We still want to print things at the following log levels: INFO, ERROR, CRITICAL From 5515a9e818888c0ffa226e0e70015c12b9c7b708 Mon Sep 17 00:00:00 2001 From: Tomaz Muraus Date: Tue, 13 Nov 2018 17:41:10 +0100 Subject: [PATCH 3/6] Ignore "Generating grammar tables" log messages generated by 2to3 library used by networkx. --- st2common/st2common/log.py | 19 ++++++++++++++++++- st2common/st2common/script_setup.py | 4 +++- st2common/st2common/service_setup.py | 2 ++ 3 files changed, 23 insertions(+), 2 deletions(-) diff --git a/st2common/st2common/log.py b/st2common/st2common/log.py index c5677fd5e1..df2cc056b1 100644 --- a/st2common/st2common/log.py +++ b/st2common/st2common/log.py @@ -40,7 +40,9 @@ 'FormatNamedFileHandler', 'ConfigurableSyslogHandler', - 'LoggingStream' + 'LoggingStream', + + 'ignore_lib2to3_log_messages' ] logging.AUDIT = logging.CRITICAL + 10 @@ -202,3 +204,18 @@ def setup(config_file, redirect_stderr=True, excludes=None, disable_existing_log sys.stderr.write('ERROR: %s' % (msg)) raise exc_cls(six.text_type(msg)) + + +def ignore_lib2to3_log_messages(): + """ + Work around to ignore "Generating grammar tables from" log messages which are logged under + INFO by default by libraries such as networkx which use 2to3. + """ + import lib2to3.pgen2.driver + + class MockLogging(object): + def getLogger(self): + return logging.getLogger('lib2to3') + + lib2to3.pgen2.driver.logging = MockLogging() + logging.getLogger('lib2to3').setLevel(logging.ERROR) diff --git a/st2common/st2common/script_setup.py b/st2common/st2common/script_setup.py index 76747db5df..ad6dc0935b 100644 --- a/st2common/st2common/script_setup.py +++ b/st2common/st2common/script_setup.py @@ -89,7 +89,9 @@ def setup(config, setup_db=True, register_mq_exchanges=True, # NOTE: statsd logger logs everything by default under INFO so we ignore those log # messages unless verbose / debug mode is used - handler.addFilter(LoggerNameExclusionFilter(exclusions=['statsd'])) + handler.addFilter(LoggerNameExclusionFilter(exclusions=['statsd', 'lib2to3'])) + + logging.ignore_lib2to3_log_messages() # All other setup code which requires config to be parsed and logging to be correctly setup if setup_db: diff --git a/st2common/st2common/service_setup.py b/st2common/st2common/service_setup.py index e7310888c1..893ece8703 100644 --- a/st2common/st2common/service_setup.py +++ b/st2common/st2common/service_setup.py @@ -117,6 +117,8 @@ def setup(service, config, setup_db=True, register_mq_exchanges=True, else: raise e + logging.ignore_lib2to3_log_messages() + if is_debug_enabled: enable_debugging() From 3deb4aadc2091dd15a7cd10ab7e3e2add4c38a5f Mon Sep 17 00:00:00 2001 From: Tomaz Muraus Date: Tue, 13 Nov 2018 17:43:15 +0100 Subject: [PATCH 4/6] Add comment. --- st2common/st2common/service_setup.py | 2 ++ 1 file changed, 2 insertions(+) diff --git a/st2common/st2common/service_setup.py b/st2common/st2common/service_setup.py index 893ece8703..4a5e30c524 100644 --- a/st2common/st2common/service_setup.py +++ b/st2common/st2common/service_setup.py @@ -103,6 +103,8 @@ def setup(service, config, setup_db=True, register_mq_exchanges=True, excluded_logger_names = list(cfg.CONF.log.excludes) 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 excluded_logger_names.append('statsd') try: From a419669c195198ce1514e9597cf5d438f8d2acec Mon Sep 17 00:00:00 2001 From: Tomaz Muraus Date: Tue, 13 Nov 2018 17:44:01 +0100 Subject: [PATCH 5/6] Remove code which is not needed. --- st2common/st2common/script_setup.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/st2common/st2common/script_setup.py b/st2common/st2common/script_setup.py index ad6dc0935b..5244ecbb7d 100644 --- a/st2common/st2common/script_setup.py +++ b/st2common/st2common/script_setup.py @@ -89,7 +89,7 @@ def setup(config, setup_db=True, register_mq_exchanges=True, # NOTE: statsd logger logs everything by default under INFO so we ignore those log # messages unless verbose / debug mode is used - handler.addFilter(LoggerNameExclusionFilter(exclusions=['statsd', 'lib2to3'])) + handler.addFilter(LoggerNameExclusionFilter(exclusions=['statsd'])) logging.ignore_lib2to3_log_messages() From 71c1480e444e418323a513f4bb0ed9f95a33fc9e Mon Sep 17 00:00:00 2001 From: Tomaz Muraus Date: Tue, 13 Nov 2018 18:25:12 +0100 Subject: [PATCH 6/6] Use the same approach for statsd as we use for lib2to3. --- st2common/st2common/log.py | 27 +++++++++++++++++++++++---- st2common/st2common/script_setup.py | 7 +++---- st2common/st2common/service_setup.py | 17 +++++++---------- 3 files changed, 33 insertions(+), 18 deletions(-) diff --git a/st2common/st2common/log.py b/st2common/st2common/log.py index df2cc056b1..1b9186fac3 100644 --- a/st2common/st2common/log.py +++ b/st2common/st2common/log.py @@ -42,7 +42,8 @@ 'LoggingStream', - 'ignore_lib2to3_log_messages' + 'ignore_lib2to3_log_messages', + 'ignore_statsd_log_messages' ] logging.AUDIT = logging.CRITICAL + 10 @@ -213,9 +214,27 @@ def ignore_lib2to3_log_messages(): """ import lib2to3.pgen2.driver - class MockLogging(object): - def getLogger(self): + class MockLoggingModule(object): + def getLogger(self, *args, **kwargs): return logging.getLogger('lib2to3') - lib2to3.pgen2.driver.logging = MockLogging() + lib2to3.pgen2.driver.logging = MockLoggingModule() logging.getLogger('lib2to3').setLevel(logging.ERROR) + + +def ignore_statsd_log_messages(): + """ + By default statsd client logs all the operations under INFO and that causes a lot of noise. + + This pull request silences all the statsd INFO log messages. + """ + import statsd.connection + import statsd.client + + class MockLoggingModule(object): + def getLogger(self, *args, **kwargs): + return logging.getLogger('statsd') + + statsd.connection.logging = MockLoggingModule() + statsd.client.logging = MockLoggingModule() + logging.getLogger('statsd').setLevel(logging.ERROR) diff --git a/st2common/st2common/script_setup.py b/st2common/st2common/script_setup.py index 5244ecbb7d..db980f6f07 100644 --- a/st2common/st2common/script_setup.py +++ b/st2common/st2common/script_setup.py @@ -30,7 +30,6 @@ from st2common.database_setup import db_teardown from st2common import triggers from st2common.logging.filters import LogLevelFilter -from st2common.logging.filters import LoggerNameExclusionFilter from st2common.transport.bootstrap_utils import register_exchanges_with_retry __all__ = [ @@ -87,9 +86,9 @@ def setup(config, setup_db=True, register_mq_exchanges=True, for handler in handlers: handler.addFilter(LogLevelFilter(log_levels=exclude_log_levels)) - # NOTE: statsd logger logs everything by default under INFO so we ignore those log - # messages unless verbose / debug mode is used - handler.addFilter(LoggerNameExclusionFilter(exclusions=['statsd'])) + # NOTE: statsd logger logs everything by default under INFO so we ignore those log + # messages unless verbose / debug mode is used + logging.ignore_statsd_log_messages() logging.ignore_lib2to3_log_messages() diff --git a/st2common/st2common/service_setup.py b/st2common/st2common/service_setup.py index 4a5e30c524..61fbea6bce 100644 --- a/st2common/st2common/service_setup.py +++ b/st2common/st2common/service_setup.py @@ -100,16 +100,9 @@ def setup(service, config, setup_db=True, register_mq_exchanges=True, is_debug_enabled = (cfg.CONF.debug or cfg.CONF.system.debug) - excluded_logger_names = list(cfg.CONF.log.excludes) - - 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 - excluded_logger_names.append('statsd') - try: logging.setup(logging_config_path, redirect_stderr=cfg.CONF.log.redirect_stderr, - excludes=excluded_logger_names) + excludes=cfg.CONF.log.excludes) except KeyError as e: tb_msg = traceback.format_exc() if 'log.setLevel' in tb_msg: @@ -119,6 +112,11 @@ def setup(service, config, setup_db=True, register_mq_exchanges=True, else: raise e + 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 + logging.ignore_statsd_log_messages() + logging.ignore_lib2to3_log_messages() if is_debug_enabled: @@ -127,8 +125,7 @@ def setup(service, config, setup_db=True, register_mq_exchanges=True, if cfg.CONF.profile: enable_profiling() - # All other setup which requires config to be parsed and logging to - # be correctly setup. + # All other setup which requires config to be parsed and logging to be correctly setup. if setup_db: db_setup()