diff --git a/.bumpversion.cfg b/.bumpversion.cfg index fb19100..1599dcb 100644 --- a/.bumpversion.cfg +++ b/.bumpversion.cfg @@ -1,5 +1,5 @@ [bumpversion] -current_version = 1.12.2 +current_version = 1.13.0 commit = False tag = False diff --git a/poetry.lock b/poetry.lock index c170e81..23a222d 100644 --- a/poetry.lock +++ b/poetry.lock @@ -495,7 +495,7 @@ version = "2.0.0" description = "Foreign Function Interface for Python calling C code." optional = false python-versions = ">=3.9" -groups = ["main", "dev"] +groups = ["main"] files = [ {file = "cffi-2.0.0-cp310-cp310-macosx_10_13_x86_64.whl", hash = "sha256:0cf2d91ecc3fcc0625c2c530fe004f82c110405f101548512cce44322fa8ac44"}, {file = "cffi-2.0.0-cp310-cp310-macosx_11_0_arm64.whl", hash = "sha256:f73b96c41e3b2adedc34a7356e64c8eb96e03a3782b535e043a986276ce12a49"}, @@ -582,7 +582,6 @@ files = [ {file = "cffi-2.0.0-cp39-cp39-win_amd64.whl", hash = "sha256:b882b3df248017dba09d6b16defe9b5c407fe32fc7c65a9c69798e6175601be9"}, {file = "cffi-2.0.0.tar.gz", hash = "sha256:44d1b5909021139fe36001ae048dbdde8214afa20200eda0f64c068cac5d5529"}, ] -markers = {dev = "platform_python_implementation != \"PyPy\""} [package.dependencies] pycparser = {version = "*", markers = "implementation_name != \"PyPy\""} @@ -875,7 +874,7 @@ version = "46.0.5" description = "cryptography is a package which provides cryptographic recipes and primitives to Python developers." optional = false python-versions = "!=3.9.0,!=3.9.1,>=3.8" -groups = ["main", "dev"] +groups = ["main"] files = [ {file = "cryptography-46.0.5-cp311-abi3-macosx_10_9_universal2.whl", hash = "sha256:351695ada9ea9618b3500b490ad54c739860883df6c1f555e088eaf25b1bbaad"}, {file = "cryptography-46.0.5-cp311-abi3-manylinux2014_aarch64.manylinux_2_17_aarch64.whl", hash = "sha256:c18ff11e86df2e28854939acde2d003f7984f721eba450b56a200ad90eeb0e6b"}, @@ -2441,12 +2440,12 @@ version = "3.0" description = "C parser in Python" optional = false python-versions = ">=3.10" -groups = ["main", "dev"] +groups = ["main"] +markers = "implementation_name != \"PyPy\"" files = [ {file = "pycparser-3.0-py3-none-any.whl", hash = "sha256:b727414169a36b7d524c1c3e31839a521725078d7b2ff038656844266160a992"}, {file = "pycparser-3.0.tar.gz", hash = "sha256:600f49d217304a5902ac3c37e1281c9fe94e4d0489de643a9504c5cdfdfc6b29"}, ] -markers = {main = "implementation_name != \"PyPy\"", dev = "platform_python_implementation != \"PyPy\" and implementation_name != \"PyPy\""} [[package]] name = "pydantic" @@ -3286,21 +3285,6 @@ dev = ["autoflake (>=1.3.1,<2.0.0)", "flake8 (>=3.8.3,<4.0.0)", "pre-commit (>=2 doc = ["cairosvg (>=2.5.2,<3.0.0)", "mdx-include (>=1.4.1,<2.0.0)", "mkdocs (>=1.1.2,<2.0.0)", "mkdocs-material (>=8.1.4,<9.0.0)", "pillow (>=9.3.0,<10.0.0)"] test = ["black (>=22.3.0,<23.0.0)", "coverage (>=6.2,<7.0)", "isort (>=5.0.6,<6.0.0)", "mypy (==0.971)", "pytest (>=4.4.0,<8.0.0)", "pytest-cov (>=2.10.0,<5.0.0)", "pytest-sugar (>=0.9.4,<0.10.0)", "pytest-xdist (>=1.32.0,<4.0.0)", "rich (>=10.11.0,<14.0.0)", "shellingham (>=1.3.0,<2.0.0)"] -[[package]] -name = "types-pyopenssl" -version = "23.3.0.20240106" -description = "Typing stubs for pyOpenSSL" -optional = false -python-versions = ">=3.8" -groups = ["dev"] -files = [ - {file = "types-pyOpenSSL-23.3.0.20240106.tar.gz", hash = "sha256:3d6f3462bec0c260caadf93fbb377225c126661b779c7d9ab99b6dad5ca10db9"}, - {file = "types_pyOpenSSL-23.3.0.20240106-py3-none-any.whl", hash = "sha256:47a7eedbd18b7bcad17efebf1c53416148f5a173918a6d75027e75e32fe039ae"}, -] - -[package.dependencies] -cryptography = ">=35.0.0" - [[package]] name = "types-requests" version = "2.32.4.20260107" @@ -3826,4 +3810,4 @@ propcache = ">=0.2.1" [metadata] lock-version = "2.1" python-versions = "^3.11" -content-hash = "faa1c6cc841cf4fdcd6a047273f69eaf16eed940475560578242679deee76175" +content-hash = "fb30f6ef926f07ad4240a59963e4b5f0b5bbd23f2a37e90f2d8a54da582d2b85" diff --git a/pyproject.toml b/pyproject.toml index 38181bd..601126d 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -1,6 +1,6 @@ [tool.poetry] name = "rasenmaeher_api" -version = "1.12.2" +version = "1.13.0" description = "python-rasenmaeher-api" authors = [ "Aciid <703382+Aciid@users.noreply.github.com>", @@ -86,8 +86,8 @@ requests = "^2.31" multikeyjwt = "^1.0" uvicorn = {version = "^0.20", extras = ["standard"]} gunicorn = "^20.1" -pyopenssl = ">=25.3" -libpvarki = { version="^2.0", source="nexuslocal"} +pyopenssl = "^25.3" +libpvarki = { version="^2.2", source="nexuslocal"} openapi-readme = "^0.2" python-multipart = ">=0.0.21,<1.0.0" aiohttp = ">=3.11.10,<4.0" @@ -114,7 +114,6 @@ bump2version = "^1.0" detect-secrets = "^1.2" httpx = ">=0.23,<1.0" # caret behaviour on 0.x is to lock to 0.x.* types-requests = "^2.31" -types-pyopenssl = "^23.1" async-asgi-testclient = "^1.4" pytest-docker = "^2.0" flaky = "^3.8" diff --git a/src/rasenmaeher_api/__init__.py b/src/rasenmaeher_api/__init__.py index cb6a898..4aa2f63 100644 --- a/src/rasenmaeher_api/__init__.py +++ b/src/rasenmaeher_api/__init__.py @@ -1,3 +1,3 @@ """python-rasenmaeher-api""" -__version__ = "1.12.2" # NOTE Use `bump2version --config-file patch` to bump versions correctly +__version__ = "1.13.0" # NOTE Use `bump2version --config-file patch` to bump versions correctly diff --git a/src/rasenmaeher_api/web/api/enduserpfx/views.py b/src/rasenmaeher_api/web/api/enduserpfx/views.py index 193867b..5536b8b 100644 --- a/src/rasenmaeher_api/web/api/enduserpfx/views.py +++ b/src/rasenmaeher_api/web/api/enduserpfx/views.py @@ -2,11 +2,12 @@ import logging -from fastapi import APIRouter, HTTPException, Depends +from fastapi import APIRouter, Request, HTTPException, Depends from fastapi.responses import FileResponse from ....db import Person from ..middleware.user import ValidUser +from ..utils.auditcontext import build_audit_extra from ....rmsettings import RMSettings router = APIRouter() @@ -16,6 +17,7 @@ @router.get(f"/{{callsign}}_{RMSettings.singleton().deployment_name}.pem") @router.get("/{callsign}.pem") async def get_user_pem( + request: Request, callsign: str, person: Person = Depends(ValidUser(auto_error=True)), ) -> FileResponse: @@ -27,10 +29,33 @@ async def get_user_pem( callsign = callsign[:-4] LOGGER.debug("PEM: Called with callsign={}".format(callsign)) if person.callsign != callsign: + LOGGER.audit( # type: ignore[attr-defined] + "Certificate download denied - callsign mismatch", + extra=build_audit_extra( + action="certificate_download", + outcome="failure", + actor=person.callsign, + target=callsign, + request=request, + error_code="CALLSIGN_MISMATCH", + certificate_type="pem", + ), + ) raise HTTPException(status_code=403, detail="Callsign must match authenticated user") # Make sure the pfx exists, this is no-op if it does await person.create_pfx() + LOGGER.audit( # type: ignore[attr-defined] + "Certificate downloaded", + extra=build_audit_extra( + action="certificate_download", + outcome="success", + actor=person.callsign, + request=request, + certificate_type="pem", + ), + ) + return FileResponse( path=person.certfile, media_type="application/x-pem-file", @@ -42,6 +67,7 @@ async def get_user_pem( @router.get("/{callsign}.pfx") @router.get("/{callsign}") async def get_user_pfx( + request: Request, callsign: str, person: Person = Depends(ValidUser(auto_error=True)), ) -> FileResponse: @@ -57,13 +83,36 @@ async def get_user_pfx( callsign = callsign[:-4] if callsign.endswith(".pem"): LOGGER.debug("PFX: got .pem suffix, delegating") - return await get_user_pem(callsign, person) + return await get_user_pem(request, callsign, person) LOGGER.debug("PFX: Called with callsign={}".format(callsign)) if person.callsign != callsign: + LOGGER.audit( # type: ignore[attr-defined] + "Certificate download denied - callsign mismatch", + extra=build_audit_extra( + action="certificate_download", + outcome="failure", + actor=person.callsign, + target=callsign, + request=request, + error_code="CALLSIGN_MISMATCH", + certificate_type="pfx", + ), + ) raise HTTPException(status_code=403, detail="Callsign must match authenticated user") # Make sure the pfx exists, this is no-op if it does await person.create_pfx() + LOGGER.audit( # type: ignore[attr-defined] + "Certificate downloaded", + extra=build_audit_extra( + action="certificate_download", + outcome="success", + actor=person.callsign, + request=request, + certificate_type="pfx", + ), + ) + return FileResponse( path=person.pfxfile, media_type="application/x-pkcs12", diff --git a/src/rasenmaeher_api/web/api/enrollment/views.py b/src/rasenmaeher_api/web/api/enrollment/views.py index 01347d2..511e380 100644 --- a/src/rasenmaeher_api/web/api/enrollment/views.py +++ b/src/rasenmaeher_api/web/api/enrollment/views.py @@ -34,6 +34,7 @@ ) from ..middleware.mtls import MTLSorJWT from ..middleware.user import ValidUser +from ..utils.auditcontext import build_audit_extra from ....db import Person from ....db import Enrollment, EnrollmentPool from ....db.errors import NotFound @@ -77,7 +78,21 @@ async def post_generate_verification_code( """ Update/Generate verification_code to database for given jwt/mtls """ - _verification_code = await Enrollment.reset_approvecode4callsign(callsign=request.state.mtls_or_jwt.userid) + callsign = request.state.mtls_or_jwt.userid + + _verification_code = await Enrollment.reset_approvecode4callsign(callsign=callsign) + + LOGGER.audit( # type: ignore[attr-defined] + "Verification code generated", + extra=build_audit_extra( + action="verification_code_generate", + outcome="success", + actor=callsign, + target=callsign, + request=request, + ), + ) + return EnrollmentGenVerifiOut(verification_code=f"{_verification_code}") @@ -177,20 +192,31 @@ async def request_enrollment_list(code: Optional[str] = None) -> EnrollmentListO dependencies=[Depends(ValidUser(auto_error=True, require_roles=["admin"]))], ) async def request_enrollment_init( + request: Request, request_in: EnrollmentInitIn = Body(), ) -> EnrollmentInitOut: """ Add new callsign (enrollment) to environment. """ + callsign = request_in.callsign # TODO ADD POOL NAME CHECK - new_enrollment = await Enrollment.create_for_callsign( - callsign=request_in.callsign, pool=None, extra={}, csr=request_in.csr - ) + new_enrollment = await Enrollment.create_for_callsign(callsign=callsign, pool=None, extra={}, csr=request_in.csr) # Create JWT token for user - claims = {"sub": request_in.callsign} + claims = {"sub": callsign} new_jwt = Issuer.singleton().issue(claims) + + LOGGER.audit( # type: ignore[attr-defined] + "Enrollment initiated by admin", + extra=build_audit_extra( + action="enrollment_init", + outcome="success", + target=callsign, + request=request, + ), + ) + return EnrollmentInitOut(callsign=new_enrollment.callsign, jwt=new_jwt, approvecode=new_enrollment.approvecode) @@ -206,13 +232,46 @@ async def request_enrollment_promote( """ "Promote" callsign/user/enrollment to have 'admin' rights """ + target_callsign = request_in.callsign - obj = await Person.by_callsign(callsign=request_in.callsign) + try: + obj = await Person.by_callsign(callsign=target_callsign) + except NotFound as exc: + LOGGER.audit( # type: ignore[attr-defined] + "User promotion failed - user not found", + extra=build_audit_extra( + action="user_promote", + outcome="failure", + target=target_callsign, + request=request, + error_code="USER_NOT_FOUND", + ), + ) + raise HTTPException(status_code=404, detail="User not found") from exc role_added = await obj.assign_role(role="admin") if role_added: + LOGGER.audit( # type: ignore[attr-defined] + "User promoted to admin", + extra=build_audit_extra( + action="user_promote", + outcome="success", + target=target_callsign, + request=request, + ), + ) return OperationResultResponse(success=True, extra="Promote done") + LOGGER.audit( # type: ignore[attr-defined] + "User promotion failed - already admin", + extra=build_audit_extra( + action="user_promote", + outcome="failure", + target=target_callsign, + request=request, + error_code="ALREADY_ADMIN", + ), + ) reason = "Given callsign/callsign already has elevated permissions." LOGGER.error("{} : {}".format(request.url, reason)) raise HTTPException(status_code=400, detail=reason) @@ -230,12 +289,46 @@ async def request_enrollment_demote( """ "Demote" callsign/user/enrollment from having 'admin' rights. callsign_hash can be used too. """ + target_callsign = request_in.callsign + + try: + obj = await Person.by_callsign(callsign=target_callsign) + except NotFound as exc: + LOGGER.audit( # type: ignore[attr-defined] + "User demotion failed - user not found", + extra=build_audit_extra( + action="user_demote", + outcome="failure", + target=target_callsign, + request=request, + error_code="USER_NOT_FOUND", + ), + ) + raise HTTPException(status_code=404, detail="User not found") from exc - obj = await Person.by_callsign(callsign=request_in.callsign) _role_removed = await obj.remove_role(role="admin") if _role_removed: + LOGGER.audit( # type: ignore[attr-defined] + "User demoted from admin", + extra=build_audit_extra( + action="user_demote", + outcome="success", + target=target_callsign, + request=request, + ), + ) return OperationResultResponse(success=True, extra="Demote done") + LOGGER.audit( # type: ignore[attr-defined] + "User demotion failed - not an admin", + extra=build_audit_extra( + action="user_demote", + outcome="failure", + target=target_callsign, + request=request, + error_code="NOT_ADMIN", + ), + ) _reason = "Given callsign/callsign_hash doesn't have 'admin' privileges to take away." LOGGER.error("{} : {}".format(request.url, _reason)) raise HTTPException(status_code=400, detail=_reason) @@ -253,11 +346,37 @@ async def request_enrollment_lock( """ Lock callsign/user/enrollment so it cannot be used anymore. """ + target_callsign = request_in.callsign + actor = request.state.mtls_or_jwt.userid + + try: + _admin_person = await Person.by_callsign(actor) + _usr_enrollment = await Enrollment.by_callsign(callsign=target_callsign) + except NotFound as exc: + LOGGER.audit( # type: ignore[attr-defined] + "Enrollment lock failed - not found", + extra=build_audit_extra( + action="enrollment_lock", + outcome="failure", + target=target_callsign, + request=request, + error_code="NOT_FOUND", + ), + ) + raise HTTPException(status_code=404, detail="Enrollment not found") from exc - _admin_person = await Person.by_callsign(request.state.mtls_or_jwt.userid) - _usr_enrollment = await Enrollment.by_callsign(callsign=request_in.callsign) await _usr_enrollment.reject(decider=_admin_person) + LOGGER.audit( # type: ignore[attr-defined] + "Enrollment locked/rejected", + extra=build_audit_extra( + action="enrollment_lock", + outcome="success", + target=target_callsign, + request=request, + ), + ) + return OperationResultResponse(success=True, extra="Lock task done") @@ -273,13 +392,50 @@ async def post_enrollment_accept( """ Accept callsign_hash (callsign/enrollment) """ + target_callsign = request_in.callsign + actor = request.state.mtls_or_jwt.userid + + try: + admin_user = await Person.by_callsign(callsign=actor) + pending_enrollment = await Enrollment.by_callsign(callsign=target_callsign) + except NotFound as exc: + LOGGER.audit( # type: ignore[attr-defined] + "Enrollment approval failed - not found", + extra=build_audit_extra( + action="enrollment_approve", + outcome="failure", + target=target_callsign, + request=request, + error_code="NOT_FOUND", + ), + ) + raise HTTPException(status_code=404, detail="Enrollment not found") from exc - admin_user = await Person.by_callsign(callsign=request.state.mtls_or_jwt.userid) - pending_enrollment = await Enrollment.by_callsign(callsign=request_in.callsign) if request_in.approvecode != pending_enrollment.approvecode: + LOGGER.audit( # type: ignore[attr-defined] + "Enrollment approval failed - invalid approvecode", + extra=build_audit_extra( + action="enrollment_approve", + outcome="failure", + target=target_callsign, + request=request, + error_code="INVALID_APPROVECODE", + ), + ) raise HTTPException(status_code=403, detail="Invalid approval code for this enrollment") + new_approved_user = await pending_enrollment.approve(approver=admin_user) + LOGGER.audit( # type: ignore[attr-defined] + "Enrollment approved", + extra=build_audit_extra( + action="enrollment_approve", + outcome="success", + target=target_callsign, + request=request, + ), + ) + return OperationResultResponse(success=True, extra=f"Approved {new_approved_user.callsign}") @@ -292,7 +448,19 @@ async def post_invite_code(request: Request) -> EnrollmentInviteCodeCreateOut: """ Create a new invite code """ + pool = await EnrollmentPool.create_for_owner(request.state.person) + + LOGGER.audit( # type: ignore[attr-defined] + "Invite code created", + extra=build_audit_extra( + action="invitecode_create", + outcome="success", + request=request, + invitecode_id=str(pool.pk), + ), + ) + return EnrollmentInviteCodeCreateOut(invite_code=pool.invitecode) @@ -304,12 +472,45 @@ async def put_activate_invite_code( """ Activate an invite code """ - obj = await EnrollmentPool.by_invitecode(invitecode=request_in.invite_code) + + try: + obj = await EnrollmentPool.by_invitecode(invitecode=request_in.invite_code) + except NotFound as exc: + LOGGER.audit( # type: ignore[attr-defined] + "Invite code activation failed - not found", + extra=build_audit_extra( + action="invitecode_activate", + outcome="failure", + request=request, + error_code="NOT_FOUND", + ), + ) + raise HTTPException(status_code=404, detail="Invite code not found") from exc + _activated_obj = await obj.set_active(state=True) if _activated_obj.active: - return OperationResultResponse(success=True, extra=f"Activated {request_in.invite_code}") - + LOGGER.audit( # type: ignore[attr-defined] + "Invite code activated", + extra=build_audit_extra( + action="invitecode_activate", + outcome="success", + request=request, + invitecode_id=str(obj.pk), + ), + ) + return OperationResultResponse(success=True, extra=f"Activated invite code {obj.pk}") + + LOGGER.audit( # type: ignore[attr-defined] + "Invite code activation failed", + extra=build_audit_extra( + action="invitecode_activate", + outcome="failure", + request=request, + invitecode_id=str(obj.pk), + error_code="ACTIVATION_FAILED", + ), + ) _reason = "Error. Unable to activate given invitecode." LOGGER.error("{} : {}".format(request.url, _reason)) raise HTTPException(status_code=500, detail=_reason) @@ -323,12 +524,45 @@ async def put_deactivate_invite_code( """ Deactivate an invite code """ - obj = await EnrollmentPool.by_invitecode(invitecode=request_in.invite_code) + + try: + obj = await EnrollmentPool.by_invitecode(invitecode=request_in.invite_code) + except NotFound as exc: + LOGGER.audit( # type: ignore[attr-defined] + "Invite code deactivation failed - not found", + extra=build_audit_extra( + action="invitecode_deactivate", + outcome="failure", + request=request, + error_code="NOT_FOUND", + ), + ) + raise HTTPException(status_code=404, detail="Invite code not found") from exc + _deactivated_obj = await obj.set_active(state=False) if _deactivated_obj.active is False: - return OperationResultResponse(success=True, extra=f"Disabled {request_in.invite_code}") - + LOGGER.audit( # type: ignore[attr-defined] + "Invite code deactivated", + extra=build_audit_extra( + action="invitecode_deactivate", + outcome="success", + request=request, + invitecode_id=str(obj.pk), + ), + ) + return OperationResultResponse(success=True, extra=f"Disabled invite code {obj.pk}") + + LOGGER.audit( # type: ignore[attr-defined] + "Invite code deactivation failed", + extra=build_audit_extra( + action="invitecode_deactivate", + outcome="failure", + request=request, + invitecode_id=str(obj.pk), + error_code="DEACTIVATION_FAILED", + ), + ) _reason = "Error. Unable to deactivate given invitecode." LOGGER.error("{} : {}".format(request.url, _reason)) raise HTTPException(status_code=500, detail=_reason) @@ -336,18 +570,40 @@ async def put_deactivate_invite_code( @ENROLLMENT_ROUTER.delete("/invitecode/{invite_code}", response_model=OperationResultResponse) async def delete_invite_code( - # request: Request, + request: Request, invite_code: str, ) -> OperationResultResponse: """ Delete an invite code """ + try: obj = await EnrollmentPool.by_invitecode(invitecode=invite_code) + pool_pk = str(obj.pk) await obj.delete() + + LOGGER.audit( # type: ignore[attr-defined] + "Invite code deleted", + extra=build_audit_extra( + action="invitecode_delete", + outcome="success", + request=request, + invitecode_id=pool_pk, + ), + ) + return OperationResultResponse(success=True, extra="Invitecode was deleted") - except NotFound: - return OperationResultResponse(success=False, extra="No such invitecode found") + except NotFound as exc: + LOGGER.audit( # type: ignore[attr-defined] + "Invite code deletion failed - not found", + extra=build_audit_extra( + action="invitecode_delete", + outcome="failure", + request=request, + error_code="NOT_FOUND", + ), + ) + raise HTTPException(status_code=404, detail="Invite code not found") from exc @NO_JWT_ENROLLMENT_ROUTER.get("/invitecode", response_model=EnrollmentIsInvitecodeActiveOut) @@ -358,6 +614,8 @@ async def get_invite_codes( /invitecode?invitecode=xxx Returns true/false if the code is usable or not """ + # Note: This is a check endpoint similar to firstuser/check-code + # Not logging at audit level to avoid noise from normal UI flow try: obj = await EnrollmentPool.by_invitecode(invitecode=params.invitecode) if obj.active: @@ -375,27 +633,76 @@ async def post_enroll_invite_code( """ Enroll with an invite code """ + callsign = request_in.callsign # CHECK IF INVITE CODE CAN BE USED - obj = await EnrollmentPool.by_invitecode(invitecode=request_in.invite_code) + try: + obj = await EnrollmentPool.by_invitecode(invitecode=request_in.invite_code) + except NotFound as exc: + LOGGER.audit( # type: ignore[attr-defined] + "Enrollment via invitecode failed - code not found", + extra=build_audit_extra( + action="enrollment_invitecode", + outcome="failure", + target=callsign, + request=request, + error_code="INVITECODE_NOT_FOUND", + ), + ) + raise HTTPException(status_code=404, detail="Invite code not found") from exc + if obj.active is False: + LOGGER.audit( # type: ignore[attr-defined] + "Enrollment via invitecode failed - code disabled", + extra=build_audit_extra( + action="enrollment_invitecode", + outcome="failure", + target=callsign, + request=request, + error_code="INVITECODE_DISABLED", + invitecode_id=str(obj.pk), + ), + ) _reason = "Error. invitecode disabled." LOGGER.error("{} : {}".format(request.url, _reason)) raise HTTPException(status_code=400, detail=_reason) # CHECK THAT THE CALLSIGN CAN BE USED try: - await Enrollment.by_callsign(callsign=request_in.callsign) + await Enrollment.by_callsign(callsign=callsign) + LOGGER.audit( # type: ignore[attr-defined] + "Enrollment via invitecode failed - callsign taken", + extra=build_audit_extra( + action="enrollment_invitecode", + outcome="failure", + target=callsign, + request=request, + error_code="CALLSIGN_TAKEN", + invitecode_id=str(obj.pk), + ), + ) _reason = "Error. callsign/callsign already taken." LOGGER.error("{} : {}".format(request.url, _reason)) raise HTTPException(status_code=400, detail=_reason) except NotFound: pass - enrollment = await obj.create_enrollment(callsign=request_in.callsign, csr=request_in.csr) + enrollment = await obj.create_enrollment(callsign=callsign, csr=request_in.csr) # Create JWT token for user - claims = {"sub": request_in.callsign} + claims = {"sub": callsign} new_jwt = Issuer.singleton().issue(claims) + LOGGER.audit( # type: ignore[attr-defined] + "Enrollment via invitecode successful", + extra=build_audit_extra( + action="enrollment_invitecode", + outcome="success", + actor=callsign, + target=callsign, + request=request, + invitecode_id=str(obj.pk), + ), + ) + return EnrollmentInitOut(callsign=enrollment.callsign, jwt=new_jwt, approvecode=enrollment.approvecode) diff --git a/src/rasenmaeher_api/web/api/firstuser/views.py b/src/rasenmaeher_api/web/api/firstuser/views.py index 481cba3..a2e1006 100644 --- a/src/rasenmaeher_api/web/api/firstuser/views.py +++ b/src/rasenmaeher_api/web/api/firstuser/views.py @@ -13,7 +13,7 @@ FirstuserAddAdminIn, FirstuserAddAdminOut, ) - +from ..utils.auditcontext import build_audit_extra from ....db import Person from ....db import LoginCode from ....db import Enrollment @@ -23,7 +23,6 @@ LOGGER = logging.getLogger(__name__) -# /check-code @router.get("/check-code", response_model=FirstuserCheckCodeOut) async def get_check_code( request: Request, @@ -36,24 +35,53 @@ async def get_check_code( try: res = await LoginCode.by_code(code=params.temp_admin_code) except NotFound: + # Note: This also triggers when UI checks if an invitecode is a firstuser code + # which is normal flow - not logging at audit level to avoid noise + LOGGER.debug("First user code check - code not found") return FirstuserCheckCodeOut(code_ok=False) # This error should already be raised in LoginCode if not res: + LOGGER.audit( # type: ignore[attr-defined] + "First user code check failed - backend error", + extra=build_audit_extra( + action="firstuser_code_check", + outcome="failure", + request=request, + error_code="BACKEND_ERROR", + ), + ) _reason = "Error. Undefined backend error q_ssjsfjwe1" LOGGER.error("{} : {}".format(request.url, _reason)) raise HTTPException(status_code=500, detail=_reason) # Code already used err. if res.used_on is not None: + LOGGER.audit( # type: ignore[attr-defined] + "First user code check failed - code already used (possible replay attempt)", + extra=build_audit_extra( + action="firstuser_code_check", + outcome="failure", + request=request, + error_code="CODE_ALREADY_USED", + ), + ) _reason = "Code already used" LOGGER.error("{} : {}".format(request.url, _reason)) raise HTTPException(status_code=403, detail=_reason) + LOGGER.audit( + "First user code check successful", + extra=build_audit_extra( + action="firstuser_code_check", + outcome="success", + request=request, + ), + ) + return FirstuserCheckCodeOut(code_ok=True) -# /add-admin @router.post("/add-admin", response_model=FirstuserAddAdminOut) async def post_admin_add( request: Request, @@ -63,7 +91,19 @@ async def post_admin_add( """ Add callsign aka username/identity. This callsign is also elevated to have managing permissions. """ + callsign = request_in.callsign + if not jwt.get("anon_admin_session", False): + LOGGER.audit( # type: ignore[attr-defined] + "First admin creation rejected - JWT missing anon_admin_session claim", + extra=build_audit_extra( + action="firstuser_admin_create", + outcome="failure", + target=callsign, + request=request, + error_code="MISSING_ANON_ADMIN_CLAIM", + ), + ) LOGGER.error("Requesting JWT must have admin session claim") raise HTTPException(status_code=403, detail="Forbidden") @@ -73,11 +113,17 @@ async def post_admin_add( if not anon_admin_added: anon_user = await Person.create_with_cert(callsign="anon_admin", extra={}) await anon_user.assign_role(role="anon_admin") + LOGGER.audit( # type: ignore[attr-defined] + "Bootstrap anon_admin user created", + extra=build_audit_extra( + action="firstuser_bootstrap", + outcome="success", + request=request, + ), + ) # Create new admin user enrollment - enrollment = await Enrollment.create_for_callsign( - callsign=request_in.callsign, pool=None, extra={}, csr=request_in.csr - ) + enrollment = await Enrollment.create_for_callsign(callsign=callsign, pool=None, extra={}, csr=request_in.csr) # Get the anon_admin 'user' that will be used to approve the new admin user # and approve the user @@ -98,6 +144,16 @@ async def tms_wait() -> None: role_add_success = await new_admin.assign_role(role="admin") if role_add_success is False: + LOGGER.audit( # type: ignore[attr-defined] + "First admin creation failed - user already admin", + extra=build_audit_extra( + action="firstuser_admin_create", + outcome="failure", + target=callsign, + request=request, + error_code="ALREADY_ADMIN", + ), + ) reason = "Error. User already admin. This shouldn't happen..." LOGGER.error("{} : {}".format(request.url, reason)) raise HTTPException(status_code=400, detail=reason) @@ -105,4 +161,14 @@ async def tms_wait() -> None: # Create JWT token for new admin user code = await LoginCode.create_for_claims(claims={"sub": request_in.callsign}) + LOGGER.audit( # type: ignore[attr-defined] + "First admin user created successfully", + extra=build_audit_extra( + action="firstuser_admin_create", + outcome="success", + target=callsign, + request=request, + ), + ) + return FirstuserAddAdminOut(admin_added=True, jwt_exchange_code=code) diff --git a/src/rasenmaeher_api/web/api/people/views.py b/src/rasenmaeher_api/web/api/people/views.py index 1d25834..52550f2 100644 --- a/src/rasenmaeher_api/web/api/people/views.py +++ b/src/rasenmaeher_api/web/api/people/views.py @@ -3,8 +3,7 @@ from typing import List, Optional import logging - -from fastapi import APIRouter, Depends +from fastapi import APIRouter, Request, Depends, HTTPException from libpvarki.schemas.generic import OperationResultResponse from .schema import ( @@ -13,8 +12,9 @@ ) from ..middleware.mtls import MTLSorJWT from ..middleware.user import ValidUser +from ..utils.auditcontext import build_audit_extra from ....db import Person -from ....db.errors import BackendError +from ....db.errors import BackendError, NotFound LOGGER = logging.getLogger(__name__) @@ -106,12 +106,58 @@ async def request_people_list_byrole(role: str) -> PeopleListOut: response_model=OperationResultResponse, dependencies=[Depends(ValidUser(auto_error=True, require_roles=["admin"]))], ) -async def delete_person(callsign: str) -> OperationResultResponse: +async def delete_person(request: Request, callsign: str) -> OperationResultResponse: """delete==revoke a callsign""" - person = await Person.by_callsign(callsign) + + try: + person = await Person.by_callsign(callsign) + except NotFound as exc: + LOGGER.audit( # type: ignore[attr-defined] + "User revocation failed - user not found", + extra=build_audit_extra( + action="user_revoke", + outcome="failure", + target=callsign, + request=request, + error_code="USER_NOT_FOUND", + ), + ) + raise HTTPException(status_code=404, detail="User not found") from exc try: deleted = await person.delete() + if deleted: + LOGGER.audit( # type: ignore[attr-defined] + "User revoked", + extra=build_audit_extra( + action="user_revoke", + outcome="success", + target=callsign, + request=request, + ), + ) + else: + LOGGER.audit( # type: ignore[attr-defined] + "User revocation returned false", + extra=build_audit_extra( + action="user_revoke", + outcome="failure", + target=callsign, + request=request, + error_code="DELETE_RETURNED_FALSE", + ), + ) return OperationResultResponse(success=deleted) except BackendError as exc: + LOGGER.audit( # type: ignore[attr-defined] + "User revocation failed - backend error", + extra=build_audit_extra( + action="user_revoke", + outcome="failure", + target=callsign, + request=request, + error_code="BACKEND_ERROR", + error_message=str(exc), + ), + ) LOGGER.error("Backend failure: {}".format(exc)) return OperationResultResponse(success=False, error=str(exc)) diff --git a/src/rasenmaeher_api/web/api/tokens/views.py b/src/rasenmaeher_api/web/api/tokens/views.py index f961c39..dd3bc14 100644 --- a/src/rasenmaeher_api/web/api/tokens/views.py +++ b/src/rasenmaeher_api/web/api/tokens/views.py @@ -2,12 +2,13 @@ import logging -from fastapi import APIRouter, HTTPException, Depends +from fastapi import APIRouter, Request, HTTPException, Depends from multikeyjwt import Verifier, Issuer from multikeyjwt.middleware import JWTBearer, JWTPayload from .schema import JWTExchangeRequestResponse, LoginCodeCreateRequest, LoginCodeRequestResponse +from ..utils.auditcontext import build_audit_extra from ....db import SeenToken, LoginCode router = APIRouter() @@ -16,27 +17,78 @@ @router.post("/jwt/exchange", tags=["tokens"], response_model=JWTExchangeRequestResponse) -async def exchange_token(req: JWTExchangeRequestResponse) -> JWTExchangeRequestResponse: +async def exchange_token(request: Request, req: JWTExchangeRequestResponse) -> JWTExchangeRequestResponse: """API method for converting TILAUSPALVELU issues single-use JWT to RASENMAEHER session JWT""" LOGGER.debug("Called") payload = Verifier.singleton().decode(req.jwt) if not payload: LOGGER.info("No acceptable token found") + LOGGER.audit( # type: ignore[attr-defined] + "JWT exchange failed - invalid token", + extra=build_audit_extra( + action="jwt_exchange", + outcome="failure", + request=request, + error_code="INVALID_TOKEN", + ), + ) raise HTTPException(status_code=403, detail="Not authenticated") if "nonce" not in payload: LOGGER.error("No nonce given, this is not allowed") + LOGGER.audit( # type: ignore[attr-defined] + "JWT exchange failed - missing nonce", + extra=build_audit_extra( + action="jwt_exchange", + outcome="failure", + request=request, + error_code="MISSING_NONCE", + ), + ) raise HTTPException(status_code=403, detail="Not authenticated") - # This will throw 403 compatible exception for reuser - await SeenToken.use_token(payload["nonce"]) + + # This will throw 403 compatible exception for reuse + try: + await SeenToken.use_token(payload["nonce"]) + except HTTPException: + LOGGER.audit( # type: ignore[attr-defined] + "JWT exchange failed - nonce reuse (possible replay attack)", + extra=build_audit_extra( + action="jwt_exchange", + outcome="failure", + request=request, + error_code="NONCE_REUSE", + ), + ) + raise + # We don't strictly *need* to check this but it makes unusable claim sets much more obvious earlier if not payload.get("anon_admin_session", False): LOGGER.error("This token cannot be exchanged for anonymous admin session") + LOGGER.audit( # type: ignore[attr-defined] + "JWT exchange failed - not anon_admin_session token", + extra=build_audit_extra( + action="jwt_exchange", + outcome="failure", + request=request, + error_code="NOT_ANON_ADMIN_SESSION", + ), + ) raise HTTPException(status_code=403, detail="Not authenticated") # Copy the claims to the session token new_jwt = Issuer.singleton().issue( {key: val for key, val in payload.items() if key not in TOKEN_COPY_EXCLUDE_FIELDS} ) + + LOGGER.audit( # type: ignore[attr-defined] + "JWT exchange successful - anon_admin session created", + extra=build_audit_extra( + action="jwt_exchange", + outcome="success", + request=request, + ), + ) + resp = JWTExchangeRequestResponse(jwt=new_jwt) LOGGER.debug("returning {}".format(resp)) return resp @@ -46,6 +98,7 @@ async def exchange_token(req: JWTExchangeRequestResponse) -> JWTExchangeRequestR async def refresh_token(jwt: JWTPayload = Depends(JWTBearer(auto_error=True))) -> JWTExchangeRequestResponse: """Refresh your JWT""" # Copy all claims to fresh token + # Note: Not audited - normal session maintenance, would be too noisy LOGGER.debug("Called") new_jwt = Issuer.singleton().issue({key: val for key, val in jwt.items() if key not in TOKEN_COPY_EXCLUDE_FIELDS}) resp = JWTExchangeRequestResponse(jwt=new_jwt) @@ -55,28 +108,97 @@ async def refresh_token(jwt: JWTPayload = Depends(JWTBearer(auto_error=True))) - @router.post("/code/generate", tags=["tokens"], response_model=LoginCodeRequestResponse) async def create_code( - req: LoginCodeCreateRequest, jwt: JWTPayload = Depends(JWTBearer(auto_error=True)) + request: Request, + req: LoginCodeCreateRequest, + jwt: JWTPayload = Depends(JWTBearer(auto_error=True)), ) -> LoginCodeRequestResponse: """Generate an alphanumeric code that can be exchanged for JWT with the given claims""" LOGGER.debug("Called") + + # Actor from JWT subject (may be None for anon sessions) + actor = jwt.get("sub") + if not jwt.get("anon_admin_session", False): LOGGER.error("Requesting JWT must have admin session claim") + LOGGER.audit( # type: ignore[attr-defined] + "Login code generation failed - missing anon_admin_session claim", + extra=build_audit_extra( + action="logincode_generate", + outcome="failure", + actor=actor, + request=request, + error_code="MISSING_ANON_ADMIN_CLAIM", + ), + ) raise HTTPException(status_code=403, detail="Forbidden") + code = await LoginCode.create_for_claims(req.claims) + + # Extract subject from claims if present for audit trail + target_subject = req.claims.get("sub") if req.claims else None + + LOGGER.audit( # type: ignore[attr-defined] + "Login code generated", + extra=build_audit_extra( + action="logincode_generate", + outcome="success", + actor=actor, + target=target_subject, + request=request, + ), + ) + resp = LoginCodeRequestResponse(code=code) LOGGER.debug("returning {}".format(resp)) return resp @router.post("/code/exchange", tags=["tokens"], response_model=JWTExchangeRequestResponse) -async def exchange_code(req: LoginCodeRequestResponse) -> JWTExchangeRequestResponse: +async def exchange_code(request: Request, req: LoginCodeRequestResponse) -> JWTExchangeRequestResponse: """Exchange code for JWT""" LOGGER.debug("Called") if not req.code: LOGGER.info("No code given") + LOGGER.audit( # type: ignore[attr-defined] + "Login code exchange failed - no code provided", + extra=build_audit_extra( + action="logincode_exchange", + outcome="failure", + request=request, + error_code="NO_CODE_PROVIDED", + ), + ) raise HTTPException(status_code=403, detail="Not authenticated") - new_jwt = await LoginCode.use_code(req.code) + try: + new_jwt = await LoginCode.use_code(req.code) + except HTTPException: + # LoginCode.use_code raises HTTPException for invalid/used codes + LOGGER.audit( # type: ignore[attr-defined] + "Login code exchange failed - invalid or expired code", + extra=build_audit_extra( + action="logincode_exchange", + outcome="failure", + request=request, + error_code="INVALID_CODE", + ), + ) + raise + + # Decode the new JWT to get subject for audit trail + payload = Verifier.singleton().decode(new_jwt) + target_subject = payload.get("sub") if payload else None + + LOGGER.audit( # type: ignore[attr-defined] + "Login code exchange successful", + extra=build_audit_extra( + action="logincode_exchange", + outcome="success", + target=target_subject, + request=request, + ), + ) + resp = JWTExchangeRequestResponse(jwt=new_jwt) LOGGER.debug("returning {}".format(resp)) return resp diff --git a/src/rasenmaeher_api/web/api/utils/auditcontext.py b/src/rasenmaeher_api/web/api/utils/auditcontext.py new file mode 100644 index 0000000..e280117 --- /dev/null +++ b/src/rasenmaeher_api/web/api/utils/auditcontext.py @@ -0,0 +1,217 @@ +# src/rasenmaeher_api/web/api/utils/auditcontext.py +"""Audit logging helpers for extracting request context. + +Intentionally a temporary solution until the libpvarki auditlogging is extended. + +Assumes nginx overwrites the relevant headers: +- X-Real-IP +- X-Forwarded-For +- X-Request-ID +- X-SSL-Client-Fingerprint +- X-ClientCert-DN +- X-ClientCert-Serial +""" + +from __future__ import annotations + +from typing import Any, Dict, Optional +import logging + +from cryptography import x509 +from fastapi import Request + +_MAX_HEADER_LEN = 256 +_MAX_FINGERPRINT_LEN = 128 +LOGGER = logging.getLogger(__name__) + + +def _clean_header(value: Optional[str], *, max_len: int = _MAX_HEADER_LEN) -> str: + """Trim and clamp header values to avoid log injection / runaway payloads.""" + if not value: + return "" + cleaned = value.strip().replace("\n", "").replace("\r", "") + if not cleaned: + return "" + return cleaned[:max_len] + + +def _first_xff_ip(xff: str) -> str: + """Extract the first entry of X-Forwarded-For.""" + return xff.split(",", maxsplit=1)[0].strip() + + +def _resolve_actor_from_request( + request: Request, + *, + trust_proxy_headers: bool = True, +) -> str: + """Resolve the actor (caller identity) from request headers. + + Resolution order: + 1) Extract CN value from X-ClientCert-DN (e.g. "CN=ffdf" -> "ffdf") + 2) X-SSL-Client-Fingerprint (fallback stable identifier) + 3) "unknown" + + :param request: Incoming FastAPI request. + :param trust_proxy_headers: Whether to trust proxy-set headers. + :returns: A best-effort actor string. + """ + if not trust_proxy_headers: + return "unknown" + + cert_dn = _clean_header(request.headers.get("X-ClientCert-DN")) + if cert_dn: + try: + name = x509.Name.from_rfc4514_string(cert_dn) + cn_attrs = name.get_attributes_for_oid(x509.oid.NameOID.COMMON_NAME) + if cn_attrs and isinstance(cn_attrs[0].value, str): + return cn_attrs[0].value + except ValueError: + LOGGER.debug("Failed to parse X-ClientCert-DN as RFC 4514: %s", cert_dn) + + cert_fp = _clean_header( + request.headers.get("X-SSL-Client-Fingerprint"), + max_len=_MAX_FINGERPRINT_LEN, + ) + if cert_fp: + return cert_fp + + return "unknown" + + +def get_audit_request_context( + request: Request, + *, + trust_proxy_headers: bool = True, +) -> Dict[str, str]: + """Extract request context for audit logging. + + Returns the following ECS 1.6.0 compliant keys: + - source.ip + - client.ip + - transaction.id + - tls.client.hash.sha256 from X-SSL-Client-Fingerprint + - tls.client.x509.subject.distinguished_name from X-ClientCert-DN + - tls.client.x509.serial_number from X-ClientCert-Serial + """ + client_ip = _clean_header(request.client.host) if request.client and request.client.host else "unknown" + + source_ip = "unknown" + if trust_proxy_headers: + x_real_ip = _clean_header(request.headers.get("X-Real-IP")) + xff = _clean_header(request.headers.get("X-Forwarded-For")) + if x_real_ip: + source_ip = x_real_ip + elif xff: + source_ip = _first_xff_ip(xff) + + if source_ip == "unknown": + source_ip = client_ip + + ctx: Dict[str, str] = { + "source.ip": source_ip, + "client.ip": client_ip, + } + + request_id = _clean_header(request.headers.get("X-Request-ID")) + if request_id: + ctx["transaction.id"] = request_id + + cert_fp = _clean_header( + request.headers.get("X-SSL-Client-Fingerprint"), + max_len=_MAX_FINGERPRINT_LEN, + ) + if cert_fp: + ctx["tls.client.hash.sha256"] = cert_fp + + cert_dn = _clean_header(request.headers.get("X-ClientCert-DN")) + if cert_dn: + ctx["tls.client.x509.subject.distinguished_name"] = cert_dn + + cert_serial = _clean_header(request.headers.get("X-ClientCert-Serial")) + if cert_serial: + ctx["tls.client.x509.serial_number"] = cert_serial + + return ctx + + +def format_audit_request_context(ctx: Dict[str, str]) -> str: + """Format request context as a stable, log-friendly string. + + Useful when extra fields aren't ingested into JSON by the log pipeline. + """ + parts = [ + f"source.ip={ctx.get('source.ip', 'unknown')}", + f"client.ip={ctx.get('client.ip', 'unknown')}", + ] + + for key in ( + "transaction.id", + "tls.client.hash.sha256", + "tls.client.x509.serial_number", + "tls.client.x509.subject.distinguished_name", + ): + value = ctx.get(key) + if value: + parts.append(f"{key}={value}") + + return " ".join(parts) + + +def build_audit_extra( # pylint: disable=too-many-arguments + *, + action: str, + outcome: str, + actor: Optional[str] = None, + target: Optional[str] = None, + request: Optional[Request] = None, + trust_proxy_headers: bool = True, + **extra_fields: Any, +) -> Dict[str, Any]: + """Build ECS 1.6.0 compliant extra dict for audit logging. + + Produces: + - event.action + - event.outcome + - user.name (actor; defaults from request headers if request provided) + - destination.user.name (target user / subject) + - + request context fields (source.ip, client.ip, transaction.id, tls.client.*) + - + extra_fields + + Actor defaulting policy: + - If actor is explicitly provided -> use it. + - Else if request is provided -> derive from certificate / fingerprint headers. + - Else -> omit user.name. + """ + normalized_outcome = outcome.strip().lower() + if normalized_outcome not in ("success", "failure", "unknown"): + normalized_outcome = "unknown" + + extra: Dict[str, Any] = { + "event.action": action, + "event.outcome": normalized_outcome, + } + + resolved_actor = actor + if not resolved_actor and request is not None: + resolved_actor = _resolve_actor_from_request( + request, + trust_proxy_headers=trust_proxy_headers, + ) + + if resolved_actor: + extra["user.name"] = resolved_actor + + if target: + extra["destination.user.name"] = target + + if request: + extra.update( + get_audit_request_context( + request, + trust_proxy_headers=trust_proxy_headers, + ) + ) + + extra.update(extra_fields) + return extra diff --git a/src/rasenmaeher_api/web/application.py b/src/rasenmaeher_api/web/application.py index 5002809..5ecc71d 100644 --- a/src/rasenmaeher_api/web/application.py +++ b/src/rasenmaeher_api/web/application.py @@ -6,7 +6,7 @@ from contextlib import asynccontextmanager from fastapi import FastAPI -from libpvarki.logging import init_logging +from libpvarki.logging import init_logging, add_trace_and_audit import aiohttp from libadvian.tasks import TaskMaster @@ -55,6 +55,7 @@ def get_app_no_init() -> FastAPI: def get_app() -> FastAPI: """Returns the FastAPI application.""" + add_trace_and_audit() # Register AUDIT and TRACE log levels init_logging(RMSettings.singleton().log_level_int) app = get_app_no_init() LOGGER.info("API init done, setting log verbosity to '{}'.".format(RMSettings.singleton().log_level)) diff --git a/tests/test_rasenmaeher_api.py b/tests/test_rasenmaeher_api.py index 20465f7..9d3ab9b 100644 --- a/tests/test_rasenmaeher_api.py +++ b/tests/test_rasenmaeher_api.py @@ -16,7 +16,7 @@ def test_version() -> None: """Make sure version matches expected""" - assert __version__ == "1.12.2" + assert __version__ == "1.13.0" @pytest.mark.asyncio(loop_scope="session")