Fixed logging issues with fastapi #408 and optimade #450.

nomad/app_fastapi/optimade/__init__.py

@@ -3,12 +3,14 @@ import os
 import sys
 import importlib
 
-# patch optimade python tools config and log handling
+# patch optimade python tools config (patched module most be outside this module to force import before optimade)
 os.environ['OPTIMADE_CONFIG_FILE'] = os.path.join(os.path.dirname(__file__), 'optimade_config.json')
+
+# patch optimade logger (patched module most be outside this module to force import before optimade)
 sys.modules['optimade.server.logger'] = importlib.import_module('nomad.app_fastapi.optimade_logger')
 
 # patch optimade base path
-from nomad import config  # nopep8
+from nomad import config, utils  # nopep8
 from optimade.server.config import CONFIG  # nopep8
 CONFIG.root_path = "%s/optimade" % config.services.api_base_path
 
@@ -40,3 +42,20 @@ from .filterparser import parse_filter  # nopep8
 
 structures.structures_coll = ElasticsearchStructureCollection()
 optimade.add_major_version_base_url(optimade.app)
+
+# patch the general exception handler
+logger = utils.get_logger(__name__)
+exception_handlers = sys.modules['optimade.server.exception_handlers']
+original_handler = getattr(exception_handlers, 'general_exception')
+
+
+def general_exception(request, exc, status_code=500, **kwargs):
+    log_method = logger.error if status_code >= 500 else logger.info
+    log_method(
+        'unexpected exception in optimade implementation',
+        status_code=status_code, exc_info=exc, url=request.url)
+
+    return original_handler(request, exc, status_code, **kwargs)
+
+
+setattr(exception_handlers, 'general_exception', general_exception)

nomad/utils/structlogging.py

@@ -88,8 +88,12 @@ class LogstashHandler(logstash.TCPLogstashHandler):
     legacy_logger = None
 
     def filter(self, record):
-        if record.name == 'gunicorn.access' and 'alive' in record.args.get('r', ''):
-            return False
+        print('*** ', record)
+        if record.name in ['uvicorn.access', 'gunicorn.access']:
+            record_string = record.args.get('r', '')
+            if 'alive' in record_string or 'gui/index.html' in record_string:
+                print('--- A')
+                return False
 
         if super().filter(record):
             is_structlog = False
@@ -97,9 +101,11 @@ class LogstashHandler(logstash.TCPLogstashHandler):
                 is_structlog = record.msg.startswith('{') and record.msg.endswith('}')
 
             if is_structlog:
+                print('+++ ')
                 return True
             else:
                 if LogstashHandler.legacy_logger is None:
+                    print('+++ ')
                     return True
                 else:
                     LogstashHandler.legacy_logger.log(
@@ -107,8 +113,10 @@ class LogstashHandler(logstash.TCPLogstashHandler):
                         exc_info=record.exc_info, stack_info=record.stack_info,
                         legacy_logger=record.name)
 
+                    print('--- B')
                     return False
 
+        print('--- C')
         return False
 
 

ops/helm/nomad/templates/api-deployment.yaml

@@ -10,7 +10,7 @@ metadata:
 data:
   gunicorn.log.conf: |
     [loggers]
-    keys=root, gunicorn.error, gunicorn.access
+    keys=root, gunicorn, gunicorn.error, gunicorn.access, uvicorn, uvicorn.error, uvicorn.access
 
     [handlers]
     keys=console, access, error
@@ -22,6 +22,11 @@ data:
     level=INFO
     handlers=console
 
+    [logger_gunicorn]
+    level=INFO
+    handlers=console
+    qualname=gunicorn
+
     [logger_gunicorn.error]
     level=INFO
     handlers=error
@@ -32,6 +37,21 @@ data:
     handlers=access
     qualname=gunicorn.access
 
+    [logger_uvicorn]
+    level=INFO
+    handlers=console
+    qualname=uvicorn
+
+    [logger_uvicorn.error]
+    level=INFO
+    handlers=error
+    qualname=uvicorn.error
+
+    [logger_uvicorn.access]
+    level=INFO
+    handlers=access
+    qualname=uvicorn.access
+
     [handler_console]
     class=StreamHandler
     formatter=generic

tests/app/test_api.py

@@ -1235,7 +1235,7 @@ class TestRepo():
     @pytest.mark.parametrize('query, nbuckets', [
         (dict(interval='1M', metrics='dft.total_energies'), 1),
         (dict(interval='1d', metrics='dft.quantities'), 6),
-        (dict(interval='1y', from_time='2019-03-20T12:43:54.566414'), 1),
+        (dict(interval='1y', from_time='2019-03-20T12:43:54.566414'), 2),
         (dict(until_time='2010-03-20T12:43:54.566414'), 0),
         (dict(interval='1m', from_time='2020-02-20T12:43:54.566414', metrics='dft.calculations'), 7201)
     ])