Merge pull request #58 from HumanCellAtlas/ds_fix_excessive_logging_430

Fix excessive logging

kubernetes/listener-deployment.yaml.ctmpl

@@ -21,6 +21,10 @@ spec:
         env:
         - name: listener_config
           value: /etc/secondary-analysis/config.json
+        readinessProbe:
+          httpGet:
+            path: /health
+            port: 8080
       volumes:
       - name: listener-config
         secret:

lira/api/health.py

@@ -2,6 +2,6 @@
 
 
 def get():
-    logger = logging.getLogger("Lira | {module_path}".format(module_path=__name__))
-    logger.info("Health check request received")
+    logger = logging.getLogger("{module_path}".format(module_path=__name__))
+    logger.debug("Health check request received")
     return dict(status="healthy")

lira/api/notifications.py

@@ -6,7 +6,7 @@
 from cromwell_tools import cromwell_tools
 from lira import lira_utils
 
-logger = logging.getLogger("Lira | {module_path}".format(module_path=__name__))
+logger = logging.getLogger("{module_path}".format(module_path=__name__))
 
 
 def post(body):

lira/lira.py

@@ -4,6 +4,7 @@
 Green box description FIXME: elaborate
 """
 import os
+import sys
 import json
 import logging
 import connexion
@@ -13,33 +14,31 @@
 from . import lira_config
 from .api import notifications
 
+class MaxLevelFilter(object):
+    """Excludes logs above max_level"""
+    def __init__(self, max_level):
+        self.max_level = max_level
+    def filter(self, log_record):
+        return log_record.levelno <= self.max_level
+
 parser = argparse.ArgumentParser()
 parser.add_argument('--host', default='0.0.0.0')
 parser.add_argument('--port', type=int, default=8080)
 args, _ = parser.parse_known_args()
 
-logging.basicConfig(level=logging.DEBUG)
-logger = logging.getLogger('Lira | {module_path}'.format(module_path=__name__))
-
 app = connexion.App(__name__)
 
 # 'application' is not used in this file, but is used by gunicorn
 application = app.app
 
 config_path = os.environ['listener_config']
-logger.info('Using config file at {0}'.format(config_path))
 with open(config_path) as f:
     config = lira_config.LiraConfig(json.load(f), app.app.config)
-    app.app.config = config
 
-    # Configure log level for loggers that print query params.
-    # Unless specified otherwise in Lira's config file, these will be set
-    # at ERROR for werkzeug and INFO for connexion.decorators.validation
-    # in order to suppress messages that include query params.
-    logging.getLogger('werkzeug').setLevel(config.log_level_werkzeug)
-    logging.getLogger('connexion.decorators.validation').setLevel(config.log_level_connexion_validation)
-
-    app.app.prepare_submission = notifications.create_prepare_submission_function(app.app.config.cache_wdls)
+logger = logging.getLogger('lira.{module_path}'.format(module_path=__name__))
+logger.info('Using config file at {0}'.format(config_path))
+app.app.config = config
+app.app.prepare_submission = notifications.create_prepare_submission_function(app.app.config.cache_wdls)
 
 resolver = RestyResolver('lira.api', collection_endpoint_name='list')
 app.add_api('lira.yml', resolver=resolver, validate_responses=True)

lira/lira.yml

@@ -9,7 +9,7 @@ schemes:
 produces:
   - application/json
 paths:
-  /:
+  /health:
     get:
       summary: health check
       operationId: 'lira.api.health.get'

lira/lira_config.py

@@ -1,6 +1,7 @@
 """Classes that represent Lira configuration.
 """
 import logging
+import sys
 
 
 class Config(object):
@@ -43,7 +44,7 @@ def _verify_fields(self):
                 'The following configuration is missing key(s): {keys}'
                 ''.format(keys=', '.join(missing_keys)))
         if extra_keys:
-            logger = logging.getLogger('Lira | {module_path}'.format(module_path=__name__))
+            logger = logging.getLogger('{module_path}'.format(module_path=__name__))
             logger.info(
                 'Configuration has non-required key(s): {keys}'
                 ''.format(keys=', '.join(extra_keys)))
@@ -101,17 +102,41 @@ class LiraConfig(Config):
     """subclass of Config representing Lira configuration"""
 
     def __init__(self, config_object, *args, **kwargs):
-        logger = logging.getLogger('Lira | {module_path}'.format(module_path=__name__))
-
         # Setting default values that can be overridden
         self.cache_wdls = True
 
         # Setting the following log levels prevents log messages that
         # print query params in the log.
         # Werkzeug has INFO messages that log the url including query params of each request.
         # The Connexion validator has DEBUG messages that do the same.
-        self.log_level_werkzeug = 'WARNING'
-        self.log_level_connexion_validation = 'INFO'
+        self.log_level_werkzeug = logging.WARNING
+        self.log_level_connexion_validation = logging.INFO
+        self.log_level_lira = logging.INFO
+
+        # Send logs between log_level_lira and info (inclusive) to stdout.
+        # If log_level_lira > INFO then nothing is sent to stdout.
+        stdout_handler = logging.StreamHandler(sys.stdout)
+        log_level_lira = config_object.get('log_level_lira', None)
+        if log_level_lira is not None:
+            self.log_level_lira = getattr(logging, log_level_lira)
+        stdout_handler.setLevel(self.log_level_lira)
+        stdout_handler.addFilter(MaxLevelFilter(logging.INFO))
+
+        # Send logs at or above the greater of warning and log_level_lira to stderr.
+        stderr_handler = logging.StreamHandler(sys.stderr)
+        self.log_level_stderr = logging.WARNING
+        if self.log_level_lira > logging.WARNING:
+            self.log_level_stderr = self.log_level_lira
+        stderr_handler.setLevel(self.log_level_stderr)
+
+        logging.basicConfig(level=self.log_level_lira, handlers=[stdout_handler, stderr_handler])
+
+        # Configure log level for loggers that print query params.
+        # Unless specified otherwise in Lira's config file, these will be set
+        # at ERROR for werkzeug and INFO for connexion.decorators.validation
+        # in order to suppress messages that include query params.
+        logging.getLogger('werkzeug').setLevel(self.log_level_werkzeug)
+        logging.getLogger('connexion.decorators.validation').setLevel(self.log_level_connexion_validation)
 
         # parse the wdls section
         wdl_configs = []
@@ -124,6 +149,7 @@ def __init__(self, config_object, *args, **kwargs):
         config_object['wdls'] = wdl_configs
 
         if config_object.get('dry_run'):
+            logger = logging.getLogger('{module_path}'.format(module_path=__name__))
             logger.warning('***Lira is running in dry_run mode and will NOT launch any workflows***')
 
         Config.__init__(self, config_object, *args, **kwargs)
@@ -145,7 +171,7 @@ def required_fields(self):
     def _verify_wdl_configs(wdl_configs):
         """Additional verification for wdl configurations"""
         if len(wdl_configs) != len(set(wdl_configs)):
-            logger = logging.getLogger('Lira | {module_path}'.format(module_path=__name__))
+            logger = logging.getLogger('{module_path}'.format(module_path=__name__))
             logger.warning('duplicate wdl definitions detected in config.json')
 
         if len(wdl_configs) != len(set([wdl.subscription_id for wdl in wdl_configs])):
@@ -159,3 +185,11 @@ def __str__(self):
         return s.format(self.env, self.submit_wdl, self.cromwell_url,
             '(cromwell_user)', '(cromwell_password)', '(notification_token)',
             self.MAX_CONTENT_LENGTH, self.wdls)
+
+
+class MaxLevelFilter(object):
+    """Excludes logs above max_level"""
+    def __init__(self, max_level):
+        self.max_level = max_level
+    def filter(self, log_record):
+        return log_record.levelno <= self.max_level

lira/test/test_config.py

@@ -5,6 +5,7 @@
 from lira import lira_config
 import os
 import sys
+import logging
 
 
 class TestStartupVerification(unittest.TestCase):
@@ -69,24 +70,24 @@ def test_cache_wdls_can_be_set_to_false(self):
     def test_werkzeug_logger_warning_by_default(self):
         test_config = deepcopy(self.correct_test_config)
         config = lira_config.LiraConfig(test_config)
-        self.assertEqual(config.log_level_werkzeug, 'WARNING')
+        self.assertEqual(config.log_level_werkzeug, logging.WARNING)
 
     def test_connexion_validation_logger_info_by_default(self):
         test_config = deepcopy(self.correct_test_config)
         config = lira_config.LiraConfig(test_config)
-        self.assertEqual(config.log_level_connexion_validation, 'INFO')
+        self.assertEqual(config.log_level_connexion_validation, logging.INFO)
 
     def test_werkzeug_logger_can_be_set_to_debug(self):
         test_config = deepcopy(self.correct_test_config)
-        test_config['log_level_werkzeug'] = 'DEBUG'
+        test_config['log_level_werkzeug'] = logging.DEBUG
         config = lira_config.LiraConfig(test_config)
-        self.assertEqual(config.log_level_werkzeug, 'DEBUG')
+        self.assertEqual(config.log_level_werkzeug, logging.DEBUG)
 
     def test_connexion_validation_can_be_set_to_debug(self):
         test_config = deepcopy(self.correct_test_config)
-        test_config['log_level_connexion_validation'] = 'DEBUG'
+        test_config['log_level_connexion_validation'] = logging.DEBUG
         config = lira_config.LiraConfig(test_config)
-        self.assertEqual(config.log_level_connexion_validation, 'DEBUG')
+        self.assertEqual(config.log_level_connexion_validation, logging.DEBUG)
 
     def test_config_duplicate_wdl_raises_value_error(self):