diff --git a/.gitignore b/.gitignore index 78cd1ee..575f4b3 100644 --- a/.gitignore +++ b/.gitignore @@ -16,6 +16,7 @@ nexus-claude-api.local.json .omo .codegraph .agents +.claude # logs logs diff --git a/docs/PRD.md b/docs/PRD.md index c9166e6..2eaec0b 100644 --- a/docs/PRD.md +++ b/docs/PRD.md @@ -60,6 +60,7 @@ The proxy defaults to Opus because this deployment is intended for users whose N - As a Claude Code user, I can use tool calls and tool results. - As a multimodal user, I can send images through Claude-compatible image content blocks. - As a developer debugging setup, I can enable verbose logs without exposing tokens. +- As a developer debugging issues, I can trace any error in the log file using a correlation_id that appears in both the client response and the log entry. ## Acceptance Criteria @@ -70,6 +71,7 @@ The proxy defaults to Opus because this deployment is intended for users whose N - `--dev` startup reads current-directory `nexus-claude-api.local.json` instead of user config. - Default logs are written to `~/.config/nexus-claude-api/logs/nexus-claude-api-YYYY-MM-DD.log`. - `--dev` logs are written to current-directory `logs/nexus-claude-api-YYYY-MM-DD.log`. +- All API errors (4xx, 5xx, network failures, client disconnects) are logged with correlation_id and duration. - Missing Nexus credentials fail fast with a clear error. - `GET /health` returns healthy status. - `GET /v1/models` returns the supported Claude models. diff --git a/docs/REQUIREMENTS_DESIGN.md b/docs/REQUIREMENTS_DESIGN.md index c60987b..2b6d048 100644 --- a/docs/REQUIREMENTS_DESIGN.md +++ b/docs/REQUIREMENTS_DESIGN.md @@ -29,7 +29,9 @@ nexus-claude-api/ __main__.py cli.py config.py + diagnostics.py errors.py + logging_config.py models.py nexus_client.py server.py @@ -212,6 +214,28 @@ Status mapping: - Nexus throttling: `429` - Nexus network/timeout: `502` or `504` - unexpected server error: `500` +- client disconnected: `499` (logged only, not sent) + +## Observability + +All errors are logged to the daily log file with a `correlation_id` for tracing. + +Request lifecycle middleware logs: + +- `request_complete` with method, path, status, and duration_ms for every `/v1/messages` request. +- `client_disconnected` when the client drops connection mid-request or mid-stream. +- `unhandled_exception` with traceback for unexpected errors (returns 500). + +Error logging at point of origin: + +- `nexus_client_error` (WARNING): Nexus API returned an error (4xx/5xx) with error code, message, HTTP status, and request ID. +- `nexus_botocore_error` (WARNING): Network/transport failure (timeout, DNS, connection reset). +- `stream_nexus_error` (WARNING): Error during streaming response iteration. +- `stream_client_disconnected` (INFO): Client closed connection during streaming. +- `validation_error` (WARNING): Malformed request that failed pydantic validation. +- `nexus_error` (WARNING): NexusClaudeError in non-streaming response path. + +Diagnostics summarize each request (model, stream flag, message count, content block types, tool info) without logging secrets, prompt text, or base64 data. ## Testing @@ -234,6 +258,11 @@ Route tests: - `POST /v1/messages` non-stream - `POST /v1/messages` stream - `POST /v1/messages/count_tokens` +- Validation errors are logged with correlation_id. +- Nexus errors (non-stream) are logged with status and type. +- Nexus errors (stream) are logged as `stream_nexus_error`. +- Request completion is logged with duration_ms. +- Unexpected exceptions return 500 and are logged. CLI tests: diff --git a/pyproject.toml b/pyproject.toml index cb5ad8b..3689066 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -1,6 +1,6 @@ [project] name = "nexus-claude-api" -version = "0.1.2" +version = "0.1.3" description = "Local Anthropic-compatible Claude Code proxy for AI Nexus Bedrock Converse." readme = "README.md" requires-python = ">=3.11" diff --git a/src/nexus_claude_api/__init__.py b/src/nexus_claude_api/__init__.py index 8096691..fed7a4a 100644 --- a/src/nexus_claude_api/__init__.py +++ b/src/nexus_claude_api/__init__.py @@ -1,3 +1,3 @@ """Local Anthropic-compatible proxy for AI Nexus Claude models.""" -__version__ = "0.1.2" +__version__ = "0.1.3" diff --git a/src/nexus_claude_api/nexus_client.py b/src/nexus_claude_api/nexus_client.py index 5e1cde2..13c4c15 100644 --- a/src/nexus_claude_api/nexus_client.py +++ b/src/nexus_claude_api/nexus_client.py @@ -40,6 +40,11 @@ class NexusClient: correlation_id=correlation_id, ) from exc except BotoCoreError as exc: + logger.warning( + "nexus_botocore_error operation=converse correlation_id=%s error=%s", + correlation_id, + str(exc), + ) raise NexusClaudeError( "Failed to call Nexus Converse API", status_code=502, @@ -62,6 +67,11 @@ class NexusClient: correlation_id=correlation_id, ) from exc except BotoCoreError as exc: + logger.warning( + "nexus_botocore_error operation=converse_stream correlation_id=%s error=%s", + correlation_id, + str(exc), + ) raise NexusClaudeError( "Failed to call Nexus Converse Stream API", status_code=502, diff --git a/src/nexus_claude_api/routes/messages.py b/src/nexus_claude_api/routes/messages.py index 6e9ecc7..50c4cf9 100644 --- a/src/nexus_claude_api/routes/messages.py +++ b/src/nexus_claude_api/routes/messages.py @@ -71,6 +71,13 @@ def anthropic_sse_stream( for event in bedrock_stream_to_anthropic_events(stream, model=model): yield sse_frame(event) except NexusClaudeError as exc: + logger.warning( + "stream_nexus_error correlation_id=%s status=%d type=%s message=%s", + correlation_id, + exc.status_code, + exc.error_type, + exc.message, + ) yield sse_frame( { "type": "error", @@ -81,6 +88,9 @@ def anthropic_sse_stream( }, } ) + except GeneratorExit: + logger.info("stream_client_disconnected correlation_id=%s", correlation_id) + return except Exception: logger.exception( "anthropic_messages_stream_error correlation_id=%s", @@ -144,12 +154,24 @@ async def create_message( ) return JSONResponse(content=anthropic_response.model_dump(exclude_none=True)) except ValidationError as exc: + logger.warning( + "validation_error correlation_id=%s error=%s", + correlation_id, + str(exc)[:500], + ) return anthropic_error_response( str(exc), status_code=400, correlation_id=correlation_id, ) except NexusClaudeError as exc: + logger.warning( + "nexus_error correlation_id=%s status=%d type=%s message=%s", + correlation_id, + exc.status_code, + exc.error_type, + exc.message, + ) return anthropic_error_response( exc.message, status_code=exc.status_code, diff --git a/src/nexus_claude_api/server.py b/src/nexus_claude_api/server.py index 819e4e9..471ba92 100644 --- a/src/nexus_claude_api/server.py +++ b/src/nexus_claude_api/server.py @@ -1,9 +1,14 @@ from __future__ import annotations +import logging +import time + from fastapi import FastAPI from fastapi.middleware.cors import CORSMiddleware from fastapi.requests import Request -from fastapi.responses import JSONResponse +from fastapi.responses import JSONResponse, Response +from starlette.middleware.base import BaseHTTPMiddleware +from starlette.requests import ClientDisconnect from nexus_claude_api import __version__ from nexus_claude_api.config import Settings @@ -13,6 +18,54 @@ from nexus_claude_api.routes.health import router as health_router from nexus_claude_api.routes.messages import router as messages_router from nexus_claude_api.routes.models import router as models_router +logger = logging.getLogger(__name__) + + +class RequestLifecycleMiddleware(BaseHTTPMiddleware): + async def dispatch(self, request: Request, call_next): + if not request.url.path.startswith("/v1/messages"): + return await call_next(request) + + start = time.perf_counter() + try: + response = await call_next(request) + duration_ms = (time.perf_counter() - start) * 1000 + logger.info( + "request_complete method=%s path=%s status=%d duration_ms=%.1f", + request.method, + request.url.path, + response.status_code, + duration_ms, + ) + return response + except ClientDisconnect: + duration_ms = (time.perf_counter() - start) * 1000 + logger.info( + "client_disconnected method=%s path=%s duration_ms=%.1f", + request.method, + request.url.path, + duration_ms, + ) + return Response(status_code=499) + except Exception: + duration_ms = (time.perf_counter() - start) * 1000 + logger.exception( + "unhandled_exception method=%s path=%s duration_ms=%.1f", + request.method, + request.url.path, + duration_ms, + ) + return JSONResponse( + status_code=500, + content={ + "type": "error", + "error": { + "type": "api_error", + "message": "Internal server error", + }, + }, + ) + def create_app( settings: Settings | None = None, @@ -23,6 +76,7 @@ def create_app( app.state.settings = resolved_settings app.state.nexus_client = nexus_client or NexusClient(resolved_settings) + app.add_middleware(RequestLifecycleMiddleware) app.add_middleware( CORSMiddleware, allow_origins=["*"], @@ -43,4 +97,18 @@ def create_app( error_type=exc.error_type, ) + @app.exception_handler(ClientDisconnect) + async def handle_client_disconnect(_: Request, exc: ClientDisconnect) -> Response: + logger.debug("client_disconnect_handler_invoked") + return Response(status_code=499) + + @app.exception_handler(Exception) + async def handle_unexpected_error(_: Request, exc: Exception) -> JSONResponse: + logger.exception("unhandled_exception") + return anthropic_error_response( + "Internal server error", + status_code=500, + error_type="api_error", + ) + return app diff --git a/tests/test_routes.py b/tests/test_routes.py index 0312921..de5a010 100644 --- a/tests/test_routes.py +++ b/tests/test_routes.py @@ -230,3 +230,87 @@ def test_count_tokens() -> None: assert response.status_code == 200 assert response.json()["input_tokens"] > 0 + + +def test_validation_error_is_logged(caplog) -> None: + caplog.set_level(logging.WARNING, logger="nexus_claude_api.routes.messages") + + response = client().post( + "/v1/messages", + json={"model": "claude-opus-4.6", "max_tokens": -1}, + ) + + assert response.status_code == 400 + assert any("validation_error" in r.message for r in caplog.records) + + +def test_nexus_error_non_stream_is_logged(caplog) -> None: + caplog.set_level(logging.WARNING, logger="nexus_claude_api.routes.messages") + + response = client(AccessDeniedNexusClient()).post( + "/v1/messages", + json={ + "model": "claude-opus-4.6", + "messages": [{"role": "user", "content": "Hello"}], + "max_tokens": 32, + }, + ) + + assert response.status_code == 403 + assert any("nexus_error" in r.message for r in caplog.records) + + +def test_stream_nexus_error_is_logged(caplog) -> None: + caplog.set_level(logging.WARNING, logger="nexus_claude_api.routes.messages") + + with client(StreamErrorNexusClient()).stream( + "POST", + "/v1/messages", + json={ + "model": "claude-opus-4.6", + "messages": [{"role": "user", "content": "Hello"}], + "max_tokens": 32, + "stream": True, + }, + ) as response: + response.read() + + assert any("stream_nexus_error" in r.message for r in caplog.records) + + +def test_request_complete_is_logged(caplog) -> None: + caplog.set_level(logging.INFO, logger="nexus_claude_api.server") + + client().post( + "/v1/messages", + json={ + "model": "claude-opus-4.6", + "messages": [{"role": "user", "content": "Hello"}], + "max_tokens": 32, + }, + ) + + assert any("request_complete" in r.message and "duration_ms" in r.message for r in caplog.records) + + +class ExplodingNexusClient: + def converse(self, request: dict, *, correlation_id: str | None = None) -> dict: + raise RuntimeError("unexpected kaboom") + + +def test_unexpected_exception_returns_500_and_is_logged(caplog) -> None: + caplog.set_level(logging.ERROR, logger="nexus_claude_api.server") + + response = client(ExplodingNexusClient()).post( + "/v1/messages", + json={ + "model": "claude-opus-4.6", + "messages": [{"role": "user", "content": "Hello"}], + "max_tokens": 32, + }, + ) + + assert response.status_code == 500 + body = response.json() + assert body["error"]["type"] == "api_error" + assert any("unhandled_exception" in r.message for r in caplog.records) diff --git a/uv.lock b/uv.lock index 9ebe087..dcfa9dc 100644 --- a/uv.lock +++ b/uv.lock @@ -173,7 +173,7 @@ wheels = [ [[package]] name = "nexus-claude-api" -version = "0.1.2" +version = "0.1.3" source = { editable = "." } dependencies = [ { name = "boto3" },