feat(#1029): improve server api logging (#1148)

* feat(logging): improve server api logging

* chore: rubrix:app

* chore: conditional logging configuration if module loguru not found

* chore: rename logging handler

* test: logging handler is configured properly

* chore: better warning message

(cherry picked from commit 18efbfb)

chore(#1029): generalize logging configuration message (#1224)

(cherry picked from commit c390911)

environment_dev.yml

@@ -11,6 +11,7 @@ dependencies:
   # tests
   - pytest
   - pytest-cov
+  - pytest-mock
   - pytest-asyncio
   # docs, pandoc needs conda ...
   - pandoc==2.12

setup.cfg

@@ -51,6 +51,8 @@ server =
     smart-open
     brotli-asgi ~= 1.1.0
     Deprecated ~= 1.2.0
+    # logging
+    loguru ~= 0.6.0
     # Advanced query search dsl
     luqum ~= 0.11.0
     # metrics

src/rubrix/logging.py

@@ -21,6 +21,11 @@
 from logging import Logger
 from typing import Type
 
+try:
+    from loguru import logger
+except ModuleNotFoundError:
+    logger = None
+
 
 def full_qualified_class_name(_class: Type) -> str:
     """Calculates the full qualified name (module + class) of a class"""
@@ -53,3 +58,48 @@ def __new__(cls, *args, **kwargs):
     def logger(self) -> logging.Logger:
         """Return the logger configured for the class"""
         return self.__logger__
+
+
+class LoguruLoggerHandler(logging.Handler):
+    """This logging handler enables an easy way to use loguru fo all built-in logger traces"""
+
+    __LOGLEVEL_MAPPING__ = {
+        50: "CRITICAL",
+        40: "ERROR",
+        30: "WARNING",
+        20: "INFO",
+        10: "DEBUG",
+        0: "NOTSET",
+    }
+
+    @property
+    def is_available(self) -> bool:
+        """Return True if handler can tackle log records. False otherwise"""
+        return logger is not None
+
+    def __init__(self, *args, **kwargs):
+        super().__init__(*args, **kwargs)
+
+        if not self.is_available:
+            logging.getLogger(__name__).warning(
+                "Cannot find required package for logging.\n"
+                "Please, install `loguru` by typing:\n"
+                "pip install loguru\n"
+                "if you want to enable enhanced logging"
+            )
+            self.emit = lambda record: None
+
+    def emit(self, record: logging.LogRecord):
+
+        try:
+            level = logger.level(record.levelname).name
+        except AttributeError:
+            level = self.__LOGLEVEL_MAPPING__[record.levelno]
+
+        frame, depth = logging.currentframe(), 2
+        while frame.f_code.co_filename == logging.__file__:
+            frame = frame.f_back
+            depth += 1
+
+        log = logger.bind(request_id="rubrix")
+        log.opt(depth=depth, exception=record.exc_info).log(level, record.getMessage())

src/rubrix/server/__main__.py

@@ -24,7 +24,7 @@
     )
 
     uvicorn.run(
-        "rubrix.server.server:app",
+        "rubrix:app",
         port=6900,
         host="0.0.0.0",
         access_log=True,

src/rubrix/server/server.py

@@ -16,7 +16,7 @@
 """
 This module configures the global fastapi application
 """
-
+import logging
 import os
 from pathlib import Path
 
@@ -33,6 +33,7 @@
 from rubrix.server.security import auth
 from rubrix.server.tasks.commons.dao.dao import DatasetRecordsDAO
 
+from ..logging import LoguruLoggerHandler
 from .commons.errors import APIErrorHandler
 from .commons.settings import settings
 from .commons.settings import settings as api_settings
@@ -84,7 +85,7 @@ def configure_app_statics(app: FastAPI):
     )
 
 
-def configure_app_startup(app: FastAPI):
+def configure_app_storage(app: FastAPI):
     @app.on_event("startup")
     async def configure_elasticsearch():
         import opensearchpy
@@ -113,6 +114,34 @@ def configure_app_security(app: FastAPI):
         app.include_router(auth.router)
 
 
+def configure_app_logging(app: FastAPI):
+    """Configure app logging using"""
+    intercept_handler = LoguruLoggerHandler()
+
+    if not intercept_handler.is_available:
+        return
+
+    def _inner_logging_config():
+        logging.basicConfig(handlers=[intercept_handler], level=logging.WARNING)
+        for name in logging.root.manager.loggerDict:
+            logger = logging.getLogger(name)
+            logger.handlers = []
+
+        for name in [
+            "uvicorn",
+            "uvicorn.lifespan",
+            "uvicorn.error",
+            "uvicorn.access",
+            "fastapi",
+        ]:
+            logger = logging.getLogger(name)
+            logger.propagate = False
+            logger.handlers = [intercept_handler]
+
+    _inner_logging_config()
+    app.on_event("startup")(_inner_logging_config)
+
+
 app = FastAPI(
     title="Rubrix",
     description="Rubrix API",
@@ -124,11 +153,12 @@ def configure_app_security(app: FastAPI):
 )
 
 for app_configure in [
+    configure_app_logging,
     configure_middleware,
     configure_api_exceptions,
     configure_app_security,
     configure_api_router,
     configure_app_statics,
-    configure_app_startup,
+    configure_app_storage,
 ]:
     app_configure(app)

tests/test_logging.py

@@ -12,8 +12,9 @@
 #  WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
 #  See the License for the specific language governing permissions and
 #  limitations under the License.
+import logging
 
-from rubrix.logging import LoggingMixin
+from rubrix.logging import LoggingMixin, LoguruLoggerHandler
 
 
 class LoggingForTest(LoggingMixin):
@@ -46,3 +47,14 @@ def test_logging_mixin_without_breaking_constructors():
     another_child = LoggingForTestChild(a=15)
     # Check logger without call property method
     assert another_child.__getattribute__("__logger__") == child.logger
+
+
+def test_logging_handler(mocker):
+    mocker.patch.object(LoguruLoggerHandler, "emit", autospec=True)
+    handler = LoguruLoggerHandler()
+
+    logger = logging.getLogger(__name__)
+    logger.handlers = [handler]
+    logger.setLevel(logging.INFO)  # Force trace
+    logger.info("This is a test")
+    handler.emit.assert_called_once()