Merge pull request #297 from bcgov/migrate-to-structlog

Move logging to structlog and centralize logging

docs/2_0_ConfigurationGuid.md

@@ -3,3 +3,6 @@
 | ------------------------ | ---- | ---------------------------------------------- |-|
 | SET_NON_REVOKED          | bool | if True, the `non_revoked` attributed  will be added to each of the present-proof request `requested_attribute` and `requested_predicate` with 'from=0' and'to=`int(time.time())`||
 | USE_OOB_PRESENT_PROOF    | bool | if True, the present-proof request will be provided as a an [out of band](https://github.com/hyperledger/aries-rfcs/tree/main/features/0434-outofband) invitation with a [present-proof](https://github.com/hyperledger/aries-rfcs/tree/main/features/0037-present-proof) request inside. If False, the present-proof request will be use the [service-decorator](https://github.com/hyperledger/aries-rfcs/tree/main/features/0056-service-decorator)|**TRUE:** BC Wallet supports our OOB Message with a minor glitch, BiFold, Lissi, Trinsic, and Estatus all read the QR code as 'Invalid' **FALSE:** Works with|
+| LOG_WITH_JSON            | bool | If True, logging output should printed as JSON if False it will be pretty printed.| Default behavior will print as JSON. |
+| LOG_TIMESTAMP_FORMAT     | string | determines the timestamp formatting used in logs | Default is "iso" |
+| LOG_LEVEL                | "DEBUG", "INFO", "WARNING", or "ERROR" | sets the minimum log level that will be printed to standard out| Defaults to DEBUG |

oidc-controller/api/authSessions/crud.py

@@ -1,4 +1,4 @@
-import logging
+import structlog
 
 from typing import Union
 from pymongo import ReturnDocument
@@ -16,7 +16,7 @@
 from api.db.session import COLLECTION_NAMES
 
 
-logger = logging.getLogger(__name__)
+logger: structlog.typing.FilteringBoundLogger = structlog.getLogger(__name__)
 
 
 class AuthSessionCRUD:

oidc-controller/api/clientConfigurations/crud.py

@@ -1,4 +1,4 @@
-import logging
+import structlog
 
 from typing import List
 from pymongo import ReturnDocument
@@ -17,7 +17,7 @@
 from api.core.oidc.provider import init_provider
 
 
-logger = logging.getLogger(__name__)
+logger: structlog.typing.FilteringBoundLogger = structlog.getLogger(__name__)
 
 
 class ClientConfigurationCRUD:

oidc-controller/api/clientConfigurations/tests/test_cc_crud.py

@@ -10,6 +10,8 @@
 
 from mongomock import MongoClient
 from typing import Callable
+import structlog
+logger = structlog.getLogger(__name__)
 
 
 def test_answer():
@@ -66,22 +68,32 @@ async def test_client_config_delete(db_client: Callable[[], MongoClient]):
     ).find_one({"client_id": test_client_config.client_id})
     assert not document
 
+@pytest.fixture(name="log_output")
+def fixture_log_output():
+    return structlog.testing.LogCapture()
+
+@pytest.fixture(autouse=True)
+def fixture_configure_structlog(log_output):
+    structlog.configure(
+        processors=[log_output]
+    )
 
 @pytest.mark.asyncio
-async def test_client_config_patch(db_client: Callable[[], MongoClient]):
+async def test_client_config_patch(db_client: Callable[[], MongoClient], log_output):
     client = db_client()
     crud = ClientConfigurationCRUD(client.db)
 
     client.db.get_collection(COLLECTION_NAMES.CLIENT_CONFIGURATIONS).insert_one(
         test_client_config.dict()
     )
 
+    assert log_output.entries == []
+
     result = await crud.patch(
         test_client_config.client_id,
         ClientConfigurationPatch(client_secret="patched_client_secret"),
     )
     assert result
-
     document = client.db.get_collection(
         COLLECTION_NAMES.CLIENT_CONFIGURATIONS
     ).find_one({"client_id": test_client_config.client_id})

oidc-controller/api/core/acapy/client.py

@@ -1,14 +1,14 @@
 import requests
 import json
-import logging
+import structlog
 from typing import Optional, Union
 from uuid import UUID
 from .models import WalletDid, CreatePresentationResponse
 from ..config import settings
 from .config import AgentConfig, MultiTenantAcapy, SingleTenantAcapy
 
 _client = None
