feat: add tenant id to log output (#1065)

* feat: add tenant id to log output

---------

Signed-off-by: Akiff Manji <[email protected]>
Signed-off-by: Akiff Manji <[email protected]>
Co-authored-by: jamshale <[email protected]>
Co-authored-by: Emiliano Suñé <[email protected]>

plugins/.devcontainer/configs/devcontainer.yml

@@ -56,9 +56,9 @@ genesis-url: http://test.bcovrin.vonx.io/genesis
 wallet-type: askar
 wallet-name: traction-wallet
 wallet-key: 'insecure-change-me'
-wallet-storage-type: postgres_storage
-wallet-storage-config: '{"url":"host.docker.internal:5432","max_connections":5,"wallet_scheme":"DatabasePerWallet"}'
-wallet-storage-creds: '{"account":"postgres","password":"postgresPass","admin_account":"postgres","admin_password":"postgresPass"}'
+# wallet-storage-type: postgres_storage
+# wallet-storage-config: '{"url":"host.docker.internal:5432","max_connections":5,"wallet_scheme":"DatabasePerWallet"}'
+# wallet-storage-creds: '{"account":"postgres","password":"postgresPass","admin_account":"postgres","admin_password":"postgresPass"}'
 multitenancy-config: '{"wallet-type":"askar-profile","wallet-name":"askar-wallet"}'
 
 log-level: info

plugins/.devcontainer/devcontainer.json

@@ -37,7 +37,7 @@
             },
             "python.formatting.provider": "black",
             "python.formatting.blackArgs": [],
-            "python.venvFolders": ["~.cache/virtualenvs"]
+            "python.venvFolders": ["${localWorkspaceFolder}/plugins/.venv"]
           },
           "extensions": [
               "ms-python.python",

plugins/traction_innkeeper/pyproject.toml

@@ -14,6 +14,7 @@ python-dateutil = "^2.8.2"
 bcrypt = "^4.1.3"
 mergedeep = "^1.3.4"
 typing-extensions = "4.8.0"
+anoncreds = "^0.2.0"
 
 [tool.poetry.dev-dependencies]
 black = "^24.4.2"

plugins/traction_innkeeper/traction_innkeeper/v1_0/tenant/__init__.py

@@ -1,14 +1,63 @@
+from contextvars import ContextVar
 import logging
 
 from aries_cloudagent.config.injection_context import InjectionContext
 from aries_cloudagent.core.event_bus import EventBus
 from aries_cloudagent.core.plugin_registry import PluginRegistry
 from aries_cloudagent.core.protocol_registry import ProtocolRegistry
+from aries_cloudagent.config.logging import TimedRotatingFileMultiProcessHandler
+
+from pythonjsonlogger import jsonlogger
 
 from .holder_revocation_service import subscribe, HolderRevocationService
 
 LOGGER = logging.getLogger(__name__)
 
+LOG_FORMAT_PATTERN = (
+    "%(asctime)s  TENANT: %(tenant_id)s %(levelname)s %(pathname)s:%(lineno)d %(message)s"
+)
+
+base_log_record_factory = logging.getLogRecordFactory()
+
+class ContextFilter(logging.Filter):
+    """Custom logging filter to adapt logs with contextual tenant_id."""
+
+    def __init__(self):
+        """Initialize an instance of logging filter."""
+
+        super(ContextFilter, self).__init__()
+
+    def filter(self, record):
+        """Filter log records and add tenant id to them."""
+
+        if not hasattr(record, 'tenant_id') or not record.tenant_id:
+            record.tenant_id = None
+        return True
+
+
+def setup_multitenant_logging():
+    """Setup method for multitenant logging"""
+
+    root_logger = logging.getLogger()
+    for handler in root_logger.handlers:
+        handler.setFormatter(
+            logging.Formatter(LOG_FORMAT_PATTERN)
+        )
+        handler.addFilter(ContextFilter())
+
+
+def log_records_inject(tenant_id: str):
+    """Injects tenant_id into log records"""
+
+    try:
+        def modded_log_record_factory(*args, **kwargs):
+            record = base_log_record_factory(*args, **kwargs)
+            record.tenant_id = tenant_id
+            return record
+
+        logging.setLogRecordFactory(modded_log_record_factory)
+    except Exception as e: # pylint: disable=broad-except
+        LOGGER.error("There was a problem injecting tenant_id into the logs: %s", e)
 
 async def setup(context: InjectionContext):
     LOGGER.info("> plugin setup...")
@@ -30,4 +79,6 @@ async def setup(context: InjectionContext):
 
     subscribe(bus)
 
+    setup_multitenant_logging()
+
     LOGGER.info("< plugin setup.")

plugins/traction_innkeeper/traction_innkeeper/v1_0/tenant/routes.py

@@ -40,6 +40,8 @@
 )
 from ..innkeeper.utils import create_api_key, TenantConfigSchema, TenantApiKeyException
 
