diff --git a/docs/2_0_ConfigurationGuid.md b/docs/2_0_ConfigurationGuid.md index cee1308e..bb83cc02 100644 --- a/docs/2_0_ConfigurationGuid.md +++ b/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 | diff --git a/oidc-controller/api/authSessions/crud.py b/oidc-controller/api/authSessions/crud.py index caaa47e8..61a1c9e4 100644 --- a/oidc-controller/api/authSessions/crud.py +++ b/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: diff --git a/oidc-controller/api/clientConfigurations/crud.py b/oidc-controller/api/clientConfigurations/crud.py index 5808ff59..4f4f7eff 100644 --- a/oidc-controller/api/clientConfigurations/crud.py +++ b/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: diff --git a/oidc-controller/api/clientConfigurations/tests/test_cc_crud.py b/oidc-controller/api/clientConfigurations/tests/test_cc_crud.py index 2a9d58eb..8c13bf0f 100644 --- a/oidc-controller/api/clientConfigurations/tests/test_cc_crud.py +++ b/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,9 +68,18 @@ 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) @@ -76,12 +87,13 @@ async def test_client_config_patch(db_client: Callable[[], MongoClient]): 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}) diff --git a/oidc-controller/api/core/acapy/client.py b/oidc-controller/api/core/acapy/client.py index d8dd5a3e..206a03f3 100644 --- a/oidc-controller/api/core/acapy/client.py +++ b/oidc-controller/api/core/acapy/client.py @@ -1,6 +1,6 @@ import requests import json -import logging +import structlog from typing import Optional, Union from uuid import UUID from .models import WalletDid, CreatePresentationResponse @@ -8,7 +8,7 @@ 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" diff --git a/oidc-controller/api/core/acapy/config.py b/oidc-controller/api/core/acapy/config.py index 9ddddbc6..3da4c5f9 100644 --- a/oidc-controller/api/core/acapy/config.py +++ b/oidc-controller/api/core/acapy/config.py @@ -1,5 +1,5 @@ import requests -import logging +import structlog import json from functools import cache @@ -7,7 +7,7 @@ from ..config import settings -logger = logging.getLogger(__name__) +logger = structlog.getLogger(__name__) class AgentConfig(Protocol): diff --git a/oidc-controller/api/core/config.py b/oidc-controller/api/core/config.py index a3f4fe86..c1733fa7 100644 --- a/oidc-controller/api/core/config.py +++ b/oidc-controller/api/core/config.py @@ -1,4 +1,8 @@ +import json import logging +import sys +import logging.config +import structlog import os from enum import Enum from functools import lru_cache @@ -6,7 +10,99 @@ 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 diff --git a/oidc-controller/api/core/logger_util.py b/oidc-controller/api/core/logger_util.py index a1d48345..29ffa1a0 100644 --- a/oidc-controller/api/core/logger_util.py +++ b/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 diff --git a/oidc-controller/api/core/oidc/issue_token_service.py b/oidc-controller/api/core/oidc/issue_token_service.py index e53c5e82..bb34e276 100644 --- a/oidc-controller/api/core/oidc/issue_token_service.py +++ b/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" diff --git a/oidc-controller/api/core/oidc/provider.py b/oidc-controller/api/core/oidc/provider.py index 4da5e1aa..be09db56 100644 --- a/oidc-controller/api/core/oidc/provider.py +++ b/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__)) diff --git a/oidc-controller/api/logconf.json b/oidc-controller/api/logconf.json new file mode 100644 index 00000000..771d9f21 --- /dev/null +++ b/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": {} + } +} diff --git a/oidc-controller/api/logging.conf b/oidc-controller/api/logging.conf deleted file mode 100644 index b4e9be62..00000000 --- a/oidc-controller/api/logging.conf +++ /dev/null @@ -1,33 +0,0 @@ -[loggers] -keys=root,simpleExample,sql - -[handlers] -keys=consoleHandler - -[formatters] -keys=simpleFormatter - -[logger_root] -level=INFO -handlers=consoleHandler - -[logger_sql] -level=ERROR -handlers=consoleHandler -qualname=sqlalchemy.engine -propagate=0 - -[logger_simpleExample] -level=DEBUG -handlers=consoleHandler -qualname=simpleExample -propagate=0 - -[handler_consoleHandler] -class=StreamHandler -level=DEBUG -formatter=simpleFormatter -args=(sys.stdout,) - -[formatter_simpleFormatter] -format=%(asctime)s - %(name)s - %(levelname)s - %(message)s \ No newline at end of file diff --git a/oidc-controller/api/main.py b/oidc-controller/api/main.py index e9a07e4a..bae9d411 100644 --- a/oidc-controller/api/main.py +++ b/oidc-controller/api/main.py @@ -1,11 +1,17 @@ +# import api.core.logconfig import logging +import logging.config +import structlog import os import time +import uuid from pathlib import Path import uvicorn from api.core.config import settings from fastapi import FastAPI +from starlette.requests import Request +from starlette.responses import Response from fastapi.responses import HTMLResponse from fastapi.middleware.cors import CORSMiddleware @@ -17,12 +23,13 @@ from api.core.oidc.provider import init_provider -# setup loggers -# TODO: set config via env parameters... -logging_file_path = (Path(__file__).parent / "logging.conf").resolve() -logging.config.fileConfig(logging_file_path, disable_existing_loggers=False) +logger: structlog.typing.FilteringBoundLogger = structlog.getLogger(__name__) + +# Setup loggers +logging_file_path = os.environ.get( + "LOG_CONFIG_PATH", (Path(__file__).parent / "logging.conf").resolve() +) -logger = logging.getLogger(__name__) os.environ["TZ"] = settings.TIMEZONE time.tzset() @@ -37,6 +44,7 @@ def get_application() -> FastAPI: ) return application + app = get_application() app.include_router(ver_configs_router, prefix="/ver_configs", tags=["ver_configs"]) app.include_router(client_config_router, prefix="/clients", tags=["oidc_clients"]) @@ -53,7 +61,7 @@ def get_application() -> FastAPI: ) # Connect the websocket server to run within the FastAPI app -app.mount('/ws', sio_app) +app.mount("/ws", sio_app) origins = ["*"] @@ -67,12 +75,37 @@ def get_application() -> FastAPI: ) +@app.middleware("http") +async def logging_middleware(request: Request, call_next) -> Response: + # clear the threadlocal context + structlog.threadlocal.clear_threadlocal() + # bind threadlocal + structlog.threadlocal.bind_threadlocal( + logger="uvicorn.access", + request_id=str(uuid.uuid4()), + cookies=request.cookies, + scope=request.scope, + url=str(request.url), + ) + start_time = time.time() + try: + response: Response = await call_next(request) + finally: + process_time = time.time() - start_time + logger.info( + "processed a request", + status_code=response.status_code, + process_time=process_time, + ) + return response + + @app.on_event("startup") async def on_tenant_startup(): """Register any events we need to respond to.""" await init_db() await init_provider(await get_db()) - logger.warning(">>> Starting up app ...") + logger.info(">>> Starting up app new ...") @app.on_event("shutdown") @@ -88,5 +121,5 @@ def main(): if __name__ == "__main__": - print("main.") + logger.info("main.") uvicorn.run(app, host="0.0.0.0", port=5100) diff --git a/oidc-controller/api/routers/acapy_handler.py b/oidc-controller/api/routers/acapy_handler.py index 31a3702f..b53ff642 100644 --- a/oidc-controller/api/routers/acapy_handler.py +++ b/oidc-controller/api/routers/acapy_handler.py @@ -1,5 +1,5 @@ import json -import logging +import structlog from datetime import datetime, timedelta from fastapi import APIRouter, Depends, Request @@ -12,15 +12,16 @@ from ..core.config import settings -from ..routers.socketio import (sio, connections_reload) - -logger = logging.getLogger(__name__) +logger = structlog.getLogger(__name__) +from ..routers.socketio import sio, connections_reload router = APIRouter() + async def _parse_webhook_body(request: Request): return json.loads((await request.body()).decode("ascii")) + @router.post("/topic/{topic}/") async def post_topic(request: Request, topic: str, db: Database = Depends(get_db)): """Called by aca-py agent.""" @@ -37,12 +38,12 @@ async def post_topic(request: Request, topic: str, db: Database = Depends(get_db auth_session: AuthSession = await AuthSessionCRUD(db).get_by_pres_exch_id( webhook_body["presentation_exchange_id"] ) - + # Get the saved websocket session pid = str(auth_session.id) connections = connections_reload() sid = connections.get(pid) - + if webhook_body["state"] == "presentation_received": logger.info("GOT A PRESENTATION, TIME TO VERIFY") client.verify_presentation(auth_session.pres_exch_id) @@ -52,10 +53,10 @@ async def post_topic(request: Request, topic: str, db: Database = Depends(get_db logger.info("VERIFIED") if webhook_body["verified"] == "true": auth_session.proof_status = AuthSessionState.VERIFIED - await sio.emit('status', {'status': 'verified'}, to=sid) + await sio.emit("status", {"status": "verified"}, to=sid) else: auth_session.proof_status = AuthSessionState.FAILED - await sio.emit('status', {'status': 'failed'}, to=sid) + await sio.emit("status", {"status": "failed"}, to=sid) await AuthSessionCRUD(db).patch( str(auth_session.id), AuthSessionPatch(**auth_session.dict()) @@ -80,7 +81,7 @@ async def post_topic(request: Request, topic: str, db: Database = Depends(get_db ): logger.info("EXPIRED") auth_session.proof_status = AuthSessionState.EXPIRED - await sio.emit('status', {'status': 'expired'}, to=sid) + await sio.emit("status", {"status": "expired"}, to=sid) await AuthSessionCRUD(db).patch( str(auth_session.id), AuthSessionPatch(**auth_session.dict()) ) diff --git a/oidc-controller/api/routers/oidc.py b/oidc-controller/api/routers/oidc.py index c03c5360..e2687b3b 100644 --- a/oidc-controller/api/routers/oidc.py +++ b/oidc-controller/api/routers/oidc.py @@ -1,6 +1,6 @@ import base64 import io -import logging +import structlog from urllib.parse import urlencode from datetime import datetime @@ -32,7 +32,7 @@ VerifiedCredentialAuthorizeUri = "/authorize" VerifiedCredentialTokenUri = "/token" -logger = logging.getLogger(__name__) +logger: structlog.typing.FilteringBoundLogger = structlog.getLogger(__name__) router = APIRouter() diff --git a/oidc-controller/api/routers/presentation_request.py b/oidc-controller/api/routers/presentation_request.py index 5ac1da55..055455a2 100644 --- a/oidc-controller/api/routers/presentation_request.py +++ b/oidc-controller/api/routers/presentation_request.py @@ -1,4 +1,4 @@ -import logging +import structlog from fastapi import APIRouter, Depends, Request from fastapi.responses import HTMLResponse, JSONResponse, RedirectResponse @@ -21,7 +21,7 @@ from ..db.session import get_db from ..templates.helpers import add_asset -logger = logging.getLogger(__name__) +logger: structlog.typing.FilteringBoundLogger = structlog.getLogger(__name__) router = APIRouter() @@ -111,5 +111,5 @@ async def send_connectionless_proof_req( service=s_d, ) msg_contents = msg - print(msg_contents.dict(by_alias=True)) + logger.debug(msg_contents.dict(by_alias=True)) return JSONResponse(msg_contents.dict(by_alias=True)) diff --git a/oidc-controller/api/routers/well_known_oid_config.py b/oidc-controller/api/routers/well_known_oid_config.py index 6f5e18d3..92a8c98c 100644 --- a/oidc-controller/api/routers/well_known_oid_config.py +++ b/oidc-controller/api/routers/well_known_oid_config.py @@ -1,4 +1,4 @@ -import logging +import structlog from fastapi import APIRouter from fastapi.responses import JSONResponse @@ -6,7 +6,7 @@ # from oic.oauth2.message import ASConfigurationResponse from ..core.oidc import provider -logger = logging.getLogger(__name__) +logger: structlog.typing.FilteringBoundLogger = structlog.getLogger(__name__) router = APIRouter() diff --git a/oidc-controller/api/verificationConfigs/models.py b/oidc-controller/api/verificationConfigs/models.py index c81026f2..5d53657f 100644 --- a/oidc-controller/api/verificationConfigs/models.py +++ b/oidc-controller/api/verificationConfigs/models.py @@ -58,6 +58,7 @@ def generate_proof_request(self): "from": int(time.time()), "to": int(time.time()), } + # TODO add I indexing for req_pred in self.proof_request.requested_predicates: label = req_pred.label or "req_pred_" + str(i) result["requested_predicates"][label] = req_pred.dict(exclude_none=True) diff --git a/oidc-controller/requirements-dev.txt b/oidc-controller/requirements-dev.txt index 51668ec7..ff65b7a0 100644 --- a/oidc-controller/requirements-dev.txt +++ b/oidc-controller/requirements-dev.txt @@ -1,4 +1,5 @@ black==23.3.0 flake8==6.0.0 mongomock==4.1.2 -pytest==7.3.1 \ No newline at end of file +pytest==7.3.1 +pytest-asyncio==0.21.1 diff --git a/oidc-controller/requirements.txt b/oidc-controller/requirements.txt index bd6c8653..000f64af 100644 --- a/oidc-controller/requirements.txt +++ b/oidc-controller/requirements.txt @@ -5,5 +5,6 @@ pymongo==4.3.3 pyop==3.4.0 python-multipart==0.0.6 # required by fastapi to serve/upload files qrcode[pil]==7.4.2 +structlog==23.1.0 uvicorn[standard]==0.22.0 -python-socketio==5.8.0 # required to run websockets \ No newline at end of file +python-socketio==5.8.0 # required to run websockets