feat: add structured logging helpers and instrument get_issue (#14)
docker / test (pull_request) Successful in 29s
test / test (push) Successful in 38s
lint / lint (push) Successful in 39s
docker / lint (pull_request) Successful in 39s
docker / docker-test (pull_request) Successful in 12s
docker / docker-publish (pull_request) Has been skipped
lint / lint (pull_request) Successful in 28s
test / test (pull_request) Successful in 22s
docker / test (pull_request) Successful in 29s
test / test (push) Successful in 38s
lint / lint (push) Successful in 39s
docker / lint (pull_request) Successful in 39s
docker / docker-test (pull_request) Successful in 12s
docker / docker-publish (pull_request) Has been skipped
lint / lint (pull_request) Successful in 28s
test / test (pull_request) Successful in 22s
Adds reusable, secret-safe logging helpers to `logging_utils`: - `log_event(logger, level, event, **context)` emits a named event with a sanitized `context` mapping (sensitive keys masked as `***`). - `log_nullable_field(...)` records whether a parsed field is None plus its runtime type, without dumping its contents. - `sanitize_context(...)` is the shared masking primitive. The JSON formatter now serializes a record's `context` into the payload. `get_issue_tool` is instrumented at DEBUG (`get_issue.start`, `get_issue.payload_shape`, `get_issue.field_check` for labels/assignees/user) so the nullable-field parsing that caused #13 is diagnosable going forward. Adds tests for the helpers, the formatter, and the get_issue instrumentation, and documents the pattern in docs/observability.md.
This commit is contained in:
@@ -6,6 +6,26 @@
|
||||
- Request correlation via `X-Request-ID`.
|
||||
- Security events and policy denials are audit logged.
|
||||
|
||||
### Structured event helpers
|
||||
|
||||
`logging_utils` exposes reusable helpers so endpoints emit consistent,
|
||||
secret-safe structured events instead of ad-hoc inline logging:
|
||||
|
||||
- `log_event(logger, level, event, **context)` — emit a named event with a
|
||||
`context` mapping; keys in `SENSITIVE_CONTEXT_KEYS` (e.g. `token`,
|
||||
`authorization`, `password`) are masked as `***`.
|
||||
- `log_nullable_field(logger, event, field, value)` — record whether a parsed
|
||||
response field is `None` and its runtime type, without dumping its contents.
|
||||
- `sanitize_context(context)` — the masking primitive used by the above.
|
||||
|
||||
The `context` mapping is serialized into the JSON log payload under a `context`
|
||||
key. These run at `DEBUG`, so they are silent unless `LOG_LEVEL=DEBUG`.
|
||||
|
||||
`get_issue` is instrumented with these helpers (`get_issue.start`,
|
||||
`get_issue.payload_shape`, `get_issue.field_check`) to make nullable-field
|
||||
parsing failures diagnosable. The same pattern can be reused for other
|
||||
parsing-heavy endpoints (`get_pull_request`, `list_issues`, `get_commit_diff`).
|
||||
|
||||
## Metrics
|
||||
|
||||
Prometheus-compatible endpoint: `GET /metrics`.
|
||||
|
||||
@@ -5,16 +5,22 @@ from __future__ import annotations
|
||||
import json
|
||||
import logging
|
||||
from datetime import datetime, timezone
|
||||
from typing import Any
|
||||
|
||||
from aegis_gitea_mcp.request_context import get_request_id
|
||||
|
||||
# Context keys whose values must never be written to logs verbatim.
|
||||
SENSITIVE_CONTEXT_KEYS = frozenset(
|
||||
{"token", "authorization", "cookie", "password", "secret", "api_key"}
|
||||
)
|
||||
|
||||
|
||||
class JsonLogFormatter(logging.Formatter):
|
||||
"""Format log records as JSON documents."""
|
||||
|
||||
def format(self, record: logging.LogRecord) -> str:
|
||||
"""Serialize a log record to JSON."""
|
||||
payload = {
|
||||
payload: dict[str, Any] = {
|
||||
"timestamp": datetime.now(timezone.utc).isoformat(),
|
||||
"level": record.levelname,
|
||||
"logger": record.name,
|
||||
@@ -22,6 +28,10 @@ class JsonLogFormatter(logging.Formatter):
|
||||
"request_id": get_request_id(),
|
||||
}
|
||||
|
||||
context = getattr(record, "context", None)
|
||||
if isinstance(context, dict) and context:
|
||||
payload["context"] = context
|
||||
|
||||
if record.exc_info:
|
||||
# Security decision: include only exception type to avoid stack leakage.
|
||||
exception_type = record.exc_info[0]
|
||||
@@ -46,3 +56,55 @@ def configure_logging(level: str) -> None:
|
||||
stream_handler = logging.StreamHandler()
|
||||
stream_handler.setFormatter(JsonLogFormatter())
|
||||
logger.addHandler(stream_handler)
|
||||
|
||||
|
||||
def sanitize_context(context: dict[str, Any]) -> dict[str, Any]:
|
||||
"""Redact sensitive values from a logging context mapping.
|
||||
|
||||
Keys whose lower-cased name is in ``SENSITIVE_CONTEXT_KEYS`` have their
|
||||
value replaced with ``"***"`` so credentials never reach the log sink.
|
||||
|
||||
Args:
|
||||
context: Arbitrary key/value pairs intended for structured logging.
|
||||
|
||||
Returns:
|
||||
A new mapping with sensitive values masked.
|
||||
"""
|
||||
return {
|
||||
key: ("***" if key.lower() in SENSITIVE_CONTEXT_KEYS else value)
|
||||
for key, value in context.items()
|
||||
}
|
||||
|
||||
|
||||
def log_event(logger: logging.Logger, level: int, event: str, **context: Any) -> None:
|
||||
"""Emit a structured log event with a sanitized context payload.
|
||||
|
||||
Args:
|
||||
logger: Logger to emit on.
|
||||
level: Standard ``logging`` level (e.g. ``logging.DEBUG``).
|
||||
event: Stable, machine-friendly event name (e.g. ``get_issue.start``).
|
||||
**context: Extra structured fields; sensitive keys are masked.
|
||||
"""
|
||||
logger.log(level, event, extra={"context": sanitize_context(context)})
|
||||
|
||||
|
||||
def log_nullable_field(logger: logging.Logger, event: str, field_name: str, value: Any) -> None:
|
||||
"""Log whether a parsed response field is ``None`` and its runtime type.
|
||||
|
||||
Makes null/nullable field failures (such as a ``null`` ``labels`` array)
|
||||
obvious in logs without dumping the field's full contents.
|
||||
|
||||
Args:
|
||||
logger: Logger to emit on.
|
||||
event: Stable event name for the field check.
|
||||
field_name: Name of the field being inspected.
|
||||
value: The parsed value to characterize.
|
||||
"""
|
||||
log_event(
|
||||
logger,
|
||||
logging.DEBUG,
|
||||
event,
|
||||
field=field_name,
|
||||
is_none=value is None,
|
||||
value_type=(type(value).__name__ if value is not None else None),
|
||||
)
|
||||
|
||||
@@ -2,6 +2,7 @@
|
||||
|
||||
from __future__ import annotations
|
||||
|
||||
import logging
|
||||
from typing import Any
|
||||
|
||||
from aegis_gitea_mcp.gitea_client import (
|
||||
@@ -10,6 +11,7 @@ from aegis_gitea_mcp.gitea_client import (
|
||||
GiteaClient,
|
||||
GiteaError,
|
||||
)
|
||||
from aegis_gitea_mcp.logging_utils import log_event, log_nullable_field
|
||||
from aegis_gitea_mcp.response_limits import limit_items, limit_text
|
||||
from aegis_gitea_mcp.tools.arguments import (
|
||||
CommitDiffArgs,
|
||||
@@ -38,6 +40,8 @@ from aegis_gitea_mcp.tools.arguments import (
|
||||
SearchCodeArgs,
|
||||
)
|
||||
|
||||
logger = logging.getLogger(__name__)
|
||||
|
||||
|
||||
async def search_code_tool(gitea: GiteaClient, arguments: dict[str, Any]) -> dict[str, Any]:
|
||||
"""Search repository code and return bounded result snippets."""
|
||||
@@ -265,8 +269,26 @@ async def list_issues_tool(gitea: GiteaClient, arguments: dict[str, Any]) -> dic
|
||||
async def get_issue_tool(gitea: GiteaClient, arguments: dict[str, Any]) -> dict[str, Any]:
|
||||
"""Get issue details."""
|
||||
parsed = IssueArgs.model_validate(arguments)
|
||||
log_event(
|
||||
logger,
|
||||
logging.DEBUG,
|
||||
"get_issue.start",
|
||||
owner=parsed.owner,
|
||||
repo=parsed.repo,
|
||||
issue_number=parsed.issue_number,
|
||||
)
|
||||
try:
|
||||
issue = await gitea.get_issue(parsed.owner, parsed.repo, parsed.issue_number)
|
||||
log_event(
|
||||
logger,
|
||||
logging.DEBUG,
|
||||
"get_issue.payload_shape",
|
||||
top_level_keys=sorted(issue.keys()) if issue else None,
|
||||
)
|
||||
# Surface nullable collections that previously broke parsing (see #13).
|
||||
log_nullable_field(logger, "get_issue.field_check", "labels", issue.get("labels"))
|
||||
log_nullable_field(logger, "get_issue.field_check", "assignees", issue.get("assignees"))
|
||||
log_nullable_field(logger, "get_issue.field_check", "user", issue.get("user"))
|
||||
return {
|
||||
"number": issue.get("number", 0),
|
||||
"title": limit_text(str(issue.get("title", ""))),
|
||||
|
||||
@@ -0,0 +1,120 @@
|
||||
"""Tests for structured logging helpers and get_issue instrumentation (#14)."""
|
||||
|
||||
from __future__ import annotations
|
||||
|
||||
import json
|
||||
import logging
|
||||
|
||||
import pytest
|
||||
|
||||
from aegis_gitea_mcp.config import reset_settings
|
||||
from aegis_gitea_mcp.logging_utils import (
|
||||
JsonLogFormatter,
|
||||
log_event,
|
||||
log_nullable_field,
|
||||
sanitize_context,
|
||||
)
|
||||
from aegis_gitea_mcp.tools.read_tools import get_issue_tool
|
||||
|
||||
READ_TOOLS_LOGGER = "aegis_gitea_mcp.tools.read_tools"
|
||||
|
||||
|
||||
@pytest.fixture(autouse=True)
|
||||
def tool_env(monkeypatch: pytest.MonkeyPatch) -> None:
|
||||
"""Provide minimal settings environment for response limit helpers."""
|
||||
reset_settings()
|
||||
monkeypatch.setenv("GITEA_URL", "https://gitea.example.com")
|
||||
monkeypatch.setenv("GITEA_TOKEN", "test-token")
|
||||
monkeypatch.setenv("MCP_API_KEYS", "a" * 64)
|
||||
monkeypatch.setenv("ENVIRONMENT", "test")
|
||||
|
||||
|
||||
def test_sanitize_context_masks_sensitive_keys() -> None:
|
||||
"""Sensitive keys are masked case-insensitively; others pass through."""
|
||||
cleaned = sanitize_context(
|
||||
{"owner": "acme", "Token": "abc", "password": "x", "issue_number": 7}
|
||||
)
|
||||
|
||||
assert cleaned["owner"] == "acme"
|
||||
assert cleaned["issue_number"] == 7
|
||||
assert cleaned["Token"] == "***"
|
||||
assert cleaned["password"] == "***"
|
||||
|
||||
|
||||
def test_json_formatter_includes_context() -> None:
|
||||
"""The formatter serializes a record's context mapping into the payload."""
|
||||
record = logging.LogRecord(
|
||||
"test", logging.DEBUG, __file__, 1, "get_issue.field_check", None, None
|
||||
)
|
||||
record.context = {"field": "labels", "is_none": True}
|
||||
|
||||
payload = json.loads(JsonLogFormatter().format(record))
|
||||
|
||||
assert payload["message"] == "get_issue.field_check"
|
||||
assert payload["context"] == {"field": "labels", "is_none": True}
|
||||
|
||||
|
||||
def test_log_event_emits_sanitized_context(caplog: pytest.LogCaptureFixture) -> None:
|
||||
"""log_event records the event name and masks sensitive context values."""
|
||||
logger = logging.getLogger("test.log_event")
|
||||
with caplog.at_level(logging.DEBUG, logger="test.log_event"):
|
||||
log_event(logger, logging.DEBUG, "evt", owner="acme", token="secret")
|
||||
|
||||
record = caplog.records[-1]
|
||||
assert record.getMessage() == "evt"
|
||||
assert record.context == {"owner": "acme", "token": "***"}
|
||||
|
||||
|
||||
def test_log_nullable_field_characterizes_value(caplog: pytest.LogCaptureFixture) -> None:
|
||||
"""log_nullable_field reports None-ness and runtime type without dumping data."""
|
||||
logger = logging.getLogger("test.nullable")
|
||||
with caplog.at_level(logging.DEBUG, logger="test.nullable"):
|
||||
log_nullable_field(logger, "evt", "labels", None)
|
||||
log_nullable_field(logger, "evt", "labels", [1, 2])
|
||||
|
||||
assert caplog.records[0].context == {
|
||||
"field": "labels",
|
||||
"is_none": True,
|
||||
"value_type": None,
|
||||
}
|
||||
assert caplog.records[1].context == {
|
||||
"field": "labels",
|
||||
"is_none": False,
|
||||
"value_type": "list",
|
||||
}
|
||||
|
||||
|
||||
class _NullIssueGitea:
|
||||
"""Minimal stub returning an issue with null collection fields."""
|
||||
|
||||
async def get_issue(self, owner: str, repo: str, index: int) -> dict[str, object]:
|
||||
return {
|
||||
"number": index,
|
||||
"title": "Issue",
|
||||
"body": "Body",
|
||||
"state": "open",
|
||||
"labels": None,
|
||||
"assignees": None,
|
||||
"user": None,
|
||||
}
|
||||
|
||||
|
||||
@pytest.mark.asyncio
|
||||
async def test_get_issue_tool_emits_debug_events(caplog: pytest.LogCaptureFixture) -> None:
|
||||
"""get_issue_tool emits start/shape/field-check debug events and still parses."""
|
||||
with caplog.at_level(logging.DEBUG, logger=READ_TOOLS_LOGGER):
|
||||
result = await get_issue_tool(
|
||||
_NullIssueGitea(), {"owner": "acme", "repo": "app", "issue_number": 7}
|
||||
)
|
||||
|
||||
events = [r.getMessage() for r in caplog.records]
|
||||
assert "get_issue.start" in events
|
||||
assert "get_issue.payload_shape" in events
|
||||
|
||||
field_checks = [r.context for r in caplog.records if r.getMessage() == "get_issue.field_check"]
|
||||
assert {"field": "labels", "is_none": True, "value_type": None} in field_checks
|
||||
assert {"field": "user", "is_none": True, "value_type": None} in field_checks
|
||||
|
||||
# Logging must not change behaviour: null collections still parse to empties.
|
||||
assert result["labels"] == []
|
||||
assert result["assignees"] == []
|
||||
Reference in New Issue
Block a user