Refactoring the app/api error handling.

nomad/app/__init__.py

@@ -31,12 +31,7 @@ from nomad import config, utils as nomad_utils
 from .api import blueprint as api
 from .optimade import blueprint as optimade
 from .docs import blueprint as docs
-
-logger: BoundLogger = None
-""" A logger pre configured with information about the current request. """
-
-base_path = config.services.api_base_path
-""" Provides the root path of the nomad APIs. """
+from . import common
 
 
 @property  # type: ignore
@@ -56,7 +51,7 @@ if config.services.https:
 app = Flask(__name__)
 """ The Flask app that serves all APIs. """
 
-app.config.APPLICATION_ROOT = base_path  # type: ignore
+app.config.APPLICATION_ROOT = common.base_path  # type: ignore
 app.config.RESTPLUS_MASK_HEADER = False  # type: ignore
 app.config.RESTPLUS_MASK_SWAGGER = False  # type: ignore
 app.config.SWAGGER_UI_OPERATION_ID = True  # type: ignore
@@ -97,7 +92,7 @@ def handle(error: Exception):
     response = jsonify(data)
     response.status_code = status_code
     if status_code == 500:
-        local_logger = logger
+        local_logger = common.logger
         # the logger is created in before_request, if the error was created before that
         # logger can be None
         if local_logger is None:
@@ -117,15 +112,23 @@ def alive():
 @app.before_request
 def before_request():
     # api logger
-    global logger
-    logger = nomad_utils.get_logger(
-        __name__,
+    args = getattr(request, 'view_args')
+    if args is None:
+        args = {}
+    else:
+        args = dict(**args)
+
+    args.update(
+        name=__name__,
         blueprint=str(request.blueprint),
         endpoint=request.endpoint,
         method=request.method,
+        url=request.url,
         json=request.json,
         args=request.args)
 
+    common.logger = nomad_utils.get_logger(**args)
+
     # chaos monkey
     if config.services.api_chaos > 0:
         if random.randint(0, 100) <= config.services.api_chaos:

nomad/app/api/api.py

@@ -24,3 +24,9 @@ api = Api(
     description='Official NOMAD API',
     validate=True)
 """ Provides the flask restplus api instance for the regular NOMAD api"""
+
+# For some unknown reason it is necessary for each fr api to have a handler.
+# Otherwise the global app error handler won't be called.
+@api.errorhandler(Exception)
+def errorhandler(error):
+    return str(error)

nomad/app/api/archive.py

@@ -29,7 +29,8 @@ import urllib.parse
 import nomad_meta_info
 
 from nomad.files import UploadFiles, Restricted
-from nomad import utils, search, config
+from nomad import search, config
+from nomad.app import common
 
 from .auth import authenticate, create_authorization_predicate
 from .api import api
@@ -168,7 +169,7 @@ class ArchiveDownloadResource(Resource):
                             upload_id, create_authorization_predicate(upload_id))
 
                         if upload_files is None:
-                            utils.get_logger(__name__).error('upload files do not exist', upload_id=upload_id)
+                            common.logger.error('upload files do not exist', upload_id=upload_id)
                             continue
 
                         upload_files.open_zipfile_cache()
@@ -192,7 +193,7 @@ class ArchiveDownloadResource(Resource):
                 except Exception as e:
                     manifest_contents = json.dumps(
                         dict(error='Could not create the manifest: %s' % (e))).encode('utf-8')
