From 8176c5621965c95c3c173f2940e25ac810074180 Mon Sep 17 00:00:00 2001 From: jamshale Date: Mon, 18 Sep 2023 15:15:09 -0700 Subject: [PATCH] Fix logging middleware exception handling Signed-off-by: jamshale --- oidc-controller/api/core/logger_util.py | 11 +- .../api/core/oidc/tests/__mocks__.py | 381 ++++++++++++++++++ .../api/core/oidc/tests/test_get_claims.py | 142 +++++++ .../api/core/oidc/tests/test_idtoken_dict.py | 9 + oidc-controller/api/main.py | 43 +- test-signing-keys/test_signing_key.pem | 28 ++ 6 files changed, 600 insertions(+), 14 deletions(-) create mode 100644 oidc-controller/api/core/oidc/tests/__mocks__.py create mode 100644 oidc-controller/api/core/oidc/tests/test_get_claims.py create mode 100644 oidc-controller/api/core/oidc/tests/test_idtoken_dict.py create mode 100644 test-signing-keys/test_signing_key.pem diff --git a/oidc-controller/api/core/logger_util.py b/oidc-controller/api/core/logger_util.py index 29ffa1a0..127c22ef 100644 --- a/oidc-controller/api/core/logger_util.py +++ b/oidc-controller/api/core/logger_util.py @@ -1,8 +1,9 @@ import structlog import time +from typing import Callable, Any +logger = structlog.getLogger(__name__) -from typing import Callable, Any def log_debug(func: Callable[..., Any]) -> Callable[..., Any]: @@ -20,3 +21,11 @@ def wrapper(*args, **kwargs): return ret_val return wrapper + + +def extract_error_msg_from_traceback_exc(format_exc) -> str: + try: + return format_exc.splitlines()[-1].split(": ")[1:][0] + except Exception: + logger.error(f"Failed to extract error message from traceback: {format_exc}") + return "Unknown error" diff --git a/oidc-controller/api/core/oidc/tests/__mocks__.py b/oidc-controller/api/core/oidc/tests/__mocks__.py new file mode 100644 index 00000000..133d261e --- /dev/null +++ b/oidc-controller/api/core/oidc/tests/__mocks__.py @@ -0,0 +1,381 @@ + + +from datetime import datetime, timedelta + +from api.verificationConfigs.models import VerificationConfig, VerificationProofRequest +from api.authSessions.models import AuthSession + +presentation = { + "thread_id": "428ab5dc-185f-40ba-8714-498c79b822f3", + "created_at": "2023-09-15T17:49:16.397954Z", + "role": "verifier", + "auto_present": False, + "presentation_exchange_id": "ccaac3c5-1606-44fb-ade3-33937dfb6dca", + "presentation_request": { + "nonce": "633368193772519315256591", + "name": "proof_requested", + "version": "0.0.1", + "requested_attributes": "invalid", # Add test requested attributes + "requested_predicates": {}, + }, + "presentation": { + "proof": { + "proofs": [ + { + "primary_proof": { + "eq_proof": { + "revealed_attrs": { + "email": "73814602767252868561268261832462872577293109184327908660400248444458427915643" + }, + "a_prime": "40809417934849907123261471333411809633354074436405510819719547561843004255793023387498104889708571270607131703938696756407487467873368373775514806534499374680059274765067020721416649641170535056242622419292879011504372419414431627060123535951854477609020119038446707071877530649018798857842493513975477809431501443034563297114458359206476293934461316378865994820249592804467758433904174100097026785285885805688715928578812499534293751388422584754995155726212908115142236221995953756086868367889189436621196564054394071524712971126196703085030819194540892286515361206473918715176334283198231106756804249201321110676817", + "e": "132166309846004002298968329630750626534906193461199076364226183288855464715230907038994149984215600411276690314987056469395087923423376034", + "v": "389852336354596234620050863642411241608940316153319185423050526707483503655636070718528707360249027781424214465818771183857876571898645233712049550065615437328753383559647676180932006072233802815800996667626559757294734656704881893512658110558847026240354780006408044914149694965180223127754340423475416000940696265773581100989216553579233198807834530514088943560794612627439000580021272527304012796141460444099028132444095750454921031441117671745673457339631909515144154149520136598843334638440138229207476684776682052027672414220327439299122271829090948693982983191662066627130404544959976637513561609461174550463471636750546362339385232864872096796748538286120598703640917737216094473317639418313144992206875604615452306826430748790105881684965109026881701380306409317275248915954859998470708379642658766566479932465684746033865495941061980422316943701392367332573162799073428328950386460662125690364635698421614848860", + "m": { + "time": "11896542455624181868867605459032062290636202825612483735571300567506766112289589216989585608752835036405824270689163034684130257627062069669940002269643613585904726141499206139998", + "master_secret": "11978669714570126125906674715703732098298259897696576462078203241042378591463388624826815153862705227192729264588296043944542578244619153416802465506231069348686312732305137579470", + }, + "m2": "5273201069177175286302918970464632772021241766353736934881903190951819578898991714048991692651562372414552361008106867369251847950990157935703897032904209115054769991615534757984", + }, + "ge_proofs": [], + } + } + ], + "aggregated_proof": { + "c_hash": "8135055767072243139738404741550925116429855319200452769474586673630216912237", + "c_list": [ + [ + 1, + 67, + 69, + 218, + 45, + 100, + 186, + 167, + 216, + 87, + 192, + 6, + 176, + 75, + 145, + 223, + 169, + 145, + 91, + 99, + 86, + 41, + 163, + 239, + 183, + 82, + 77, + 155, + 0, + 10, + 154, + 38, + 31, + 69, + 75, + 147, + 247, + 207, + 186, + 120, + 218, + 30, + 96, + 230, + 113, + 83, + 229, + 113, + 65, + 218, + 211, + 2, + 184, + 149, + 159, + 80, + 65, + 4, + 47, + 122, + 28, + 181, + 39, + 20, + 204, + 185, + 201, + 137, + 212, + 132, + 147, + 176, + 84, + 227, + 132, + 184, + 226, + 193, + 1, + 169, + 31, + 158, + 224, + 180, + 173, + 41, + 147, + 12, + 237, + 53, + 27, + 16, + 111, + 101, + 235, + 112, + 141, + 159, + 255, + 215, + 208, + 77, + 227, + 83, + 44, + 203, + 54, + 248, + 105, + 79, + 58, + 244, + 217, + 3, + 83, + 67, + 181, + 129, + 109, + 166, + 91, + 43, + 36, + 95, + 7, + 251, + 47, + 182, + 233, + 58, + 30, + 228, + 20, + 108, + 86, + 60, + 177, + 63, + 93, + 120, + 37, + 182, + 164, + 151, + 82, + 124, + 197, + 249, + 17, + 117, + 100, + 36, + 209, + 255, + 131, + 228, + 44, + 103, + 47, + 19, + 34, + 26, + 108, + 253, + 27, + 233, + 134, + 22, + 122, + 87, + 29, + 120, + 69, + 202, + 207, + 5, + 153, + 48, + 125, + 28, + 19, + 142, + 237, + 82, + 212, + 27, + 49, + 85, + 117, + 228, + 23, + 53, + 190, + 84, + 58, + 185, + 84, + 162, + 71, + 203, + 170, + 110, + 237, + 101, + 192, + 94, + 233, + 142, + 48, + 184, + 69, + 188, + 85, + 145, + 167, + 147, + 159, + 55, + 146, + 49, + 96, + 146, + 17, + 99, + 61, + 50, + 112, + 3, + 188, + 87, + 174, + 85, + 198, + 73, + 142, + 105, + 158, + 244, + 209, + 121, + 8, + 120, + 195, + 221, + 251, + 46, + 216, + 41, + 0, + 49, + 212, + 19, + 76, + 166, + 236, + 37, + 81, + ] + ], + }, + }, + "requested_proof": { + "revealed_attrs": {}, + "revealed_attr_groups": "invalid", # Add test revealed_attr_groups + "self_attested_attrs": {}, + "unrevealed_attrs": {}, + "predicates": {}, + }, + "identifiers": [ + { + "schema_id": "MTYqmTBoLT7KLP5RNfgK3b:2:verified-email:1.2.3", + "cred_def_id": "MTYqmTBoLT7KLP5RNfgK3b:3:CL:160342:default", + } + ], + }, + "verified": "true", + "state": "verified", + "presentation_request_dict": { + "@type": "did:sov:BzCbsNYhMrjHiqZDTUASHg;spec/present-proof/1.0/request-presentation", + "@id": "428ab5dc-185f-40ba-8714-498c79b822f3", + "request_presentations~attach": [ + { + "@id": "libindy-request-presentation-0", + "mime-type": "application/json", + "data": { + "base64": "eyJuYW1lIjogInByb29mX3JlcXVlc3RlZCIsICJ2ZXJzaW9uIjogIjAuMC4xIiwgInJlcXVlc3RlZF9hdHRyaWJ1dGVzIjogeyJyZXFfYXR0cl8wIjogeyJuYW1lcyI6IFsiZW1haWwiXSwgInJlc3RyaWN0aW9ucyI6IFt7InNjaGVtYV9uYW1lIjogInZlcmlmaWVkLWVtYWlsIiwgImlzc3Vlcl9kaWQiOiAiTVRZcW1UQm9MVDdLTFA1Uk5mZ0szYiJ9XSwgIm5vbl9yZXZva2VkIjogeyJmcm9tIjogMTY5NDgwMDE1NiwgInRvIjogMTY5NDgwMDE1Nn19fSwgInJlcXVlc3RlZF9wcmVkaWNhdGVzIjoge30sICJub25jZSI6ICI2MzMzNjgxOTM3NzI1MTkzMTUyNTY1OTEifQ==" + }, + } + ], + }, + "initiator": "self", + "updated_at": "2023-09-15T17:49:33.477755Z", + "trace": False, + "auto_verify": True, + "verified_msgs": ["RMV_GLB_NRI", "RMV_RFNT_NRI::req_attr_0"], +} + +auth_session = AuthSession( + pres_exch_id="e444bc3e-346d-47d1-882d-39c014b8978c", + expired_timestamp=datetime.now() + timedelta(seconds=3000), + ver_config_id="verified-email", + request_parameters={ + 'scope': 'openid vc_authn', + 'state': 'oFLNfUyzDtWHmc61dNiQZkVZRsRUUXZ5KZIiQBeQuJQ.xfaKQBh1xfQ.T02DEr3QRTmMUfjegc9fQQ', + 'response_type': 'code', + 'client_id': 'keycloak', + 'redirect_uri': 'http://localhost:8880/auth/realms/vc-authn/broker/vc-authn/endpoint', + 'pres_req_conf_id': 'verified-email', + 'nonce': 'J2o8dDBWAZyov0ipkMPZng' + }, + pyop_auth_code="str", + response_url="str", + proof_status="pending", +) + +ver_config = VerificationConfig( + ver_config_id="verified-email", + subject_identifier="email", + proof_request=VerificationProofRequest( + name="BCGov Verified Email", + version="1.0", + requested_attributes=[ + { + "names": ["email"], + "restrictions": [ + { + "schema_name": "verified-email", + "issuer_did": "MTYqmTBoLT7KLP5RNfgK3b" + } + ] + } + ], + requested_predicates=[] + ) +) diff --git a/oidc-controller/api/core/oidc/tests/test_get_claims.py b/oidc-controller/api/core/oidc/tests/test_get_claims.py new file mode 100644 index 00000000..107aa379 --- /dev/null +++ b/oidc-controller/api/core/oidc/tests/test_get_claims.py @@ -0,0 +1,142 @@ +import mock +import pytest +from api.authSessions.models import AuthSession +from api.core.oidc.issue_token_service import Token +from api.core.oidc.tests.__mocks__ import auth_session, presentation, ver_config + +@pytest.mark.asyncio +async def test_valid_proof_presentation_with_one_attribute_returns_token(): + presentation['presentation_request']['requested_attributes'] = { + "req_attr_0": { + "names": ["email"], + "restrictions": [ + { + "schema_name": "verified-email", + "issuer_did": "MTYqmTBoLT7KLP5RNfgK3b", + } + ], + } + } + presentation['presentation']['requested_proof']['revealed_attr_groups'] = { + "req_attr_0": { + "sub_proof_index": 0, + "values": { + "email": { + "raw": "jamiehalebc@gmail.com", + "encoded": "73814602767252868561268261832462872577293109184327908660400248444458427915643", + } + } + } + } + with mock.patch.object(AuthSession, "presentation_exchange", presentation): + token = Token.get_claims(auth_session, ver_config) + assert token is not None + + +@pytest.mark.asyncio +async def test_valid_proof_presentation_with_multiple_attributes_returns_token(): + presentation['presentation_request']['requested_attributes'] = { + "req_attr_0": { + "names": ["email"], + "restrictions": [ + { + "schema_name": "verified-email", + "issuer_did": "MTYqmTBoLT7KLP5RNfgK3b", + } + ], + }, + "req_attr_1": { + "names": ["age"], + "restrictions": [ + { + "schema_name": "verified-age", + "issuer_did": "MTYqmTBoLT7KLP5RNfgK3c", + } + ], + } + } + presentation['presentation']['requested_proof']['revealed_attr_groups'] = { + "req_attr_0": { + "sub_proof_index": 0, + "values": { + "email": { + "raw": "jamiehalebc@gmail.com", + "encoded": "73814602767252868561268261832462872577293109184327908660400248444458427915643", + } + } + }, + "req_attr_1": { + "sub_proof_index": 0, + "values": { + "age": { + "raw": "30", + "encoded": "73814602767252868561268261832462872577293109184327908660400248444458427915644", + } + } + } + } + with mock.patch.object(AuthSession, "presentation_exchange", presentation): + token = Token.get_claims(auth_session, ver_config) + assert token is not None + + +@pytest.mark.asyncio +async def test_valid_proof_presentation_with_one_attribute_and_multiple_values_returns_token(): + presentation['presentation_request']['requested_attributes'] = { + "req_attr_0": { + "names": ["email_1", "age_1"], + "restrictions": [ + { + "schema_name": "verified-email", + "issuer_did": "MTYqmTBoLT7KLP5RNfgK3b", + } + ], + }, + } + presentation['presentation']['requested_proof']['revealed_attr_groups'] = { + "req_attr_0": { + "sub_proof_index": 0, + "values": { + "email_1": { + "raw": "jamiehalebc@gmail.com", + "encoded": "73814602767252868561268261832462872577293109184327908660400248444458427915643", + }, + "age_1": { + "raw": "30", + "encoded": "73814602767252868561268261832462872577293109184327908660400248444458427915644", + } + } + } + } + with mock.patch.object(AuthSession, "presentation_exchange", presentation): + token = Token.get_claims(auth_session, ver_config) + assert token is not None + + +@pytest.mark.asyncio +async def test_revealed_attrs_dont_match_requested_attributes_throws_exception(): + presentation['presentation_request']['requested_attributes'] = { + "req_attr_0": { + "names": ["email"], + "restrictions": [ + { + "schema_name": "verified-email", + "issuer_did": "MTYqmTBoLT7KLP5RNfgK3b", + } + ], + } + } + presentation['presentation']['requested_proof']['revealed_attr_groups'] = { + "req_attr_0": { + "sub_proof_index": 0, + "values": { + "email-wrong": { + "raw": "jamiehalebc@gmail.com", + "encoded": "73814602767252868561268261832462872577293109184327908660400248444458427915643", + } + } + } + } + with mock.patch.object(AuthSession, "presentation_exchange", presentation): + with pytest.raises(Exception) as e: + Token.get_claims(auth_session, ver_config) diff --git a/oidc-controller/api/core/oidc/tests/test_idtoken_dict.py b/oidc-controller/api/core/oidc/tests/test_idtoken_dict.py new file mode 100644 index 00000000..5dfa97da --- /dev/null +++ b/oidc-controller/api/core/oidc/tests/test_idtoken_dict.py @@ -0,0 +1,9 @@ +import mock +import pytest +from api.authSessions.models import AuthSession +from api.core.oidc.issue_token_service import Token +from api.core.oidc.tests.__mocks__ import auth_session, presentation, ver_config + +@pytest.mark.asyncio +async def test_first_test(): + assert True \ No newline at end of file diff --git a/oidc-controller/api/main.py b/oidc-controller/api/main.py index 7fd8f5d3..1e99cceb 100644 --- a/oidc-controller/api/main.py +++ b/oidc-controller/api/main.py @@ -1,23 +1,31 @@ -# import api.core.logconfig + +import traceback +import structlog import os import time import uuid from pathlib import Path +from fastapi import status as http_status -import structlog import uvicorn from api.core.config import settings -from api.core.oidc.provider import init_provider from fastapi import FastAPI -from fastapi.middleware.cors import CORSMiddleware from starlette.requests import Request from starlette.responses import Response +from fastapi.responses import JSONResponse +from fastapi.middleware.cors import CORSMiddleware from .clientConfigurations.router import router as client_config_router from .db.session import get_db, init_db from .routers import acapy_handler, oidc, presentation_request, well_known_oid_config -from .routers.socketio import sio_app from .verificationConfigs.router import router as ver_configs_router +from .clientConfigurations.router import router as client_config_router +from .db.session import init_db, get_db +from .routers.socketio import sio_app +from api.core.logger_util import extract_error_msg_from_traceback_exc +from api.core.models import GenericErrorMessage + +from api.core.oidc.provider import init_provider logger: structlog.typing.FilteringBoundLogger = structlog.getLogger(__name__) @@ -73,9 +81,7 @@ 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()), @@ -86,14 +92,25 @@ async def logging_middleware(request: Request, call_next) -> Response: start_time = time.time() try: response: Response = await call_next(request) + return response finally: process_time = time.time() - start_time - logger.info( - "processed a request", - status_code=response.status_code, - process_time=process_time, - ) - return response + # If we have a response object, log the details + if 'response' in locals(): + logger.info("processed a request", status_code=response.status_code, process_time=process_time) + # Otherwise, extract the exception from traceback, log and return a 500 response + else: + logger.info("failed to process a request", status_code=500, process_time=process_time) + + # Need to explicitly log the traceback as json here. Not clear as to why. + if os.environ.get("LOG_WITH_JSON") is True: + logger.error(traceback.format_exc()) + + return JSONResponse( + status_code=http_status.HTTP_500_INTERNAL_SERVER_ERROR, + content=GenericErrorMessage( + detail=extract_error_msg_from_traceback_exc(traceback.format_exc())).dict() + ) @app.on_event("startup") diff --git a/test-signing-keys/test_signing_key.pem b/test-signing-keys/test_signing_key.pem new file mode 100644 index 00000000..49e6da5e --- /dev/null +++ b/test-signing-keys/test_signing_key.pem @@ -0,0 +1,28 @@ +-----BEGIN PRIVATE KEY----- +MIIEuwIBADANBgkqhkiG9w0BAQEFAASCBKUwggShAgEAAoIBAQCokbd2f4hszw7J +/L0wO/aEoaTBvxjTgws/uVn4sLX9ic6gMPW7FwY3ST8DvNiX5dHsSQSUvy/N4b0k +v7WIPtjpag/2c9jtlT/asrgK0S2KS4Pv7qLa4sOpgMrqbYLZSIgMXu/GIea0eQ5Y +aOBnzzQIkUswBlMSRGEFzMvgCtn8hIhFUrvamlFLh3v6cZMzudaGcm+mYkSqyoEv +sYzqoRxUN0qxDWDCBDSRFE0kmGkjjl8YnPqhg0Pi2NTwiJmfuGPoVC97j6A8kI8J +4D5KsHfj2/yH+Fh+8dimwYWzoKiSgQUFvcoQLShjd3WvdNHFLrhp6SZZBdw1eIn2 +Q7sSyO6hAgMBAAECgf8h4MDYAxZbLkHxCYDJCndA49VFtJVvIA18Teptg+MPhK91 +aMf6EczuAr20KP/4U/fpXpAziAXTgTEopMUwqXDVEe8Jv1gzND7hDr07COjEiOi7 +QvqRgxscgp94l3An7kVpakSsgHCDuzcAdBNyYyVrk2FinxX5Vd5dJaU6IcD6ce3f +8y2jIt1cAVgEqlHwR1mhZTXMc14Dd0AseGzz9sWhQ1i5wc02BMxEdN8ktNXZ/4LT +00f0Lataduo8un3TCN6xg298QjjY5ZmvbyH7xf04oYLSymo9/sSPbq8YYnvv4jn3 +MEcaJoRIzxqZlzj+6QxZMy/xf40mJRwgLXMbPgECgYEA6WnounXhPyL/LR/kRA58 +xYu349ZCMSir4yMZKgdTap9JfMzfizLbMta8pQpBgwKcQ9N4Xbdncc+bdLMQWGQI +9oOpmoqvwBL6GC4/ZCMVIR7uPKcYr9bFSramriaL6/piR1xOZMmHuYhPwxKTNbjr +Le1LpRKHUc0QIay2RnPR00ECgYEAuOF9JYf6feeAFQTMzsC8QHOpLY2lWJmW9WzF +K8o6adaW2KU35iNVvmBCkHf98InERHD/QLgORVp4/jXKNgYQ+s/5zOxs5lpBZEmr +Nh4fVM5IZUyW0onFgfgQq6CkY2u/Y5ruTy4f/Xw9ZnCf0Vr28fAPhQpcPA3eSZV+ +prTmI2ECgYBXpl+wdUeqT9gG9+zd6ZrNC9R4CCM/FojFeI6gi7O1XC9aYAyp1uUd +SCn6x8kmCzrm9WhDuPVtdYpo3j0LFDWRbIup7t5kgDvODL/dOJdcoqLPv+ezUDEy +Bzi8ONleOd3h8jW1/z+qWheppzYEfHZD/tHjIPwTqa+fFZ41ApUOgQKBgQCtDhyX +ofW+HpEMm6aeLVjJN7p3MmxAR9w/NKZHPA97fGtMtTJi0FZ1UiNcmYTwv/QgYGj9 +iouJLYut4Gm8Med47m4T/IZfBMLK/g4uJPoM5t5rO8q9nkprQulPzZmymmvW73H8 +Wd+F5eKPXgKq8+vNQXk1fiIh8JVO6YlYwGHfYQKBgG5r5M/3FtsBTNjEebKPudm+ +t+trBfht6f2kdxuC4D4ODibnCfCJ0gh/Ok7nimOdNfMQw45JgjzTmcG4Fa2gX5c6 +0imW7sYwVxDK5um+1ha/j6t3LMKs0l0lsD0Mdjesw6FVYrgGyhTx1bcYuq30nRkW +RzoS+Y65j6wrsdGLBED1 +-----END PRIVATE KEY-----