Improved wrapped logging #187

.gitignore

@@ -139,3 +139,6 @@ PythonImportHelper-v2-Completion.json
 
 # cpl unittest stuff
 unittests/test_*_playground
+
+# cpl logs
+**/logs/*.jsonl

src/cpl-api/cpl/api/application/web_app.py

@@ -203,7 +203,7 @@ class WebApp(ApplicationABC):
 
                 _policies.append(policy)
 
-            self._policies.extend_policies(_policies)
+            self._policies.extend(_policies)
 
         self.with_middleware(AuthorizationMiddleware)
         return self

src/cpl-api/cpl/api/logger.py

@@ -1,8 +1,7 @@
-from cpl.core.log import LoggerABC
 from cpl.core.log.wrapped_logger import WrappedLogger
 
 
 class APILogger(WrappedLogger):
 
-    def __init__(self, logger: LoggerABC):
-        WrappedLogger.__init__(self, logger)
+    def __init__(self):
+        WrappedLogger.__init__(self, "api")

src/cpl-api/cpl/api/model/policy.py

@@ -1,5 +1,5 @@
 from asyncio import iscoroutinefunction
-from typing import Optional, Any, Coroutine, Awaitable
+from typing import Optional
 
 from cpl.api.typing import PolicyResolver
 from cpl.core.ctx import get_user

src/cpl-api/cpl/api/registry/route.py

@@ -1,6 +1,5 @@
 from typing import Optional
 
-from cpl.api.model.policy import Policy
 from cpl.api.model.api_route import ApiRoute
 from cpl.core.abc.registry_abc import RegistryABC
 

src/cpl-application/cpl/application/abc/application_abc.py

@@ -5,7 +5,6 @@ from cpl.application.host import Host
 from cpl.core.log.log_level import LogLevel
 from cpl.core.log.log_settings import LogSettings
 from cpl.core.log.logger_abc import LoggerABC
-from cpl.core.log.structured_logger import StructuredLogger
 from cpl.dependency.service_provider_abc import ServiceProviderABC
 
 

src/cpl-application/cpl/application/abc/application_extension_abc.py

@@ -1,6 +1,6 @@
 from abc import ABC, abstractmethod
 
-from cpl.dependency import ServiceProviderABC
+from cpl.dependency.service_provider_abc import ServiceProviderABC
 
 
 class ApplicationExtensionABC(ABC):

src/cpl-auth/cpl/auth/__init__.py

@@ -6,7 +6,7 @@ from cpl.auth import permission as _permission
 from cpl.auth.keycloak.keycloak_admin import KeycloakAdmin as _KeycloakAdmin
 from cpl.auth.keycloak.keycloak_client import KeycloakClient as _KeycloakClient
 from cpl.dependency.service_collection import ServiceCollection as _ServiceCollection
-from .auth_logger import AuthLogger
+from .logger import AuthLogger
 from .keycloak_settings import KeycloakSettings
 from .permission_seeder import PermissionSeeder
 

src/cpl-auth/cpl/auth/auth_logger.py

@@ -1,8 +0,0 @@
-from cpl.core.log import LoggerABC
-from cpl.core.log.wrapped_logger import WrappedLogger
-
-
-class AuthLogger(WrappedLogger):
-
-    def __init__(self, logger: LoggerABC):
-        WrappedLogger.__init__(self, logger)

src/cpl-auth/cpl/auth/keycloak/keycloak_admin.py

@@ -1,13 +1,13 @@
 from keycloak import KeycloakAdmin as _KeycloakAdmin, KeycloakOpenIDConnection
 
-from cpl.auth.auth_logger import AuthLogger
 from cpl.auth.keycloak_settings import KeycloakSettings
+from cpl.auth.logger import AuthLogger
 
 
 class KeycloakAdmin(_KeycloakAdmin):
 
     def __init__(self, logger: AuthLogger, settings: KeycloakSettings):
-        logger.info("Initializing Keycloak admin")
+        # logger.info("Initializing Keycloak admin")
         _connection = KeycloakOpenIDConnection(
             server_url=settings.url,
             client_id=settings.client_id,

src/cpl-auth/cpl/auth/keycloak/keycloak_client.py

@@ -2,7 +2,7 @@ from typing import Optional
 
 from keycloak import KeycloakOpenID
 
-from cpl.auth.auth_logger import AuthLogger
+from cpl.auth.logger import AuthLogger
 from cpl.auth.keycloak_settings import KeycloakSettings
 
 

src/cpl-auth/cpl/auth/logger.py

@@ -0,0 +1,7 @@
+from cpl.core.log.wrapped_logger import WrappedLogger
+
+
+class AuthLogger(WrappedLogger):
+
+    def __init__(self):
+        WrappedLogger.__init__(self, "auth")

src/cpl-auth/cpl/auth/permission_seeder.py

@@ -14,7 +14,7 @@ from cpl.auth.schema import (
 )
 from cpl.core.utils.get_value import get_value
 from cpl.database.abc.data_seeder_abc import DataSeederABC
-from cpl.database.db_logger import DBLogger
+from cpl.database.logger import DBLogger
 
 
 class PermissionSeeder(DataSeederABC):

src/cpl-auth/cpl/auth/schema/_administration/auth_user.py

@@ -9,7 +9,7 @@ from cpl.auth.keycloak import KeycloakAdmin
 from cpl.auth.permission.permissions import Permissions
 from cpl.core.typing import SerialId
 from cpl.database.abc import DbModelABC
-from cpl.database.db_logger import DBLogger
+from cpl.database.logger import DBLogger
 from cpl.dependency import ServiceProviderABC
 
 
@@ -36,8 +36,8 @@ class AuthUser(DbModelABC):
             return "ANONYMOUS"
 
         try:
-            keycloak_admin: KeycloakAdmin = ServiceProviderABC.get_global_service(KeycloakAdmin)
-            return keycloak_admin.get_user(self._keycloak_id).get("username")
+            keycloak = ServiceProviderABC.get_global_service(KeycloakAdmin)
+            return keycloak.get_user(self._keycloak_id).get("username")
         except KeycloakGetError as e:
             return "UNKNOWN"
         except Exception as e:
@@ -51,8 +51,8 @@ class AuthUser(DbModelABC):
             return "ANONYMOUS"
 
         try:
-            keycloak_admin: KeycloakAdmin = ServiceProviderABC.get_global_service(KeycloakAdmin)
-            return keycloak_admin.get_user(self._keycloak_id).get("email")
+            keycloak = ServiceProviderABC.get_global_service(KeycloakAdmin)
+            return keycloak.get_user(self._keycloak_id).get("email")
         except KeycloakGetError as e:
             return "UNKNOWN"
         except Exception as e:

src/cpl-core/cpl/core/ctx/user_context.py

@@ -6,13 +6,13 @@ from cpl.auth.schema._administration.auth_user import AuthUser
 _user_context: ContextVar[Optional[AuthUser]] = ContextVar("user", default=None)
 
 
-def set_user(user_id: Optional[AuthUser]):
+def set_user(user: Optional[AuthUser]):
     from cpl.dependency.service_provider_abc import ServiceProviderABC
     from cpl.core.log.logger_abc import LoggerABC
 
     logger = ServiceProviderABC.get_global_service(LoggerABC)
-    logger.trace("Setting user context", user_id)
-    _user_context.set(user_id)
+    logger.trace("Setting user context", user.id)
+    _user_context.set(user)
 
 
 def get_user() -> Optional[AuthUser]:

src/cpl-core/cpl/core/log/structured_logger.py

@@ -1,9 +1,13 @@
 import asyncio
 import importlib.util
+import json
 import traceback
 from datetime import datetime
 
-from cpl.core.log import Logger, LogLevel
+from starlette.requests import Request
+
+from cpl.core.log.log_level import LogLevel
+from cpl.core.log.logger import Logger
 from cpl.core.typing import Source, Messages
 
 
@@ -20,8 +24,9 @@ class StructuredLogger(Logger):
         try:
             timestamp = datetime.now().strftime("%Y-%m-%d %H:%M:%S.%f")
             formatted_message = self._format_message(level.value, timestamp, *messages)
+            structured_message = self._get_structured_message(level.value, timestamp, formatted_message)
 
-            self._write_log_to_file(level, formatted_message)
+            self._write_log_to_file(level, structured_message)
             self._write_to_console(level, formatted_message)
         except Exception as e:
             print(f"Error while logging: {e} -> {traceback.format_exc()}")
@@ -37,10 +42,31 @@ class StructuredLogger(Logger):
         self._enrich_message_with_request(structured_message)
         self._enrich_message_with_user(structured_message)
 
-        return str(structured_message)
+        return json.dumps(structured_message, ensure_ascii=False)
 
     @staticmethod
-    def _enrich_message_with_request(message: dict):
+    def _scope_to_json(request: Request, include_headers: bool = False) -> dict:
+        scope = dict(request.scope)
+
+        def convert(value):
+            if isinstance(value, bytes):
+                return value.decode("utf-8")
+            if isinstance(value, (list, tuple)):
+                return [convert(v) for v in value]
+            if isinstance(value, dict):
+                return {str(k): convert(v) for k, v in value.items()}
+            if not isinstance(value, (str, int, float, bool, type(None))):
+                return str(value)
+            return value
+
+        serializable_scope = {str(k): convert(v) for k, v in scope.items()}
+
+        if not include_headers and "headers" in serializable_scope:
+            serializable_scope["headers"] = "<omitted>"
+
+        return serializable_scope
+
+    def _enrich_message_with_request(self, message: dict):
         if importlib.util.find_spec("cpl.api") is None:
             return
 
@@ -55,7 +81,7 @@ class StructuredLogger(Logger):
         message["request"] = {
             "url": str(request.url),
             "method": request.method,
-            "scope": request.scope,
+            "scope": self._scope_to_json(request),
         }
         if isinstance(request, Request) and request.scope == "http":
             request: Request = request  # fix typing for IDEs
@@ -73,8 +99,13 @@ class StructuredLogger(Logger):
         if user is None:
             return
 
+        from cpl.dependency.service_provider_abc import ServiceProviderABC
+        from cpl.auth.keycloak.keycloak_admin import KeycloakAdmin
+
+        keycloak = ServiceProviderABC.get_global_service(KeycloakAdmin)
+        kc_user = keycloak.get_user(user.keycloak_id)
         message["user"] = {
             "id": str(user.id),
-            "username": user.username,
-            "email": user.email,
+            "username": kc_user.get("username"),
+            "email": kc_user.get("email"),
         }

src/cpl-core/cpl/core/log/wrapped_logger.py

@@ -1,13 +1,28 @@
+import inspect
+
 from cpl.core.log import LoggerABC, LogLevel
-from cpl.core.typing import Messages
+from cpl.core.typing import Messages, Source
+from cpl.dependency.service_provider_abc import ServiceProviderABC
 
 
 class WrappedLogger(LoggerABC):
 
-    def __init__(self, logger: LoggerABC):
+    def __init__(self, file_prefix: str):
         LoggerABC.__init__(self)
-        assert isinstance(logger, LoggerABC), "logger must be an instance of LoggerABC"
-        self._logger = logger
+        assert file_prefix is not None and file_prefix != "", "file_prefix must be a non-empty string"
+
+        t_logger = ServiceProviderABC.get_global_service(LoggerABC)
+        self._t_logger = type(t_logger) if t_logger is not None else None
+        self._source = None
+        self._file_prefix = file_prefix
+
+        self._set_logger()
+
+    def _set_logger(self):
+        if self._t_logger is None:
+            raise Exception("No LoggerABC service registered in ServiceProviderABC")
+
+        self._logger = self._t_logger(self._source, self._file_prefix)
 
     def set_level(self, level: LogLevel):
         self._logger.set_level(level)
@@ -15,23 +30,68 @@ class WrappedLogger(LoggerABC):
     def _format_message(self, level: str, timestamp, *messages: Messages) -> str:
         return self._logger._format_message(level, timestamp, *messages)
 
+    @staticmethod
+    def _get_source() -> str | None:
+        stack = inspect.stack()
+        if len(stack) <= 1:
+            return None
+
+        from cpl.dependency import ServiceCollection
+        ignore_classes = [
+            ServiceProviderABC,
+            ServiceProviderABC.__subclasses__(),
+            ServiceCollection,
+
+            WrappedLogger,
+            WrappedLogger.__subclasses__()
+        ]
+
+        ignore_modules = [x.__module__ for x in ignore_classes if isinstance(x, type)]
+
+        for i, frame_info in enumerate(stack[1:]):
+            module = inspect.getmodule(frame_info.frame)
+            if module is None:
+                continue
+
+            if module.__name__ in ignore_classes or module in ignore_classes:
+                continue
+
+            if module in ignore_modules or module.__name__ in ignore_modules:
+                continue
+
+            if module.__name__ != __name__:
+                return module.__name__
+
+        return None
+
+    def _set_source(self):
+        self._source = self._get_source()
+        self._set_logger()
+
     def header(self, string: str):
+        self._set_source()
         self._logger.header(string)
 
     def trace(self, *messages: Messages):
+        self._set_source()
         self._logger.trace(*messages)
 
     def debug(self, *messages: Messages):
+        self._set_source()
         self._logger.debug(*messages)
 
     def info(self, *messages: Messages):
+        self._set_source()
         self._logger.info(*messages)
 
     def warning(self, *messages: Messages):
+        self._set_source()
         self._logger.warning(*messages)
 
     def error(self, messages: str, e: Exception = None):
+        self._set_source()
         self._logger.error(messages, e)
 
     def fatal(self, messages: str, e: Exception = None):
+        self._set_source()
         self._logger.fatal(messages, e)

src/cpl-database/cpl/database/abc/data_access_object_abc.py

@@ -9,7 +9,7 @@ from cpl.core.utils.get_value import get_value
 from cpl.core.utils.string import String
 from cpl.database.abc.db_context_abc import DBContextABC
 from cpl.database.const import DATETIME_FORMAT
-from cpl.database.db_logger import DBLogger
+from cpl.database.logger import DBLogger
 from cpl.database.external_data_temp_table_builder import ExternalDataTempTableBuilder
 from cpl.database.postgres.sql_select_builder import SQLSelectBuilder
 from cpl.database.typing import T_DBM, Attribute, AttributeFilters, AttributeSorts

src/cpl-database/cpl/database/db_logger.py

@@ -1,8 +0,0 @@
-from cpl.core.log import LoggerABC
-from cpl.core.log.wrapped_logger import WrappedLogger
-
-
-class DBLogger(WrappedLogger):
-
-    def __init__(self, logger: LoggerABC):
-        WrappedLogger.__init__(self, logger)

src/cpl-database/cpl/database/logger.py

@@ -0,0 +1,7 @@
+from cpl.core.log.wrapped_logger import WrappedLogger
+
+
+class DBLogger(WrappedLogger):
+
+    def __init__(self):
+        WrappedLogger.__init__(self, "db")

src/cpl-database/cpl/database/mysql/db_context.py

@@ -5,7 +5,7 @@ from mysql.connector import Error as MySQLError, PoolError
 
 from cpl.core.configuration import Configuration
 from cpl.database.abc.db_context_abc import DBContextABC
-from cpl.database.db_logger import DBLogger
+from cpl.database.logger import DBLogger
 from cpl.database.model.database_settings import DatabaseSettings
 from cpl.database.mysql.mysql_pool import MySQLPool
 

src/cpl-database/cpl/database/mysql/mysql_pool.py

@@ -4,7 +4,7 @@ import sqlparse
 from mysql.connector.aio import MySQLConnectionPool
 
 from cpl.core.environment import Environment
-from cpl.database.db_logger import DBLogger
+from cpl.database.logger import DBLogger
 from cpl.database.model import DatabaseSettings
 from cpl.dependency import ServiceProviderABC
 

src/cpl-database/cpl/database/postgres/db_context.py

@@ -7,7 +7,7 @@ from psycopg_pool import PoolTimeout
 from cpl.core.configuration import Configuration
 from cpl.core.environment import Environment
 from cpl.database.abc.db_context_abc import DBContextABC
-from cpl.database.db_logger import DBLogger
+from cpl.database.logger import DBLogger
 from cpl.database.model import DatabaseSettings
 from cpl.database.postgres.postgres_pool import PostgresPool
 

src/cpl-database/cpl/database/postgres/postgres_pool.py

@@ -5,7 +5,7 @@ from psycopg import sql
 from psycopg_pool import AsyncConnectionPool, PoolTimeout
 
 from cpl.core.environment import Environment
-from cpl.database.db_logger import DBLogger
+from cpl.database.logger import DBLogger
 from cpl.database.model import DatabaseSettings
 from cpl.dependency import ServiceProviderABC
 

src/cpl-database/cpl/database/service/migration_service.py

@@ -2,7 +2,7 @@ import glob
 import os
 
 from cpl.database.abc import DBContextABC
-from cpl.database.db_logger import DBLogger
+from cpl.database.logger import DBLogger
 from cpl.database.model import Migration
 from cpl.database.model.server_type import ServerType, ServerTypes
 from cpl.database.schema.executed_migration import ExecutedMigration

src/cpl-database/cpl/database/service/seeder_service.py

@@ -1,5 +1,5 @@
 from cpl.database.abc.data_seeder_abc import DataSeederABC
-from cpl.database.db_logger import DBLogger
+from cpl.database.logger import DBLogger
 from cpl.dependency import ServiceProviderABC
 
 

src/cpl-dependency/cpl/dependency/service_collection.py

@@ -1,9 +1,6 @@
 from typing import Union, Type, Callable, Self
 
-from cpl.core.log.logger import Logger
 from cpl.core.log.logger_abc import LoggerABC
-from cpl.core.log.structured_logger import StructuredLogger
-from cpl.core.log.wrapped_logger import WrappedLogger
 from cpl.core.typing import T, Service
 from cpl.dependency.service_descriptor import ServiceDescriptor
 from cpl.dependency.service_lifetime_enum import ServiceLifetimeEnum
@@ -82,14 +79,20 @@ class ServiceCollection:
         return self
 
     def add_logging(self) -> Self:
+        from cpl.core.log.logger import Logger
+        from cpl.core.log.wrapped_logger import WrappedLogger
+
         self.add_transient(LoggerABC, Logger)
-        return self
-
-    def add_structured_logging(self) -> Self:
-        self.add_transient(LoggerABC, StructuredLogger)
-        return self
-
-    def add_wrapped_logging(self) -> Self:
+        for wrapper in WrappedLogger.__subclasses__():
+            self.add_transient(wrapper)
+        return self
+
+    def add_structured_logging(self) -> Self:
+        from cpl.core.log.structured_logger import StructuredLogger
+        from cpl.core.log.wrapped_logger import WrappedLogger
+
+        self.add_transient(LoggerABC, StructuredLogger)
+
         for wrapper in WrappedLogger.__subclasses__():
             self.add_transient(wrapper)
         return self

src/cpl-mail/cpl/mail/__init__.py

@@ -3,7 +3,7 @@ from .abc.email_client_abc import EMailClientABC
 from .email_client import EMailClient
 from .email_client_settings import EMailClientSettings
 from .email_model import EMail
-from .mail_logger import MailLogger
+from .logger import MailLogger
 
 
 def add_mail(collection: _ServiceCollection):

src/cpl-mail/cpl/mail/email_client.py

@@ -5,7 +5,7 @@ from typing import Optional
 from cpl.mail.abc.email_client_abc import EMailClientABC
 from cpl.mail.email_client_settings import EMailClientSettings
 from cpl.mail.email_model import EMail
-from cpl.mail.mail_logger import MailLogger
+from cpl.mail.logger import MailLogger
 
 
 class EMailClient(EMailClientABC):

src/cpl-mail/cpl/mail/logger.py

@@ -0,0 +1,7 @@
+from cpl.core.log.wrapped_logger import WrappedLogger
+
+
+class MailLogger(WrappedLogger):
+
+    def __init__(self):
+        WrappedLogger.__init__(self, "mail")

src/cpl-mail/cpl/mail/mail_logger.py

@@ -1,8 +0,0 @@
-from cpl.core.log import LoggerABC
-from cpl.core.log.wrapped_logger import WrappedLogger
-
-
-class MailLogger(WrappedLogger):
-
-    def __init__(self, logger: LoggerABC):
-        WrappedLogger.__init__(self, logger)

tests/custom/api/src/main.py

@@ -16,8 +16,8 @@ def main():
     Configuration.add_json_file(f"appsettings.{Environment.get_environment()}.json")
     Configuration.add_json_file(f"appsettings.{Environment.get_host_name()}.json", optional=True)
 
+    # builder.services.add_logging()
     builder.services.add_structured_logging()
-    builder.services.add_wrapped_logging()
     builder.services.add_transient(PingService)
     builder.services.add_module(api)
 

tests/custom/api/src/routes/ping.py

@@ -1,17 +1,16 @@
 from urllib.request import Request
 
+from service import PingService
 from starlette.responses import JSONResponse
 
+from cpl.api import APILogger
 from cpl.api.router import Router
-from cpl.auth.permission.permissions import Permissions
-from cpl.core.log import Logger
-from service import PingService
 
 
 @Router.authenticate()
-@Router.authorize(permissions=[Permissions.administrator])
+# @Router.authorize(permissions=[Permissions.administrator])
 # @Router.authorize(policies=["test"])
 @Router.get(f"/ping")
-async def ping(r: Request, ping: PingService, logger: Logger):
+async def ping(r: Request, ping: PingService, logger: APILogger):
     logger.info(f"Ping: {ping}")
     return JSONResponse(ping.ping(r))