-logger = logging.getLogger(__name__)
+logger = structlog.getLogger(__name__)
 
 WALLET_DID_URI = "/wallet/did"
 PUBLIC_WALLET_DID_URI = "/wallet/did/public"

oidc-controller/api/core/acapy/config.py

@@ -1,13 +1,13 @@
 import requests
-import logging
+import structlog
 import json
 
 from functools import cache
 from typing import Dict, Protocol
 
 from ..config import settings
 
-logger = logging.getLogger(__name__)
+logger = structlog.getLogger(__name__)
 
 
 class AgentConfig(Protocol):

oidc-controller/api/core/config.py

@@ -1,12 +1,108 @@
+import json
 import logging
+import sys
+import logging.config
+import structlog
 import os
 from enum import Enum
 from functools import lru_cache
 from typing import Optional, Union
 
 from pydantic import BaseSettings
 
-logger = logging.getLogger(__name__)
+from pathlib import Path
+
+
+# Use environment variable to determine logging format
+# fallback to logconf.json
+# finally default to true
+# bool() is needed to coerce the results of the environment variable
+use_json_logs: bool = bool(os.environ.get("LOG_WITH_JSON", True))
+
+time_stamp_format: str = os.environ.get("LOG_TIMESTAMP_FORMAT", "iso")
+
+with open((Path(__file__).parent.parent / "logconf.json").resolve()) as user_file:
+    file_contents: dict = json.loads(user_file.read())
+    logging.config.dictConfig(file_contents["logger"])
+
+
+def determin_log_level():
+    match os.environ.get("LOG_LEVEL"):
+        case "DEBUG":
+            return logging.DEBUG
+        case "INFO":
+            return logging.INFO
+        case "WARNING":
+            return logging.WARNING
+        case "ERROR":
+            return logging.ERROR
+        case _:
+            return logging.DEBUG
+
+
+logging.basicConfig(
+    format="%(message)s",
+    stream=sys.stdout,
+    level=determin_log_level(),
+)
+
+shared_processors = [
+    structlog.contextvars.merge_contextvars,
+    structlog.stdlib.add_logger_name,
+    structlog.stdlib.PositionalArgumentsFormatter(),
+    structlog.stdlib.ExtraAdder(),
+    structlog.processors.StackInfoRenderer(),
+    structlog.stdlib.add_log_level,
+    structlog.processors.TimeStamper(fmt=time_stamp_format),
+]
+
+renderer = (
+    structlog.processors.JSONRenderer()
+    if use_json_logs
+    else structlog.dev.ConsoleRenderer()
+)
+
+# override uvicorn logging to use logstruct
+formatter = structlog.stdlib.ProcessorFormatter(
+    # These run ONLY on `logging` entries that do NOT originate within
+    # structlog.
+    foreign_pre_chain=shared_processors,
+    # These run on ALL entries after the pre_chain is done.
+    processors=[
+        # Remove _record & _from_structlog.
+        structlog.stdlib.ProcessorFormatter.remove_processors_meta,
+        renderer,
+    ],
+)
+
+handler = logging.StreamHandler()
+handler.setFormatter(formatter)
+
+for _log in ["uvicorn", "uvicorn.error"]:
+    # Clear the log handlers for uvicorn loggers, and enable propagation
+    # so the messages are caught by our root logger and formatted correctly
+    # by structlog
+    logging.getLogger(_log).handlers.clear()
+    logging.getLogger(_log).addHandler(handler)
+    logging.getLogger(_log).propagate = False
+
+# This is already handled by our middleware
+logging.getLogger("uvicorn.access").handlers.clear()
+logging.getLogger("uvicorn.access").propagate = False
+
+# Configure structlog
+structlog.configure(
+    processors=[structlog.stdlib.filter_by_level] + shared_processors + [renderer],
+    context_class=dict,
+    logger_factory=structlog.stdlib.LoggerFactory(),
+    wrapper_class=structlog.make_filtering_bound_logger(
+        logging.getLogger().getEffectiveLevel()
+    ),
+    cache_logger_on_first_use=True,
+)
+
+# Setup logger for config
+logger: structlog.typing.FilteringBoundLogger = structlog.getLogger(__name__)
 
 
 class EnvironmentEnum(str, Enum):
