fix logging with correlation_id, fix flaky test

Author: pgorecki

src/api/main.py

@@ -8,7 +8,6 @@
 from config.container import TopLevelContainer
 from seedwork.domain.exceptions import DomainException, EntityNotFoundException
 from seedwork.infrastructure.logging import LoggerFactory, logger
-from seedwork.infrastructure.request_context import request_context
 
 # configure logger prior to first usage
 LoggerFactory.configure(logger_name="api")

src/api/routers/catalog.py

@@ -15,7 +15,6 @@
 from modules.catalog.application.query.get_listing_details import GetListingDetails
 from seedwork.application import Application
 from seedwork.domain.value_objects import Money
-from seedwork.infrastructure.request_context import request_context
 
 """
 Inspired by https://developer.ebay.com/api-docs/sell/inventory/resources/offer/methods/createOffer

src/cli/__main__.py

@@ -55,7 +55,7 @@
         )
     )
 
-# use transaction context to acccess any dependency (i.e a repository, a service, etc.)
+# use transaction context to access any dependency (i.e a repository, a service, etc.)
 with app.transaction_context() as ctx:
     listing_repository = ctx.get_service(ListingRepository)
     listing_count = listing_repository.count()

src/config/container.py

@@ -104,23 +104,25 @@ def on_enter_transaction_context(ctx):
         engine = ctx.app.dependency_provider["db_engine"]
         session = Session(engine)
         correlation_id = uuid.uuid4()
+        logger.correlation_id.set(uuid.uuid4())
         transaction_container = TransactionContainer(
             db_session=session, correlation_id=correlation_id, logger=logger
         )
         ctx.dependency_provider = IocProvider(transaction_container)
-        logger.info(f"{id(session)} transaction started")
+        logger.debug(f"transaction started")
 
     @application.on_exit_transaction_context
     def on_exit_transaction_context(ctx, exc_type, exc_val, exc_tb):
         session = ctx.dependency_provider.get_dependency("db_session")
         if exc_type:
             session.rollback()
-            logger.info(f"{id(session)} rollback due to {exc_type}")
+            logger.debug(f"rollback due to {exc_type}")
         else:
             session.commit()
-            logger.info(f"{id(session)} committed")
+            logger.debug(f"committed")
         session.close()
-        logger.info(f"{id(session)} transaction ended ")
+        logger.debug(f"transaction ended ")
+        logger.correlation_id.set(uuid.UUID(int=0))
 
     @application.transaction_middleware
     def logging_middleware(ctx, next, command=None, query=None, event=None):

src/modules/bidding/tests/application/test_create_listing_when_draft_is_published.py

@@ -20,5 +20,5 @@ def test_create_listing_on_draft_published_event(app, engine):
         )
 
     with app.transaction_context() as ctx:
-        listing_repository = ctx.get_service(BiddingListingRepository)
+        listing_repository = ctx[BiddingListingRepository]
         assert listing_repository.count() == 1

src/seedwork/application/__init__.py

@@ -1,11 +1,8 @@
 import importlib
 import inspect
-import uuid
 from collections import defaultdict
 from functools import partial
-from typing import Dict, Type
-
-from sqlalchemy.orm import Session
+from typing import Any
 
 from seedwork.application.command_handlers import CommandResult
 from seedwork.application.commands import Command
@@ -16,8 +13,7 @@
 from seedwork.application.queries import Query
 from seedwork.application.query_handlers import QueryResult
 from seedwork.domain.events import DomainEvent
-from seedwork.infrastructure.logging import logger
-from seedwork.infrastructure.request_context import request_context
+from seedwork.utils.data_structures import OrderedSet
 
 
 def get_function_arguments(func):
@@ -187,9 +183,13 @@ def handle_domain_event(self, event) -> EventResultSet:
     def collect_integration_event(self, event):
         self.integration_events.append(event)
 
-    def get_service(self, service_cls):
+    def get_service(self, service_cls) -> Any:
+        """Get a dependency from the dependency provider"""
         return self.dependency_provider.get_dependency(service_cls)
 
+    def __getitem__(self, item) -> Any:
+        return self.get_service(item)
+
     @property
     def current_user(self):
         return self.dependency_provider.get_dependency("current_user")
@@ -201,7 +201,7 @@ def __init__(self, name, version=1.0):
         self.version = version
         self.command_handlers = {}
         self.query_handlers = {}
-        self.event_handlers = defaultdict(set)
+        self.event_handlers = defaultdict(OrderedSet)
 
     def query_handler(self, handler_func):
         """Query handler decorator"""

src/seedwork/infrastructure/logging.py

@@ -1,22 +1,27 @@
 import logging
+import uuid
+from contextvars import ContextVar
 from datetime import datetime
 from logging.config import dictConfig
 
 from pythonjsonlogger import jsonlogger
 
-from seedwork.infrastructure.request_context import request_context
 from seedwork.utils.functional import SimpleLazyObject
 
+correlation_id: ContextVar[uuid.UUID] = ContextVar(
+    "correlation_id", default=uuid.UUID("00000000-0000-0000-0000-000000000000")
+)
+
 
 class RequestContextFilter(logging.Filter):
     """ "Provides correlation id parameter for the logger"""
 
-    def __init__(self, name: str, request_context) -> None:
+    def __init__(self, name: str, correlation_id) -> None:
         super().__init__(name=name)
-        self.request_context = request_context
+        self.correlation_id = correlation_id
 
     def filter(self, record):
-        record.correlation_id = self.request_context.correlation_id.get()
+        record.correlation_id = self.correlation_id.get()
         return True
 
 
@@ -40,11 +45,11 @@ def configure(
         cls,
         logger_name="app",
         log_filename="./logs.json",
-        request_context=request_context,
+        correlation_id=correlation_id,
     ):
         cls.logger_name = logger_name
         cls.log_filename = log_filename
-        cls.request_context = request_context
+        cls.correlation_id = correlation_id
         cls._configured = True
 
     @classmethod
@@ -131,9 +136,10 @@ def create_logger(cls):
 
         dictConfig(logging_config)
         logger = logging.getLogger(name=cls.logger_name)
+        logger.correlation_id = cls.correlation_id
         logger.addFilter(
             RequestContextFilter(
-                name=cls.logger_name, request_context=cls.request_context
+                name=cls.logger_name, correlation_id=cls.correlation_id
             )
         )
         return logger

src/seedwork/infrastructure/request_context.py

@@ -0,0 +1,16 @@
+from collections import OrderedDict
+
+
+class OrderedSet(OrderedDict):
+    def __init__(self, iterable=None):
+        super().__init__()
+        if iterable:
+            for item in iterable:
+                self.add(item)
+
+    def add(self, item):
+        self[item] = None
+
+    def update(self, iterable):
+        for item in iterable:
+            self.add(item)