+from ..tenant import log_records_inject
+
 LOGGER = logging.getLogger(__name__)
 
 SWAGGER_CATEGORY = "traction-tenant"
@@ -78,6 +80,33 @@ class TenantLedgerIdConfigSchema(OpenAPISchema):
         required=True,
     )
 
+@web.middleware
+async def setup_tenant_context(request: web.Request, handler):
+    """Middle ware to extract tenant_id and provide it to log formatter
+
+    This middleware is appended to the app middlewares and therefore runs
+    last. At this point the wallet_id has been extracted from a previous
+    middleware function and is used to query the tenant record.
+
+    Note: this function is very similar to tenant_self. Can we combine this logic?
+    """
+    context: AdminRequestContext = request["context"]
+    wallet_id, tenant_id = context.profile.settings.get("wallet.id"), None
+
+    if wallet_id:
+        mgr = context.inject(TenantManager)
+        profile = mgr.profile
+
+        async with profile.session() as session:
+            # Tenant records must always be fetched by their wallet id.
+            rec = await TenantRecord.query_by_wallet_id(session, wallet_id)
+            LOGGER.debug(rec)
+            tenant_id = rec.tenant_id
+
+    log_records_inject(tenant_id)
+
+    return await handler(request)
+
 
 @docs(
     tags=[SWAGGER_CATEGORY],
@@ -94,9 +123,9 @@ async def tenant_self(request: web.BaseRequest):
     profile = mgr.profile
 
     async with profile.session() as session:
-        # tenant's must always fetch by their wallet id.
+        # Tenants must always be fetch by their wallet id.
         rec = await TenantRecord.query_by_wallet_id(session, wallet_id)
-        LOGGER.info(rec)
+        LOGGER.debug(rec)
 
     return web.json_response(rec.serialize())
 
@@ -311,7 +340,7 @@ async def tenant_api_key_get(request: web.BaseRequest):
         rec = await TenantAuthenticationApiRecord.retrieve_by_auth_api_id(
             session, tenant_authentication_api_id
         )
-        LOGGER.info(rec)
+        LOGGER.debug(rec)
 
         # if rec tenant_id does not match the tenant_id from the wallet, raise 404
         if rec.tenant_id != tenant_id:
@@ -398,9 +427,7 @@ async def tenant_server_config_handler(request: web.BaseRequest):
     profile = mgr.profile
 
     config = {
-        k: (
-           profile.context.settings[k]
-        )
+        k: (profile.context.settings[k])
         for k in profile.context.settings
         if k
         not in [
@@ -424,13 +451,15 @@ async def tenant_server_config_handler(request: web.BaseRequest):
         ]
     }
     try:
-      del config["plugin_config"]["traction_innkeeper"]["innkeeper_wallet"]
-      config["config"]["ledger.ledger_config_list"] = [
-        {k: v for k, v in d.items() if k != "genesis_transactions"}
-        for d in config["config"]["ledger.ledger_config_list"]
-      ]
+        del config["plugin_config"]["traction_innkeeper"]["innkeeper_wallet"]
+        config["config"]["ledger.ledger_config_list"] = [
+            {k: v for k, v in d.items() if k != "genesis_transactions"}
+            for d in config["config"]["ledger.ledger_config_list"]
+        ]
     except KeyError as e:
-      LOGGER.warn(f"The key to be removed: '{e.args[0]}' is missing from the dictionary.")
+        LOGGER.warn(
+            f"The key to be removed: '{e.args[0]}' is missing from the dictionary."
+        )
     config["version"] = __version__
 
     return web.json_response({"config": config})
@@ -439,6 +468,10 @@ async def tenant_server_config_handler(request: web.BaseRequest):
 async def register(app: web.Application):
     """Register routes."""
     LOGGER.info("> registering routes")
+
+    # register tenant specific middleware
+    app.middlewares.append(setup_tenant_context)
+
     # routes that require a tenant token.
     app.add_routes(
         [
@@ -462,9 +495,9 @@ async def register(app: web.Application):
                 tenant_api_key_delete,
             ),
             web.get(
-                "/tenant/server/status/config", 
-                tenant_server_config_handler, 
-                allow_head=False
+                "/tenant/server/status/config",
+                tenant_server_config_handler,
+                allow_head=False,
             ),
         ]
     )