@@ -48,7 +144,7 @@ class GlobalConfig(BaseSettings):
 
     ACAPY_AGENT_URL: Optional[str] = os.environ.get("ACAPY_AGENT_URL")
     if not ACAPY_AGENT_URL:
-        print("WARNING: ACAPY_AGENT_URL was not provided, agent will not be accessible")
+        logger.warning("ACAPY_AGENT_URL was not provided, agent will not be accessible")
 
     ACAPY_TENANCY: str = os.environ.get(
         "ACAPY_TENANCY", "single"
@@ -85,13 +181,11 @@ class GlobalConfig(BaseSettings):
 
     # OIDC Controller Settings
     CONTROLLER_API_KEY: str = os.environ.get("CONTROLLER_API_KEY", "")
-    USE_OOB_PRESENT_PROOF: Union[bool, str] = os.environ.get(
-        "USE_OOB_PRESENT_PROOF", False
+    USE_OOB_PRESENT_PROOF: bool = bool(os.environ.get("USE_OOB_PRESENT_PROOF", False))
+    USE_OOB_LOCAL_DID_SERVICE: bool = bool(
+        os.environ.get("USE_OOB_LOCAL_DID_SERVICE", False)
     )
-    USE_OOB_LOCAL_DID_SERVICE: Union[bool, str] = os.environ.get(
-        "USE_OOB_LOCAL_DID_SERVICE", False
-    )
-    SET_NON_REVOKED: Union[bool, str] = os.environ.get("SET_NON_REVOKED", True)
+    SET_NON_REVOKED: bool = bool(os.environ.get("SET_NON_REVOKED", True))
 
     class Config:
         case_sensitive = True

oidc-controller/api/core/logger_util.py

@@ -1,4 +1,4 @@
-import logging
+import structlog
 import time
 
 
@@ -7,14 +7,15 @@
 
 def log_debug(func: Callable[..., Any]) -> Callable[..., Any]:
     def wrapper(*args, **kwargs):
-        logger = logging.getLogger(func.__name__)
-        logger.setLevel(logging.DEBUG)
-        logger.info(f" >>>> {func.__name__}")
+        logger = structlog.getLogger(func.__name__)
+        logger.debug(f" >>>> {func.__name__}")
         logger.debug(f" ..with params={{{args}}}")
         start_time = time.time()
         ret_val = func(*args, **kwargs)
         end_time = time.time()
-        logger.info(f" <<<< {func.__name__} and took {end_time-start_time:.3f} seconds")
+        logger.debug(
+            f" <<<< {func.__name__} and took {end_time-start_time:.3f} seconds"
+        )
         logger.debug(f" ..with ret_val={{{ret_val}}}")
         return ret_val
 

oidc-controller/api/core/oidc/issue_token_service.py

@@ -1,4 +1,4 @@
-import logging
+import structlog
 import json
 import uuid
 import dataclasses
@@ -9,7 +9,7 @@
 from ...authSessions.models import AuthSession
 from ...verificationConfigs.models import VerificationConfig
 
-logger = logging.getLogger(__name__)
+logger = structlog.getLogger(__name__)
 
 PROOF_CLAIMS_ATTRIBUTE_NAME = "vc_presented_attributes"
 

oidc-controller/api/core/oidc/provider.py

@@ -1,4 +1,5 @@
-import logging
+import structlog
+import structlog.typing
 import os
 
 from api.core.config import settings
@@ -14,7 +15,7 @@
 from urllib.parse import urlparse
 from jwkest.jwk import rsa_load, RSAKey, KEYS
 
-logger = logging.getLogger(__name__)
+logger: structlog.typing.FilteringBoundLogger = structlog.get_logger()
 DIR_PATH = os.path.dirname(os.path.realpath(__file__))
 
 

oidc-controller/api/logconf.json

@@ -0,0 +1,23 @@
+{
+  "logger": {
+    "version": 1,
+    "disable_existing_loggers": false,
+    "formatters": {
+      "plain": {
+        "()": "structlog.stdlib.ProcessorFormatter",
+        "processors": [
+          "renderer"
+        ],
+        "foreign_pre_chain": "shared_processors"
+      }
+    },
+    "handlers": {
+      "out": {
+        "formatter": "plain",
+        "class": "logging.StreamHandler",
+        "stream": "ext://sys.stdout"
+      }
+    },
+    "loggers": {}
+  }
+}