diff --git a/config.example.toml b/config.example.toml index b1c7957..66aa6d8 100644 --- a/config.example.toml +++ b/config.example.toml @@ -32,3 +32,9 @@ modules = [ [rate_limit] # Maximum requests per minute per client IP (default: 60) # rpm = 60 + +[logging] +# Log level: DEBUG, INFO, WARNING, ERROR, CRITICAL (default: INFO) +# level = "INFO" +# Log format: "plain" (human-readable) or "json" (structured, one record per line) +# format = "plain" diff --git a/src/deckhand/config/settings.py b/src/deckhand/config/settings.py index f928bf3..ebfff5b 100644 --- a/src/deckhand/config/settings.py +++ b/src/deckhand/config/settings.py @@ -24,6 +24,8 @@ def __init__(self) -> None: self.config_file_path: str | None = None self.state_file_path: str | None = None self.rate_limit_rpm: int = 60 + self.log_level: str = "INFO" + self.log_format: str = "plain" # "plain" or "json" # Auth: list of {key, scope} dicts self._raw_api_keys: list[dict[str, str]] = [] @@ -90,6 +92,12 @@ def _load_from_config_file(self, file_path: str) -> None: rl_config = config["rate_limit"] self.rate_limit_rpm = rl_config.get("rpm", self.rate_limit_rpm) + # Logging + if "logging" in config: + log_config = config["logging"] + self.log_level = log_config.get("level", self.log_level) + self.log_format = log_config.get("format", self.log_format) + def _load_auth(self, auth_config: dict[str, Any]) -> None: """Parse the [auth] section.""" if "api_keys" in auth_config: @@ -130,3 +138,9 @@ def _load_from_env(self) -> None: self.rate_limit_rpm = int(rpm_str) except ValueError: pass + + if log_level := os.getenv("DECKHAND_LOG_LEVEL"): + self.log_level = log_level + + if log_format := os.getenv("DECKHAND_LOG_FORMAT"): + self.log_format = log_format diff --git a/src/deckhand/logging_config.py b/src/deckhand/logging_config.py new file mode 100644 index 0000000..1882e2d --- /dev/null +++ b/src/deckhand/logging_config.py @@ -0,0 +1,91 @@ +"""Logging configuration: configurable level + plain/JSON output formats.""" + +from __future__ import annotations + +import json +import logging +import sys +from datetime import datetime, timezone +from typing import Any + +# Standard LogRecord attributes that should not be included in the "extra" dict +# of a JSON record. Anything not in this set was added via logger.xxx(..., extra=...). +_RESERVED_ATTRS = { + "name", + "msg", + "args", + "levelname", + "levelno", + "pathname", + "filename", + "module", + "exc_info", + "exc_text", + "stack_info", + "lineno", + "funcName", + "created", + "msecs", + "relativeCreated", + "thread", + "threadName", + "processName", + "process", + "message", + "asctime", + "taskName", +} + + +class JsonFormatter(logging.Formatter): + """Format log records as a single line of JSON. + + Includes any keyword arguments passed to the logger via ``extra=`` so + callers can attach contextual fields like ``agent_id`` or ``action_name``. + """ + + def format(self, record: logging.LogRecord) -> str: + payload: dict[str, Any] = { + "timestamp": datetime.fromtimestamp( + record.created, tz=timezone.utc + ).isoformat(), + "level": record.levelname, + "logger": record.name, + "message": record.getMessage(), + } + + # Attach contextual fields supplied via `extra=` + for key, value in record.__dict__.items(): + if key in _RESERVED_ATTRS or key.startswith("_"): + continue + payload[key] = value + + if record.exc_info: + payload["exc_info"] = self.formatException(record.exc_info) + + return json.dumps(payload, default=str) + + +def configure_logging(level: str = "INFO", fmt: str = "plain") -> None: + """Configure the root logger with the requested level and format. + + Safe to call multiple times — replaces existing handlers on the root logger. + """ + root = logging.getLogger() + root.setLevel(level.upper()) + + # Remove pre-existing handlers so re-configuration is idempotent + for handler in list(root.handlers): + root.removeHandler(handler) + + handler = logging.StreamHandler(sys.stderr) + if fmt == "json": + handler.setFormatter(JsonFormatter()) + else: + handler.setFormatter( + logging.Formatter( + "%(asctime)s %(levelname)-8s %(name)s: %(message)s", + datefmt="%Y-%m-%dT%H:%M:%S", + ) + ) + root.addHandler(handler) diff --git a/src/deckhand/main.py b/src/deckhand/main.py index 49ab7d4..e23939c 100644 --- a/src/deckhand/main.py +++ b/src/deckhand/main.py @@ -21,6 +21,7 @@ from deckhand.agents.mock import MockAgent from deckhand.config.settings import Settings +from deckhand.logging_config import configure_logging from deckhand.orchestrator.actions import ActionRegistry from deckhand.orchestrator.events import build_error_event, build_event from deckhand.orchestrator.manager import Orchestrator @@ -57,9 +58,10 @@ async def lifespan(app: FastAPI): settings, \ rate_limiter - # Startup - logger.info("Starting Deckhand service...") + # Startup — load settings first so we can configure logging from them settings = Settings() + configure_logging(level=settings.log_level, fmt=settings.log_format) + logger.info("Starting Deckhand service...") # Log configuration logger.info("Configuration:") @@ -142,6 +144,10 @@ async def dispatch(self, request: Request, call_next): if rate_limiter is not None: client_ip = request.client.host if request.client else "unknown" if not rate_limiter.check(client_ip): + logger.warning( + "Rate limit exceeded", + extra={"client_ip": client_ip, "path": request.url.path}, + ) return JSONResponse( status_code=429, content={"detail": "Rate limit exceeded"}, @@ -170,15 +176,24 @@ def _require_scope(request: Request, scope: str) -> ApiKeyEntry: if settings is None: raise HTTPException(status_code=503, detail="Service not initialized") + client_ip = request.client.host if request.client else "unknown" + log_ctx = {"client_ip": client_ip, "path": request.url.path, "scope": scope} + token = _extract_token(request) if not token: + logger.warning("Auth failed: missing API key", extra=log_ctx) raise HTTPException(status_code=401, detail="Missing API key") entry = resolve_key(token, settings.api_keys) if entry is None: + logger.warning("Auth failed: invalid API key", extra=log_ctx) raise HTTPException(status_code=401, detail="Invalid API key") if not has_scope(entry, scope): + logger.warning( + "Auth failed: insufficient scope", + extra={**log_ctx, "key_scope": entry.scope}, + ) raise HTTPException( status_code=403, detail=f"Insufficient scope: requires '{scope}'" ) @@ -574,12 +589,15 @@ async def events(websocket: WebSocket) -> None: # Accept the connection, then authenticate via first message await websocket.accept() + client_ip = websocket.client.host if websocket.client else "unknown" + ws_ctx = {"client_ip": client_ip, "path": "/events"} try: raw = await asyncio.wait_for(websocket.receive_text(), timeout=_WS_AUTH_TIMEOUT) auth_msg = json.loads(raw) if auth_msg.get("type") != "auth" or "token" not in auth_msg: + logger.warning("WS auth failed: malformed auth message", extra=ws_ctx) await websocket.send_json( { "type": "auth_error", @@ -591,6 +609,7 @@ async def events(websocket: WebSocket) -> None: entry = resolve_key(auth_msg["token"], settings.api_keys) if entry is None: + logger.warning("WS auth failed: invalid API key", extra=ws_ctx) await websocket.send_json( {"type": "auth_error", "detail": "Invalid API key"} ) @@ -600,9 +619,11 @@ async def events(websocket: WebSocket) -> None: await websocket.send_json({"type": "auth_ok", "scope": entry.scope}) except asyncio.TimeoutError: + logger.warning("WS auth failed: handshake timed out", extra=ws_ctx) await websocket.close(code=4001, reason="Auth handshake timed out") return except (json.JSONDecodeError, KeyError): + logger.warning("WS auth failed: malformed auth message", extra=ws_ctx) await websocket.close(code=4001, reason="Malformed auth message") return diff --git a/tests/test_logging_config.py b/tests/test_logging_config.py new file mode 100644 index 0000000..de1507d --- /dev/null +++ b/tests/test_logging_config.py @@ -0,0 +1,55 @@ +"""Tests for structured logging configuration.""" + +from __future__ import annotations + +import json +import logging + +from deckhand.logging_config import JsonFormatter, configure_logging + + +def _make_record(**kwargs) -> logging.LogRecord: + record = logging.LogRecord( + name="deckhand.test", + level=logging.INFO, + pathname=__file__, + lineno=10, + msg="hello %s", + args=("world",), + exc_info=None, + ) + for key, value in kwargs.items(): + setattr(record, key, value) + return record + + +def test_json_formatter_emits_required_fields() -> None: + record = _make_record() + out = json.loads(JsonFormatter().format(record)) + assert out["level"] == "INFO" + assert out["logger"] == "deckhand.test" + assert out["message"] == "hello world" + assert "timestamp" in out + + +def test_json_formatter_includes_extra_context() -> None: + record = _make_record(agent_id="mock-1", action_name="run", client_ip="127.0.0.1") + out = json.loads(JsonFormatter().format(record)) + assert out["agent_id"] == "mock-1" + assert out["action_name"] == "run" + assert out["client_ip"] == "127.0.0.1" + + +def test_configure_logging_is_idempotent_and_sets_level() -> None: + configure_logging(level="DEBUG", fmt="json") + root = logging.getLogger() + assert root.level == logging.DEBUG + handlers_before = len(root.handlers) + assert handlers_before == 1 + assert isinstance(root.handlers[0].formatter, JsonFormatter) + + # Re-configuring replaces handlers, doesn't accumulate them + configure_logging(level="WARNING", fmt="plain") + assert len(root.handlers) == 1 + assert root.level == logging.WARNING + assert not isinstance(root.handlers[0].formatter, JsonFormatter)