-                    utils.get_logger(__name__).error(
+                    common.logger.error(
                         'could not create raw query manifest', exc_info=e)
 
                 yield (
@@ -201,7 +202,7 @@ class ArchiveDownloadResource(Resource):
                     lambda *args: len(manifest_contents))
 
             except Exception as e:
-                utils.get_logger(__name__).warning(
+                common.logger.warning(
                     'unexpected error while streaming raw data from query',
                     exc_info=e,
                     query=urllib.parse.urlencode(request.args, doseq=True))

nomad/app/api/common.py

@@ -26,7 +26,7 @@ import os.path
 
 from nomad import search, config
 from nomad.app.optimade import filterparser
-from nomad.app.utils import RFC3339DateTime, rfc3339DateTime
+from nomad.app.common import RFC3339DateTime, rfc3339DateTime
 from nomad.files import Restricted
 
 from .api import api

nomad/app/api/dataset.py

@@ -17,10 +17,10 @@ from flask_restplus import Resource, fields, abort
 import re
 
 from nomad import utils, processing as proc
-from nomad.app.utils import with_logger
 from nomad.datamodel import Dataset
 from nomad.metainfo.flask_restplus import generate_flask_restplus_model
 from nomad.doi import DOI
+from nomad.app import common
 
 from .api import api
 from .auth import authenticate
@@ -125,8 +125,7 @@ class DatasetResource(Resource):
     @api.response(400, 'The dataset already has a DOI')
     @api.marshal_with(dataset_model, skip_none=True, code=200, description='DOI assigned')
     @authenticate(required=True)
-    @with_logger
-    def post(self, name: str, logger):
+    def post(self, name: str):
         """ Assign a DOI to the dataset. """
         try:
             result = Dataset.m_def.m_x('me').get(user_id=g.user.user_id, name=name)
@@ -154,12 +153,12 @@ class DatasetResource(Resource):
 
         result.m_x('me').save()
         if doi.state != 'findable':
-            logger.warning(
+            common.logger.warning(
                 'doi was created, but is not findable', doi=doi.doi, doi_state=doi.state,
                 dataset=result.dataset_id)
 
         # update all affected calcs in the search index
-        edit(dict(dataset_id=result.dataset_id), logger)
+        edit(dict(dataset_id=result.dataset_id))
 
         return result
 
@@ -168,8 +167,7 @@ class DatasetResource(Resource):
     @api.response(400, 'The dataset has a DOI and cannot be deleted')
     @api.marshal_with(dataset_model, skip_none=True, code=200, description='Dateset deleted')
     @authenticate(required=True)
-    @with_logger
-    def delete(self, name: str, logger):
+    def delete(self, name: str):
         """ Delete the dataset. """
         try:
             result = Dataset.m_def.m_x('me').get(user_id=g.user.user_id, name=name)
@@ -182,7 +180,6 @@ class DatasetResource(Resource):
         # edit all affected entries
         edit(
             dict(dataset_id=result.dataset_id),
-            logger,
             {'__raw__': {'$pull': {'metadata.datasets': result.dataset_id}}})
 
         # delete the dataset

nomad/app/api/raw.py

@@ -31,6 +31,7 @@ import urllib.parse
 from nomad import search, utils, config
 from nomad.files import UploadFiles, Restricted
 from nomad.processing import Calc
+from nomad.app import common
 
 from .api import api
 from .auth import authenticate, create_authorization_predicate
@@ -401,8 +402,7 @@ class RawFileQueryResource(Resource):
 
         The zip file will contain a ``manifest.json`` with the repository meta data.
         """
-        logger = utils.get_logger(__name__)
-        logger = logger.bind(query=urllib.parse.urlencode(request.args, doseq=True))
+        logger = common.logger.bind(query=urllib.parse.urlencode(request.args, doseq=True))
 
         patterns: List[str] = None
         try:
@@ -458,7 +458,7 @@ class RawFileQueryResource(Resource):
                             upload_id, create_authorization_predicate(upload_id))
 
                         if upload_files is None:
-                            utils.get_logger(__name__).error('upload files do not exist', upload_id=upload_id)
+                            logger.error('upload files do not exist', upload_id=upload_id)
                             continue
 
                         upload_files.open_zipfile_cache()
@@ -502,8 +502,7 @@ class RawFileQueryResource(Resource):
                 except Exception as e:
                     manifest_contents = json.dumps(
                         dict(error='Could not create the manifest: %s' % (e))).encode('utf-8')
-                    utils.get_logger(__name__).error(
-                        'could not create raw query manifest', exc_info=e)
+                    logger.error('could not create raw query manifest', exc_info=e)
 
                 yield (
                     'manifest.json', 'manifest',

nomad/app/api/repo.py

@@ -26,8 +26,9 @@ import elasticsearch.helpers
 from datetime import datetime
 
 from nomad import search, utils, datamodel, processing as proc, infrastructure
-from nomad.app.utils import RFC3339DateTime, with_logger
 from nomad.datamodel import UserMetadata, Dataset, User
+from nomad.app import common
+from nomad.app.common import RFC3339DateTime
 
 from .api import api
 from .auth import authenticate
@@ -293,9 +294,9 @@ _repo_edit_model = api.model('RepoEdit', {
 })
 
 
-def edit(parsed_query: Dict[str, Any], logger, mongo_update: Dict[str, Any] = None, re_index=True) -> List[str]:
+def edit(parsed_query: Dict[str, Any], mongo_update: Dict[str, Any] = None, re_index=True) -> List[str]:
     # get all calculations that have to change
-    with utils.timer(logger, 'edit query executed'):
+    with utils.timer(common.logger, 'edit query executed'):
         search_request = search.SearchRequest()
         apply_search_parameters(search_request, parsed_query)
         upload_ids = set()
@@ -305,14 +306,14 @@ def edit(parsed_query: Dict[str, Any], logger, mongo_update: Dict[str, Any] = No
             upload_ids.add(hit['upload_id'])
 
     # perform the update on the mongo db
-    with utils.timer(logger, 'edit mongo update executed', size=len(calc_ids)):
+    with utils.timer(common.logger, 'edit mongo update executed', size=len(calc_ids)):
         if mongo_update is not None:
             n_updated = proc.Calc.objects(calc_id__in=calc_ids).update(multi=True, **mongo_update)
             if n_updated != len(calc_ids):
-                logger.error('edit repo did not update all entries', payload=mongo_update)
+                common.logger.error('edit repo did not update all entries', payload=mongo_update)
 
     # re-index the affected entries in elastic search
-    with utils.timer(logger, 'edit elastic update executed', size=len(calc_ids)):
+    with utils.timer(common.logger, 'edit elastic update executed', size=len(calc_ids)):
         if re_index:
             def elastic_updates():
                 for calc in proc.Calc.objects(calc_id__in=calc_ids):
@@ -326,7 +327,7 @@ def edit(parsed_query: Dict[str, Any], logger, mongo_update: Dict[str, Any] = No
                 infrastructure.elastic_client, elastic_updates(), stats_only=True)
             search.refresh()
             if failed > 0:
-                logger.error(
+                common.logger.error(
                     'edit repo with failed elastic updates',
                     payload=mongo_update, nfailed=len(failed))
 
@@ -348,8 +349,7 @@ class EditRepoCalcsResource(Resource):
     @api.expect(_repo_edit_model)
     @api.marshal_with(_repo_edit_model, skip_none=True, code=200, description='Edit verified/performed')
     @authenticate()
-    @with_logger
-    def post(self, logger):
+    def post(self):
         """ Edit repository metadata. """
 
         # basic body parsing and some semantic checks
@@ -385,7 +385,7 @@ class EditRepoCalcsResource(Resource):
         lift_embargo = False
         removed_datasets = None
 
-        with utils.timer(logger, 'edit verified'):
+        with utils.timer(common.logger, 'edit verified'):
             for action_quantity_name, quantity_actions in actions.items():
                 quantity = UserMetadata.m_def.all_quantities.get(action_quantity_name)
                 if quantity is None:
@@ -511,7 +511,7 @@ class EditRepoCalcsResource(Resource):
 
         # perform the change
         mongo_update['metadata__last_edit'] = datetime.utcnow()
-        upload_ids = edit(parsed_query, logger, mongo_update, True)
+        upload_ids = edit(parsed_query, mongo_update, True)
 
         # lift embargo
         if lift_embargo:
@@ -705,7 +705,7 @@ class RepoPidResource(Resource):
             abort(404, 'Entry with PID %s does not exist' % pid)
 
         if total > 1:
-            utils.get_logger(__name__).error('Two entries for the same pid', pid=pid_int)
+            common.logger.error('Two entries for the same pid', pid=pid_int)
 
         result = results[0]
         return dict(

nomad/app/api/upload.py

@@ -29,8 +29,9 @@ from functools import wraps
 from nomad import config, utils, files, search, datamodel
 from nomad.processing import Upload, FAILURE
 from nomad.processing import ProcessAlreadyRunning
+from nomad.app import common
+from nomad.app.common import RFC3339DateTime
 
-from nomad.app.utils import with_logger, RFC3339DateTime
 from .api import api
 from .auth import authenticate, generate_upload_token
 from .common import pagination_request_parser, pagination_model, upload_route, metadata_model
@@ -218,8 +219,7 @@ class UploadListResource(Resource):
     @api.response(400, 'To many uploads')
     @marshal_with(upload_model, skip_none=True, code=200, description='Upload received')
     @authenticate(required=True, upload_token=True)
-    @with_logger
-    def put(self, logger):
+    def put(self):
         """
         Upload a file and automatically create a new upload in the process.
         Can be used to upload files via browser or other http clients like curl.
@@ -252,7 +252,7 @@ class UploadListResource(Resource):
         upload_name = request.args.get('name')
         upload_id = utils.create_uuid()
 
-        logger = logger.bind(upload_id=upload_id, upload_name=upload_name)
+        logger = common.logger.bind(upload_id=upload_id, upload_name=upload_name)
         logger.info('upload created', )
 
         try:
@@ -397,8 +397,7 @@ class UploadResource(Resource):
     @api.response(400, 'The upload is still/already processed')
     @api.marshal_with(upload_model, skip_none=True, code=200, description='Upload deleted')
     @authenticate(required=True)
-    @with_logger
-    def delete(self, upload_id: str, logger):
+    def delete(self, upload_id: str):
         """
         Delete an existing upload.
 
@@ -424,7 +423,7 @@ class UploadResource(Resource):
         except ProcessAlreadyRunning:
             abort(400, message='The upload is still processed')
         except Exception as e:
-            logger.error('could not delete processing upload', exc_info=e)
+            common.logger.error('could not delete processing upload', exc_info=e)
             raise e
 
         return upload, 200

nomad/app/utils.py → nomad/app/common.py

@@ -12,47 +12,19 @@
 # See the License for the specific language governing permissions and
 # limitations under the License.
 
-from werkzeug.exceptions import HTTPException
+from structlog import BoundLogger
 from flask_restplus import fields
 from datetime import datetime
 import pytz
-import inspect
 
-from nomad import utils
+from nomad import config
 
 
-def with_logger(func):
-    """
-    Decorator for endpoint implementations that provides a pre configured logger and
-    automatically logs errors on all 500 responses.
-    """
-    signature = inspect.signature(func)
-    has_logger = 'logger' in signature.parameters
-    wrapper_signature = signature.replace(parameters=tuple(
-        param for param in signature.parameters.values()
-        if param.name != 'logger'
-    ))
+logger: BoundLogger = None
+""" A logger pre configured with information about the current request. """
 
-    def wrapper(*args, **kwargs):
-        if has_logger:
-            args = inspect.getcallargs(wrapper, *args, **kwargs)
-            logger_args = {
-                k: v for k, v in args.items()
-                if k in ['upload_id', 'calc_id']}
-            logger = utils.get_logger(__name__, **logger_args)
-            args.update(logger=logger)
-        try:
-            return func(**args)
-        except HTTPException as e:
-            if getattr(e, 'code', None) == 500:
-                logger.error('Internal server error', exc_info=e)
-            raise e
-        except Exception as e:
-            logger.error('Internal server error', exc_info=e)
-            raise e
-
-    wrapper.__signature__ = wrapper_signature
-    return wrapper
+base_path = config.services.api_base_path
+""" Provides the root path of the nomad APIs. """
 
 
 class RFC3339DateTime(fields.DateTime):

nomad/app/optimade/api.py

@@ -44,3 +44,10 @@ api = Api(
     description='NOMAD\'s OPTiMaDe API implementation, version 0.10.0.',
     validate=True)
 """ Provides the flask restplust api instance for the optimade api"""
+
+
+# For some unknown reason it is necessary for each fr api to have a handler.
+# Otherwise the global app error handler won't be called.
+@api.errorhandler(Exception)
+def errorhandler(error):
+    return str(error)

nomad/app/optimade/models.py

@@ -22,7 +22,7 @@ import datetime
 import math
 
 from nomad import config
-from nomad.app.utils import RFC3339DateTime
+from nomad.app.common import RFC3339DateTime
 from nomad.datamodel import CalcWithMetadata
 
 from .api import api, base_url, url

nomad/metainfo/flask_restplus.py

 from flask_restplus import fields
 
-from nomad.app.utils import RFC3339DateTime
+from nomad.app.common import RFC3339DateTime
 
 from .metainfo import Section, Quantity, Datetime
 

tests/app/test_api.py

@@ -25,7 +25,7 @@ from urllib.parse import urlencode
 import base64
 import itertools
 
-from nomad.app.utils import rfc3339DateTime
+from nomad.app.common import rfc3339DateTime
 from nomad.app.api.auth import generate_upload_token
 from nomad import search, parsing, files, config, utils, infrastructure
 from nomad.files import UploadFiles, PublicUploadFiles