From 937ef3eb68d83b5d9d0ec388d1bd2db88e99e622 Mon Sep 17 00:00:00 2001 From: Francisco Aranda Date: Mon, 14 Feb 2022 13:10:42 +0100 Subject: [PATCH 1/6] feat(logging): improve server api logging --- setup.cfg | 2 ++ src/rubrix/logging.py | 29 +++++++++++++++++++++++++++++ src/rubrix/server/server.py | 29 ++++++++++++++++++++++++++++- 3 files changed, 59 insertions(+), 1 deletion(-) diff --git a/setup.cfg b/setup.cfg index 4a65d7698a..2ea59371c7 100644 --- a/setup.cfg +++ b/setup.cfg @@ -51,6 +51,8 @@ server = smart-open brotli-asgi ~= 1.1.0 Deprecated ~= 1.2.0 + # logging + loguru ~= 0.6.0 # metrics scikit-learn >= 0.24.2 # Words cloud diff --git a/src/rubrix/logging.py b/src/rubrix/logging.py index abea5c018c..8672049102 100644 --- a/src/rubrix/logging.py +++ b/src/rubrix/logging.py @@ -53,3 +53,32 @@ def __new__(cls, *args, **kwargs): def logger(self) -> logging.Logger: """Return the logger configured for the class""" return self.__logger__ + + +class InterceptHandler(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", + } + + def emit(self, record): + from loguru import logger + + 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="app") + log.opt(depth=depth, exception=record.exc_info).log(level, record.getMessage()) diff --git a/src/rubrix/server/server.py b/src/rubrix/server/server.py index 2f467596f1..8c51b54bc4 100644 --- a/src/rubrix/server/server.py +++ b/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 InterceptHandler from .commons.errors import APIErrorHandler from .commons.settings import settings from .commons.settings import settings as api_settings @@ -114,6 +115,31 @@ def configure_app_security(app: FastAPI): app.include_router(auth.router) +def configure_app_logging(app: FastAPI): + """Configure app logging using""" + intercept_handler = InterceptHandler() + + 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", @@ -125,6 +151,7 @@ def configure_app_security(app: FastAPI): ) for app_configure in [ + configure_app_logging, configure_middleware, configure_api_exceptions, configure_app_security, From b71662d1ed15a0847f21c9b1e1c215f8a3da804c Mon Sep 17 00:00:00 2001 From: Francisco Aranda Date: Mon, 14 Feb 2022 13:13:31 +0100 Subject: [PATCH 2/6] chore: rubrix:app --- src/rubrix/server/__main__.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/rubrix/server/__main__.py b/src/rubrix/server/__main__.py index d3eb390fcc..32e12b8d30 100644 --- a/src/rubrix/server/__main__.py +++ b/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, From 0b285955da8a0b24ca93a1d05ac35405adc8978a Mon Sep 17 00:00:00 2001 From: Francisco Aranda Date: Mon, 14 Feb 2022 16:02:20 +0100 Subject: [PATCH 3/6] chore: conditional logging configuration if module loguru not found --- src/rubrix/logging.py | 23 +++++++++++++++++++++-- src/rubrix/server/server.py | 7 +++++-- 2 files changed, 26 insertions(+), 4 deletions(-) diff --git a/src/rubrix/logging.py b/src/rubrix/logging.py index 8672049102..64b5f32a55 100644 --- a/src/rubrix/logging.py +++ b/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""" @@ -67,8 +72,22 @@ class InterceptHandler(logging.Handler): 0: "NOTSET", } - def emit(self, record): - from loguru import logger + @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` if you want to enable server api logging" + ) + self.emit = lambda record: None + + def emit(self, record: logging.LogRecord): try: level = logger.level(record.levelname).name diff --git a/src/rubrix/server/server.py b/src/rubrix/server/server.py index 8c51b54bc4..773e2633e0 100644 --- a/src/rubrix/server/server.py +++ b/src/rubrix/server/server.py @@ -85,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 @@ -119,6 +119,9 @@ def configure_app_logging(app: FastAPI): """Configure app logging using""" intercept_handler = InterceptHandler() + 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: @@ -157,6 +160,6 @@ def _inner_logging_config(): configure_app_security, configure_api_router, configure_app_statics, - configure_app_startup, + configure_app_storage, ]: app_configure(app) From 163be6efb235927f6c4230ca6da1900ca62ab5ab Mon Sep 17 00:00:00 2001 From: Francisco Aranda Date: Mon, 14 Feb 2022 16:34:35 +0100 Subject: [PATCH 4/6] chore: rename logging handler --- src/rubrix/logging.py | 2 +- src/rubrix/server/server.py | 4 ++-- 2 files changed, 3 insertions(+), 3 deletions(-) diff --git a/src/rubrix/logging.py b/src/rubrix/logging.py index 64b5f32a55..8693646411 100644 --- a/src/rubrix/logging.py +++ b/src/rubrix/logging.py @@ -60,7 +60,7 @@ def logger(self) -> logging.Logger: return self.__logger__ -class InterceptHandler(logging.Handler): +class LoguruLoggerHandler(logging.Handler): """This logging handler enables an easy way to use loguru fo all built-in logger traces""" __LOGLEVEL_MAPPING__ = { diff --git a/src/rubrix/server/server.py b/src/rubrix/server/server.py index 773e2633e0..3907cebfc2 100644 --- a/src/rubrix/server/server.py +++ b/src/rubrix/server/server.py @@ -33,7 +33,7 @@ from rubrix.server.security import auth from rubrix.server.tasks.commons.dao.dao import DatasetRecordsDAO -from ..logging import InterceptHandler +from ..logging import LoguruLoggerHandler from .commons.errors import APIErrorHandler from .commons.settings import settings from .commons.settings import settings as api_settings @@ -117,7 +117,7 @@ def configure_app_security(app: FastAPI): def configure_app_logging(app: FastAPI): """Configure app logging using""" - intercept_handler = InterceptHandler() + intercept_handler = LoguruLoggerHandler() if not intercept_handler.is_available: return From 5a8bc35d61da0d5b88bbb0f70f2d48d2e3cd5f73 Mon Sep 17 00:00:00 2001 From: Francisco Aranda Date: Mon, 14 Feb 2022 16:35:09 +0100 Subject: [PATCH 5/6] test: logging handler is configured properly --- environment_dev.yml | 1 + tests/test_logging.py | 14 +++++++++++++- 2 files changed, 14 insertions(+), 1 deletion(-) diff --git a/environment_dev.yml b/environment_dev.yml index f9f24eb284..fa5b564aaf 100644 --- a/environment_dev.yml +++ b/environment_dev.yml @@ -11,6 +11,7 @@ dependencies: # tests - pytest - pytest-cov + - pytest-mock - pytest-asyncio # docs, pandoc needs conda ... - pandoc==2.12 diff --git a/tests/test_logging.py b/tests/test_logging.py index 0f9336e781..144fc2b1fa 100644 --- a/tests/test_logging.py +++ b/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() From 29c50ea704adb14f5953b2899b064fc85aff4b1d Mon Sep 17 00:00:00 2001 From: Francisco Aranda Date: Mon, 14 Feb 2022 16:40:28 +0100 Subject: [PATCH 6/6] chore: better warning message --- src/rubrix/logging.py | 6 ++++-- 1 file changed, 4 insertions(+), 2 deletions(-) diff --git a/src/rubrix/logging.py b/src/rubrix/logging.py index 8693646411..5888f57dec 100644 --- a/src/rubrix/logging.py +++ b/src/rubrix/logging.py @@ -83,7 +83,9 @@ def __init__(self, *args, **kwargs): if not self.is_available: logging.getLogger(__name__).warning( "Cannot find required package for logging.\n" - "Please, install `loguru` if you want to enable server api logging" + "Please, install `loguru` by typing:\n" + "pip install loguru\n" + "if you want to enable enhanced server api logging" ) self.emit = lambda record: None @@ -99,5 +101,5 @@ def emit(self, record: logging.LogRecord): frame = frame.f_back depth += 1 - log = logger.bind(request_id="app") + log = logger.bind(request_id="rubrix") log.opt(depth=depth, exception=record.exc_info).log(level, record.getMessage())