From efc1b6e785628f34892f8f7c9dd62cdfbedee47d Mon Sep 17 00:00:00 2001 From: mrKazzila Date: Fri, 18 Sep 2026 16:28:54 +0300 Subject: [PATCH 01/12] feat: improve logging skill guidance and validation Clarify task scope, preserve event contracts, and align logging examples. Update installation docs, add portable validation, CI checks, and behavioral eval scenarios. --- .github/pull_request_template.md | 4 +- .github/workflows/quality.yml | 23 ++ .github/workflows/release.yml | 8 + .gitignore | 2 + README.md | 56 +++-- evals/README.md | 25 ++ evals/cases.json | 111 +++++++++ evals/fixtures/async_jobs.py | 25 ++ evals/fixtures/cli.py | 5 + evals/fixtures/sensitive.py | 11 + evals/fixtures/service.py | 19 ++ just/quality.just | 14 +- .../skills/python-structured-logging/SKILL.md | 163 +++----------- .../agents/openai.yaml | 2 +- .../examples/stdlib/bad.py | 28 +-- .../examples/stdlib/good.py | 27 +-- .../examples/structlog/bad.py | 22 +- .../examples/structlog/good.py | 30 +-- .../references/Python Logging Style Guide.md | 213 ++---------------- requirements-dev.txt | 2 + scripts/validate_repo.py | 145 ++++++++++++ tests/test_examples.py | 110 +++++++++ tests/test_validation.py | 53 +++++ 23 files changed, 678 insertions(+), 420 deletions(-) create mode 100644 .github/workflows/quality.yml create mode 100644 evals/README.md create mode 100644 evals/cases.json create mode 100644 evals/fixtures/async_jobs.py create mode 100644 evals/fixtures/cli.py create mode 100644 evals/fixtures/sensitive.py create mode 100644 evals/fixtures/service.py create mode 100644 requirements-dev.txt create mode 100644 scripts/validate_repo.py create mode 100644 tests/test_examples.py create mode 100644 tests/test_validation.py diff --git a/.github/pull_request_template.md b/.github/pull_request_template.md index 4024982..9b8f7c3 100644 --- a/.github/pull_request_template.md +++ b/.github/pull_request_template.md @@ -16,7 +16,7 @@ Describe what this PR changes and why. - [ ] `examples/stdlib/` - [ ] plugin metadata - [ ] `README.md` -- [ ] `_.github/` +- [ ] `.github/` ## Behavior impact Explain any user-visible change in skill triggering, recommendations, examples, or installation flow. @@ -37,7 +37,7 @@ Notes (include details if you could not run something): - [ ] Updated examples to match the guidance ## Checklist -- [ ] I kept the repo aligned with a `structlog`-first but Python-wide logging stance +- [ ] I kept the repo aligned with the existing logging stack and user-requested scope - [ ] I did not silently contradict the bundled reference guide - [ ] I preserved the split between `structlog` and stdlib examples where applicable - [ ] I kept installation and metadata paths consistent with the current repo layout diff --git a/.github/workflows/quality.yml b/.github/workflows/quality.yml new file mode 100644 index 0000000..308f9cf --- /dev/null +++ b/.github/workflows/quality.yml @@ -0,0 +1,23 @@ +name: Quality + +on: + pull_request: + push: + branches: ['**'] + +permissions: + contents: read + +jobs: + check: + runs-on: ubuntu-latest + steps: + - uses: actions/checkout@v4 + - uses: actions/setup-python@v5 + with: + python-version: '3.12' + cache: pip + - run: python -m pip install -r requirements-dev.txt + - run: python scripts/validate_repo.py + - run: python -m unittest discover -s tests -v + - run: python scripts/check_release_state.py diff --git a/.github/workflows/release.yml b/.github/workflows/release.yml index fde4e22..7f22957 100644 --- a/.github/workflows/release.yml +++ b/.github/workflows/release.yml @@ -23,6 +23,14 @@ jobs: with: python-version: '3.12' + - name: Install validation dependencies + run: python -m pip install -r requirements-dev.txt + + - name: Validate skill and examples + run: | + python scripts/validate_repo.py + python -m unittest discover -s tests -v + - name: Validate release state run: | python3 scripts/check_release_state.py --expected-version "${GITHUB_REF_NAME}" diff --git a/.gitignore b/.gitignore index 0792d49..50a0420 100644 --- a/.gitignore +++ b/.gitignore @@ -4,3 +4,5 @@ venv .uv* .DS_Store +__pycache__/ +*.py[cod] diff --git a/README.md b/README.md index dd40acb..5cb408c 100644 --- a/README.md +++ b/README.md @@ -29,27 +29,26 @@ npx skills add https://github.com/mrKazzila/python-structured-logging-skill ### Manual install -#### Claude Code +Copy the inner `plugins/python-structured-logging/skills/python-structured-logging` directory, including its examples and references. Run these commands from the repository root; choose the location for your client. -Copy this repository into the target project's `/.claude` folder. +| Client / scope | Destination | +| --- | --- | +| Claude Code / project | `/.claude/skills/python-structured-logging` | +| Codex / user | `~/.agents/skills/python-structured-logging` | +| OpenCode / user | `~/.config/opencode/skills/python-structured-logging` | -See the [official Claude Skills documentation](https://platform.claude.com/docs/en/agents-and-tools/agent-skills/overview). - -#### Codex CLI - -Copy [`plugins/python-structured-logging/skills/python-structured-logging`](plugins/python-structured-logging/skills/python-structured-logging) into your Codex skills path, typically `~/.codex/skills/python-structured-logging`. - -See the [Agent Skills specification](https://agentskills.io/specification) for the standard skill format. - -#### OpenCode - -Clone the entire repo into the OpenCode skills directory: +For example, for Codex: ```sh -git clone https://github.com/mrKazzila/python-structured-logging-skill.git ~/.opencode/skills/python-structured-logging-skill +mkdir -p ~/.agents/skills +cp -R plugins/python-structured-logging/skills/python-structured-logging ~/.agents/skills/ ``` -Do not copy only the inner `skills/` folder. OpenCode auto-discovers `SKILL.md` files under `~/.opencode/skills/`. +For an existing installation, update its contents rather than nesting another copy. Do not copy the entire repository into a skill directory. + +Verify discovery in a fresh client session: use `/python-structured-logging` for a manually installed Claude Code skill, `/skills` or `$python-structured-logging` in Codex, or ask OpenCode to list available skills. For Claude plugin installation, the command is namespaced as `/python-structured-logging:python-structured-logging`. + +See the official [Claude Code](https://code.claude.com/docs/en/skills), [Codex](https://learn.chatgpt.com/docs/build-skills), and [OpenCode](https://opencode.ai/docs/skills/) documentation. Paths were checked against documentation on 2026-09-18; discovery still needs a smoke test in your client version. The skill inspects the logging stack already in use before changing anything. If the project already uses `structlog`, it leans into bound context and structured fields. If the project intentionally uses stdlib `logging`, it improves event names, `extra` payloads, and traceback handling without forcing a migration. @@ -71,24 +70,33 @@ The skill inspects the logging stack already in use before changing anything. If ## When Not to Use -- The user explicitly asked not to change logging behavior. +- The task is unrelated to logging. Review-only requests are supported and must not change files. - The task is a one-off throwaway script where logging would add more noise than value. - The project has strict logging conventions and the current task is unrelated to logging or observability. ## Verify / Contribute -- Edit the skill or reference guide. -- Update examples if the recommended behavior changes. -- Run checks before finishing: +Requires Python 3.12+ and either `uv` with `just`, or a Python virtual environment. No local Codex installation is needed. ```sh -just validate -python scripts/check_release_state.py +just check ``` -- `just validate` uses `uv` plus `pyyaml`. If `pyyaml` is not already available, `uv` may need a writable cache and network access to fetch it. -- `uv run python scripts/check_release_state.py` is an equivalent release-state check if you prefer to keep the command under `uv`. -- Keep the skill concise, direct, and usable by agents during review and refactoring. +Equivalent commands without `just` or `uv`: + +```sh +python3 -m venv .venv +.venv/bin/python -m pip install -r requirements-dev.txt +.venv/bin/python scripts/validate_repo.py +.venv/bin/python -m unittest discover -s tests -v +.venv/bin/python scripts/check_release_state.py +``` + +Dependencies are pinned in `requirements-dev.txt`. The first installation requires access to a package index. `just validate` runs structural validation; `just test` runs executable example and validator regression checks. CI runs these checks on pull requests, branch pushes, and before a release. + +Behavioral agent evaluation is separate: see [evals/README.md](evals/README.md) for fixtures, prompts, acceptance criteria, and skill/no-skill comparisons. Passing structural checks does not establish agent quality. + +Keep changes scoped and update examples or eval cases when the recommended behavior changes. ## License diff --git a/evals/README.md b/evals/README.md new file mode 100644 index 0000000..10f0c39 --- /dev/null +++ b/evals/README.md @@ -0,0 +1,25 @@ +# Behavioral evaluations + +These cases evaluate agent decisions separately from deterministic repository checks. They have not been benchmarked yet. `cases.json` contains prompts, input files, expected implicit activation, and outcome criteria. Keep cases and results outside the installed skill so the agent does not see the grading answers. + +## Run a case + +1. Create a fresh temporary project and copy only the listed fixtures into it, keeping their basenames. Install any fixture dependencies in an isolated environment. Record initial file checksums. +2. Start a fresh agent session with no prior discussion of the expected solution. Use the exact prompt from the case. For activation tests, make the skill discoverable without naming it in the prompt. Inspect the trace to determine whether it was loaded. +3. Allow local edits and tests only in the temporary project. These cases need no production services, real credentials, publishing, or network access beyond dependency setup. +4. Save the trace, final response, diff, emitted logs, and test output. Score each criterion with evidence; do not grade exact wording or prescribed code structure. Use runtime checks for output and behavior, and human review for scope and diagnostic usefulness. +5. Repeat in a separate clean context without the skill installed or available through another plugin. Do not force skill invocation in the baseline. Use the same model, runtime, prompt, dependencies, and permissions. + +Run at least three trials per case and condition when making quality claims. Also compare the old and new skill revisions if evaluating an instruction change. Explicit invocation can be tested separately, but cannot establish implicit activation accuracy. Models may need different amounts of guidance; report results per model instead of pooling them. + +## Record results + +Use a JSONL row per trial with these fields: + +```json +{"case_id":"stdlib_refactor","condition":"with_skill","skill_commit":"","model":"","runtime":"","trial":1,"skill_loaded":true,"criteria":[{"index":0,"passed":true,"evidence":""}],"elapsed_seconds":0,"input_tokens":null,"output_tokens":null,"artifacts":""} +``` + +Use null for unavailable metrics; do not infer them. Mark unresolved criteria as null with an explanation, rather than passing them. Summarize per-case pass rates, activation misses/false positives, latency, and token usage where available. Compare paired outcomes with and without the skill. Store results outside the skill package; no generated results are committed by the deterministic checks. + +The unit tests in `tests/` verify the bundled examples and repository validator. They do not execute an agent or prove that it passes these scenarios. diff --git a/evals/cases.json b/evals/cases.json new file mode 100644 index 0000000..89245b3 --- /dev/null +++ b/evals/cases.json @@ -0,0 +1,111 @@ +{ + "cases": [ + { + "id": "stdlib_refactor", + "should_trigger": true, + "fixtures": [ + "plugins/python-structured-logging/skills/python-structured-logging/examples/stdlib/bad.py" + ], + "prompt": "Improve logging in bad.py using the existing stdlib stack. Preserve its signature and business behavior. Demonstrate fields in rendered output with a test formatter.", + "criteria": [ + "No structlog dependency or arbitrary keyword fields are introduced.", + "Success returns None; negative amount raises PaymentGatewayError with the original message.", + "Rendered output contains invoice and request IDs; the failure has one traceback record.", + "No module-level handler installation or global logging reconfiguration is introduced." + ] + }, + { + "id": "structlog_refactor", + "should_trigger": true, + "fixtures": [ + "plugins/python-structured-logging/skills/python-structured-logging/examples/structlog/bad.py" + ], + "prompt": "Improve logging in bad.py while preserving the current stack, function signature, and exception behavior.", + "criteria": [ + "A stable event and structured fields replace interpolated variable event names.", + "Successful input returns None and negative input still raises PaymentGatewayError.", + "A failure produces one record with traceback; negative input is not marked retryable." + ] + }, + { + "id": "review_only", + "should_trigger": true, + "fixtures": [ + "plugins/python-structured-logging/skills/python-structured-logging/examples/stdlib/bad.py" + ], + "prompt": "Review the logging in bad.py. Report issues and concrete effects. Do not modify files.", + "criteria": [ + "Fixture checksums are unchanged and no new project files appear.", + "Findings identify dynamic events and missing traceback with file locations.", + "No migration or code edit is performed." + ] + }, + { + "id": "event_contract", + "should_trigger": true, + "fixtures": [ + "evals/fixtures/service.py" + ], + "prompt": "Add amount_cents to the success log in service.py. Existing dotted event names are consumed by production alerts and must remain unchanged.", + "criteria": [ + "Both dotted event names remain unchanged.", + "The success LogRecord contains amount_cents.", + "Function signatures, return values and exception behavior remain unchanged." + ] + }, + { + "id": "exception_owner", + "should_trigger": true, + "fixtures": [ + "evals/fixtures/service.py" + ], + "prompt": "Review exception logging across charge and handle_invoice. Change it only if necessary to prevent duplicate failure records.", + "criteria": [ + "One call with negative input produces exactly one failure record with traceback.", + "The ValueError still propagates.", + "No failure log is added to charge; leaving correct logging unchanged is acceptable." + ] + }, + { + "id": "context_lifecycle", + "should_trigger": true, + "fixtures": [ + "evals/fixtures/async_jobs.py" + ], + "prompt": "Fix job context leaking into worker_idle in async_jobs.py. Preserve event names and ensure overlapping jobs retain their own IDs.", + "criteria": [ + "Run the program and decode every JSON line.", + "Each job_processed event has its own job_id: one, two, three.", + "worker_idle has no job_id.", + "Cleanup also executes if processing raises; demonstrate that path with a focused test." + ] + }, + { + "id": "unrelated_cli", + "should_trigger": false, + "fixtures": [ + "evals/fixtures/cli.py" + ], + "prompt": "Change render_total to include currency USD in its JSON output. Preserve stdout as the result stream.", + "criteria": [ + "The logging skill is not implicitly selected.", + "JSON on stdout contains amount_cents and currency USD.", + "No logging dependency, configuration, or conversion of print to logging is introduced." + ] + }, + { + "id": "sensitive_output", + "should_trigger": true, + "fixtures": [ + "evals/fixtures/sensitive.py" + ], + "prompt": "Make logging in sensitive.py safe for payloads containing synthetic credentials. Preserve exception propagation. Verify the rendered failure output.", + "criteria": [ + "Neither the synthetic marker nor payload credentials occur anywhere in rendered logs.", + "The original ValueError still propagates with its original message.", + "The solution checks exception text as well as structured fields.", + "The record retains enough operation and error-type information to diagnose the failure." + ] + } + ] +} diff --git a/evals/fixtures/async_jobs.py b/evals/fixtures/async_jobs.py new file mode 100644 index 0000000..fdc4c08 --- /dev/null +++ b/evals/fixtures/async_jobs.py @@ -0,0 +1,25 @@ +import asyncio + +import structlog + +structlog.configure(processors=[ + structlog.contextvars.merge_contextvars, + structlog.processors.JSONRenderer(), +]) +logger = structlog.get_logger() + + +async def run_job(job_id): + structlog.contextvars.bind_contextvars(job_id=job_id) + await asyncio.sleep(0) + logger.info('job_processed') + + +async def main(): + await asyncio.gather(run_job('one'), run_job('two')) + await run_job('three') + logger.info('worker_idle') + + +if __name__ == '__main__': + asyncio.run(main()) diff --git a/evals/fixtures/cli.py b/evals/fixtures/cli.py new file mode 100644 index 0000000..663324e --- /dev/null +++ b/evals/fixtures/cli.py @@ -0,0 +1,5 @@ +import json + + +def render_total(amount_cents): + print(json.dumps({'amount_cents': amount_cents})) diff --git a/evals/fixtures/sensitive.py b/evals/fixtures/sensitive.py new file mode 100644 index 0000000..23a3667 --- /dev/null +++ b/evals/fixtures/sensitive.py @@ -0,0 +1,11 @@ +import logging + +logger = logging.getLogger(__name__) + + +def process_request(payload): + try: + raise ValueError('upstream rejected token=TEST_SECRET_DO_NOT_USE') + except ValueError: + logger.exception('request_failed', extra={'payload': payload}) + raise diff --git a/evals/fixtures/service.py b/evals/fixtures/service.py new file mode 100644 index 0000000..4c76b83 --- /dev/null +++ b/evals/fixtures/service.py @@ -0,0 +1,19 @@ +import logging + +logger = logging.getLogger(__name__) + + +def charge(amount_cents): + if amount_cents < 0: + raise ValueError('negative amount') + return amount_cents + + +def handle_invoice(invoice_id, amount_cents): + try: + result = charge(amount_cents) + except ValueError: + logger.exception('invoice.charge.failed', extra={'invoice_id': invoice_id}) + raise + logger.info('invoice.charge.completed', extra={'invoice_id': invoice_id}) + return result diff --git a/just/quality.just b/just/quality.just index e4b232f..29ffc6c 100644 --- a/just/quality.just +++ b/just/quality.just @@ -1,4 +1,14 @@ [group('Quality')] -[doc('To validate the skill folder structure and frontmatter')] +[doc('Validate skill metadata, resources, and plugin paths')] validate: - @uv run --with pyyaml python "${CODEX_HOME:-$HOME/.codex}/skills/.system/skill-creator/scripts/quick_validate.py" plugins/python-structured-logging/skills/python-structured-logging + @uv run --with-requirements requirements-dev.txt python scripts/validate_repo.py + +[group('Quality')] +[doc('Run example and validator regression tests')] +test: + @uv run --with-requirements requirements-dev.txt python -m unittest discover -s tests -v + +[group('Quality')] +[doc('Run all deterministic checks')] +check: validate test + @python3 scripts/check_release_state.py diff --git a/plugins/python-structured-logging/skills/python-structured-logging/SKILL.md b/plugins/python-structured-logging/skills/python-structured-logging/SKILL.md index f79bdbf..fccb1dc 100644 --- a/plugins/python-structured-logging/skills/python-structured-logging/SKILL.md +++ b/plugins/python-structured-logging/skills/python-structured-logging/SKILL.md @@ -1,147 +1,56 @@ --- name: python-structured-logging -description: Use when reviewing or changing Python logging behavior, including structlog, stdlib logging, event naming, structured fields, bound context, exception logging, correlation IDs, or sensitive-data-safe observability. +description: Review or improve Python logging with structlog, stdlib logging, or existing wrappers. Use for logging changes, not unrelated Python refactoring. --- # Python Structured Logging -## Core Rule +Make logs useful operational events while preserving the user's scope and the project's contracts. -Logs are operational events, not developer diary entries. +## Scope and workflow -## Workflow +- For review requests, report findings with file locations and concrete effects; edit only when requested. +- Inspect the existing logger API, formatter/processors, exception ownership, and event conventions before proposing changes. +- Keep the current stack and wrappers. If migration would help, explain why; do not migrate without authorization. +- Preserve business behavior, function signatures, exception propagation, and retry decisions during logging refactors. +- Treat existing event names and fields as contracts that may feed alerts, dashboards, and queries. Preserve them unless changing that contract is in scope. +- When no convention exists, use stable `snake_case` events such as `invoice_processed`; put variable values in fields. +- Replace diagnostic `print` calls only when in scope. Preserve intentional CLI output. -1. Inspect the current stack first: `structlog`, stdlib `logging`, or a project wrapper. -2. Preserve the current direction unless it is harmful or migration was explicitly requested. -3. If the project uses stdlib `logging` intentionally, improve message shape and `extra` fields instead of forcing `structlog`. -4. Replace prose or dynamic event names with stable `snake_case` events. -5. Move variable data into structured fields and bind shared context once near the request or job boundary. -6. Keep one meaningful exception log at the layer that owns the failure, with a traceback when needed. -7. Remove or redact sensitive data before it reaches bound context or payload fields. -8. Verify output shape, levels, and noise after the change. +## Choose the matching API -## Event Naming +Read only the examples for the project's stack: -- Use stable `snake_case` event names. -- Prefer action or action-plus-result names such as `invoice_processed` or `broker_publish_failed`. -- Do not put IDs, emails, statuses, or exception text into the event name. -- Do not use generic events such as `error`, `failed`, or `something_went_wrong` without the operation name. +- **structlog:** [good](examples/structlog/good.py), [bad](examples/structlog/bad.py). Use keyword fields and a locally bound logger. +- **stdlib logging:** [good](examples/stdlib/good.py), [bad](examples/stdlib/bad.py). Use `extra` or the existing adapter; arbitrary keyword fields and `.bind()` are not stdlib APIs. `extra` adds LogRecord attributes, but the formatter must emit them. Avoid reserved LogRecord keys. +- **Project wrappers:** inspect their interface and output before adapting either pattern. -Good: +The example pairs have identical inputs and business behavior. Their operation owns the failure log; a caller must not log the same failure again. -```python -logger.info("invoice_processed", invoice_id=invoice_id, duration_ms=duration_ms) -logger.warning("retry_scheduled", attempt=attempt, delay_seconds=delay_seconds) -``` +## Fields and context -Bad: +- Follow existing field names. For new fields, use explicit units such as `duration_ms` and `size_bytes`. +- Bind or inject shared context at a meaningful request/job boundary where supported. Repeating `extra` is acceptable when it is simpler and correct. +- A locally bound structlog logger does not automatically attach context to every logger in a request. For cross-module or concurrent context, read the [context lifecycle guidance](references/Python%20Logging%20Style%20Guide.md#context-lifecycle). +- Allowlist necessary payload fields before binding them. Do not log credentials, tokens, authorization headers, or raw sensitive payloads. Identifiers and payment-derived fields still need the project's data policy; masking alone does not make them universally safe. -```python -logger.info(f"invoice {invoice_id} processed in {duration_ms} ms") -logger.error(f"publish failed for order {order_id}") -logger.info(f"user_{user_id}_updated") -``` +## Exceptions and levels -## Fields and Context +- Identify the layer responsible for the final operational outcome. Log a failure once there; lower layers can propagate it without logging. +- Use `logger.exception(...)` inside `except` when a traceback is appropriate. Preserve the original control flow; do not introduce swallowing, re-raising, or retries merely to improve a log. +- Derive retryability from the real failure and retry policy, never from the presence of an exception. +- Tracebacks and exception messages can contain sensitive values even if structured fields are safe. Inspect the rendered output and use the existing sanitization path when needed. +- Use `INFO` for meaningful outcomes, `DEBUG` for optional diagnostics, `WARNING` for actionable degradation, and `ERROR` for failed operations needing attention, subject to project conventions. +- Avoid per-item loop noise and redundant boundary logs; retain start/progress events when they help diagnose long-running or stalled work. -- Use stable field names such as `request_id`, `correlation_id`, `job_id`, `user_id`, `entity_id`, `status`, and `duration_ms` when they are relevant. -- Bind shared context once when possible instead of passing the same fields manually everywhere. -- Keep units in the key name: `duration_ms`, `delay_seconds`, `size_bytes`. -- Avoid renaming the same concept across modules. -- Prefer allowlisted payload fragments such as `{"amount_cents": ..., "card_last4": ...}` over raw payload logging. +## Verify the result -Good: +Check a representative success and failure through the configured output pipeline: -```python -log = logger.bind(request_id=request_id, job_id=job_id) -log.info("job_started", task_name=task_name) -``` +- Existing event/field contracts and application behavior are preserved. +- Fields survive formatting and serialization; no logger API errors occur. +- One appropriate failure record appears, with a traceback when needed. +- Sensitive values are absent from fields, messages, and rendered exceptions. +- Request/job context does not leak into another operation. -Bad: - -```python -logger.info("job started", extra={"req": request_id, "job": job_id}) -logger.info("job_started", request_id=request_id, job_id=job_id) -logger.info("job_finished", request_id=request_id, job_id=job_id) -``` - -## Exception Logging - -- Use `logger.exception(...)` inside `except` when you need the traceback. -- Use `exc_info=True` only when the logger API requires it. -- Do not log and swallow unless that behavior is intentional and the caller does not need the failure. -- Do not duplicate the same exception log at every layer. -- Do not use `logger.error(str(exc))` as the only exception log for unexpected failures. - -Good: - -```python -try: - send_invoice(invoice) -except ProviderTimeoutError: - logger.exception("invoice_send_failed", invoice_id=invoice.id, retryable=True) - raise -``` - -Bad: - -```python -try: - send_invoice(invoice) -except Exception as exc: - logger.error(f"invoice failed: {exc}") -``` - -## Sensitive Data - -- Never log passwords, tokens, API keys, cookies, authorization headers, private keys, or raw secrets. -- Never log raw request bodies, raw response bodies, session data, personal data, or payment data unless the user explicitly asks for a safe, scoped format. -- Prefer allowlisted fields over blocklists when logging payload-derived data. -- Redact at boundaries before binding context. - -Good: - -```python -safe_payment = { - "card_last4": payment.card_last4, - "amount_cents": payment.amount_cents, -} -logger.info("payment_authorized", payment=safe_payment) -``` - -Bad: - -```python -logger.info("payment_authorized", payload=payment_payload, auth_header=auth_header) -``` - -## Noise Control - -- `INFO` for business or operational events that matter. -- `DEBUG` for local diagnostics that can be turned off safely. -- `WARNING` for degraded but handled situations such as retries or fallbacks. -- `ERROR` for failed operations that need attention. -- Avoid logs inside tight loops unless they are sampled or aggregated. -- Remove `started` and `finished` chatter unless the boundary is operationally meaningful. -- Prefer one outcome log over multiple step-by-step logs when the extra detail does not change operator action. - -## Bundled Resources - -- [`examples/structlog/good.py`](examples/structlog/good.py) -- [`examples/structlog/bad.py`](examples/structlog/bad.py) -- [`examples/stdlib/good.py`](examples/stdlib/good.py) -- [`examples/stdlib/bad.py`](examples/stdlib/bad.py) -- [`references/Python Logging Style Guide.md`](references/Python Logging Style Guide.md) - -- Read the examples that match the stack already in use. -- Read the reference guide when you need human-oriented rationale, level guidance, or migration examples. - -## Verification Checklist - -- Current logging style is preserved or intentionally migrated. -- Event names are stable and `snake_case`. -- Variable data is in fields, not prose strings. -- Shared context is bound or injected once where the stack supports it. -- Exceptions include stack traces where needed. -- Sensitive data is redacted or omitted. -- Output still fits the project's log pipeline. +Use focused tests or output capture proportional to the change. Report what was checked and any unverified pipeline assumptions. Read the [reference guide](references/Python%20Logging%20Style%20Guide.md) for formatter, context, and exception edge cases. diff --git a/plugins/python-structured-logging/skills/python-structured-logging/agents/openai.yaml b/plugins/python-structured-logging/skills/python-structured-logging/agents/openai.yaml index 38d5a20..7655245 100644 --- a/plugins/python-structured-logging/skills/python-structured-logging/agents/openai.yaml +++ b/plugins/python-structured-logging/skills/python-structured-logging/agents/openai.yaml @@ -1,4 +1,4 @@ interface: display_name: "Python Structured Logging" short_description: "Practical guidance for safer, more useful Python logs" - default_prompt: "Use $python-structured-logging to inspect the current Python logging stack, tighten event names and fields, and improve exception logging without forcing an unnecessary migration." + default_prompt: "Use $python-structured-logging to review Python logging, report concrete findings, and preserve the existing stack and event contracts. Apply changes only when requested." diff --git a/plugins/python-structured-logging/skills/python-structured-logging/examples/stdlib/bad.py b/plugins/python-structured-logging/skills/python-structured-logging/examples/stdlib/bad.py index 184ccfa..e582354 100644 --- a/plugins/python-structured-logging/skills/python-structured-logging/examples/stdlib/bad.py +++ b/plugins/python-structured-logging/skills/python-structured-logging/examples/stdlib/bad.py @@ -1,30 +1,24 @@ import logging - logger = logging.getLogger(__name__) +class PaymentGatewayError(RuntimeError): + pass + + def process_invoice( invoice_id: str, customer_id: str, request_id: str, attempt: int, - payment_payload: dict, + amount_cents: int, ) -> None: - print("starting invoice processing", invoice_id, customer_id, request_id) - logger.info( - f"processing invoice {invoice_id} for customer {customer_id} attempt={attempt}" - ) - try: - logger.info( - f"invoice_{invoice_id}_processed", - extra={ - "payload": payment_payload, - "request": request_id, - "authorization_header": "Bearer secret-token", - }, - ) - except Exception as exc: + if amount_cents < 0: + raise PaymentGatewayError("negative amount") + + logger.info(f"invoice_{invoice_id}_processed for customer {customer_id} request={request_id} attempt={attempt}") + except PaymentGatewayError as exc: logger.error(f"invoice processing failed for {invoice_id}: {exc}") - return + raise diff --git a/plugins/python-structured-logging/skills/python-structured-logging/examples/stdlib/good.py b/plugins/python-structured-logging/skills/python-structured-logging/examples/stdlib/good.py index 80153df..30e4107 100644 --- a/plugins/python-structured-logging/skills/python-structured-logging/examples/stdlib/good.py +++ b/plugins/python-structured-logging/skills/python-structured-logging/examples/stdlib/good.py @@ -1,6 +1,5 @@ import logging - logger = logging.getLogger(__name__) @@ -15,36 +14,18 @@ def process_invoice( attempt: int, amount_cents: int, ) -> None: - shared_context = { + # This operation owns the failure record; callers propagate without logging. + context = { "request_id": request_id, "invoice_id": invoice_id, "customer_id": customer_id, "attempt": attempt, } - safe_payment = { - "amount_cents": amount_cents, - "card_last4": "4242", - } - try: if amount_cents < 0: raise PaymentGatewayError("negative amount") - logger.info( - "invoice_processed", - extra={ - **shared_context, - "status": "success", - "payment": safe_payment, - }, - ) + logger.info("invoice_processed", extra={**context, "amount_cents": amount_cents}) except PaymentGatewayError: - logger.exception( - "invoice_processing_failed", - extra={ - **shared_context, - "retryable": True, - "payment": safe_payment, - }, - ) + logger.exception("invoice_processing_failed", extra={**context, "retryable": False}) raise diff --git a/plugins/python-structured-logging/skills/python-structured-logging/examples/structlog/bad.py b/plugins/python-structured-logging/skills/python-structured-logging/examples/structlog/bad.py index 3b6f5c3..3a23c9c 100644 --- a/plugins/python-structured-logging/skills/python-structured-logging/examples/structlog/bad.py +++ b/plugins/python-structured-logging/skills/python-structured-logging/examples/structlog/bad.py @@ -1,26 +1,24 @@ import structlog - logger = structlog.get_logger(__name__) +class PaymentGatewayError(RuntimeError): + pass + + def process_invoice( invoice_id: str, customer_id: str, request_id: str, attempt: int, - payment_payload: dict, + amount_cents: int, ) -> None: try: - logger.info( - f"starting invoice processing for invoice={invoice_id}, customer={customer_id}, request={request_id}" - ) - logger.info( - f"invoice_{invoice_id}_processed", - payload=payment_payload, - attempt=attempt, - authorization_header="Bearer secret-token", - ) - except Exception as exc: + if amount_cents < 0: + raise PaymentGatewayError("negative amount") + + logger.info(f"invoice_{invoice_id}_processed for customer {customer_id} request={request_id} attempt={attempt}") + except PaymentGatewayError as exc: logger.error(f"invoice processing failed for {invoice_id}: {exc}") raise diff --git a/plugins/python-structured-logging/skills/python-structured-logging/examples/structlog/good.py b/plugins/python-structured-logging/skills/python-structured-logging/examples/structlog/good.py index 8e7fb07..043d003 100644 --- a/plugins/python-structured-logging/skills/python-structured-logging/examples/structlog/good.py +++ b/plugins/python-structured-logging/skills/python-structured-logging/examples/structlog/good.py @@ -1,6 +1,5 @@ import structlog - logger = structlog.get_logger(__name__) @@ -15,30 +14,19 @@ def process_invoice( attempt: int, amount_cents: int, ) -> None: - log = logger.bind( - request_id=request_id, - invoice_id=invoice_id, - customer_id=customer_id, - attempt=attempt, - ) - safe_payment = { - "amount_cents": amount_cents, - "card_last4": "4242", + # This operation owns the failure record; callers propagate without logging. + context = { + "request_id": request_id, + "invoice_id": invoice_id, + "customer_id": customer_id, + "attempt": attempt, } - + log = logger.bind(**context) try: if amount_cents < 0: raise PaymentGatewayError("negative amount") - log.info( - "invoice_processed", - status="success", - payment=safe_payment, - ) + log.info("invoice_processed", amount_cents=amount_cents) except PaymentGatewayError: - log.exception( - "invoice_processing_failed", - retryable=True, - payment=safe_payment, - ) + log.exception("invoice_processing_failed", retryable=False) raise diff --git a/plugins/python-structured-logging/skills/python-structured-logging/references/Python Logging Style Guide.md b/plugins/python-structured-logging/skills/python-structured-logging/references/Python Logging Style Guide.md index 517d384..93d2f4a 100644 --- a/plugins/python-structured-logging/skills/python-structured-logging/references/Python Logging Style Guide.md +++ b/plugins/python-structured-logging/skills/python-structured-logging/references/Python Logging Style Guide.md @@ -1,210 +1,41 @@ -# Python Logging Style Guide +# Python Logging Integration Notes -Use this reference when you need human-oriented guidance for reviewing or improving logs in Python code. The skill file is the execution checklist; this guide adds rationale, examples, and migration patterns. Prefer `structlog` when the project already uses it, and keep stdlib `logging` when the project intentionally standardized on it. +Read the section relevant to the current stack or failure mode. Shared scope and naming rules live in `SKILL.md`. -## Core Rules +## Output pipeline -- Treat each log as an operational event. -- Keep event names short, stable, and in `snake_case`. -- Put variable data into fields, not interpolated prose. -- Bind shared context once when possible. -- Preserve stack traces for unexpected failures. -- Redact sensitive data before it reaches logs. -- Keep debug noise on a short leash. +Stdlib `extra` adds attributes to a LogRecord; a default text formatter does not include arbitrary attributes. Inspect the project's formatter before claiming the output is structured. Preserve the existing handler configuration; reusable modules should not call `basicConfig()` or install root handlers. -## Event Naming +Use `extra={"invoice_id": invoice_id}` with stdlib, and `invoice_id=invoice_id` with structlog. Do not use reserved LogRecord keys such as `name`, `message`, or `levelname` as `extra` fields. Formatter-required fields must also be handled for third-party records that lack them. -Prefer event names like: +Capture the final rendered output as well as records. Check JSON decoding where JSON is the configured format, field types, exception rendering, and duplicate records from handler propagation. A test that only captures the pre-render event dictionary cannot establish downstream compatibility. -```python -"invoice_processed" -"retry_scheduled" -"broker_publish_failed" -``` +## Context lifecycle -Avoid event names like: +`logger.bind(...)` returns a logger with additional context; pass that logger to code that needs it. It does not automatically enrich independent loggers elsewhere. -```python -"Invoice processed successfully!" -f"invoice_{invoice_id}_processed" -"something went wrong" -``` +For a structlog application already using contextvars, check that `merge_contextvars` is in the processor chain. Clear context at the start of a request/job, then bind its identifiers. Reset or clear context when the operation ends, including failure paths. Use scoped binding/token reset for nested operations that must restore parent context instead of clearing it. -Good: +Test two overlapping requests with distinct IDs and a subsequent operation with no ID. Their outputs must not share identifiers. Thread/task boundaries and hybrid sync/async frameworks may require explicit propagation; do not assume every execution context shares the same values. -```python -logger.info("invoice_processed", invoice_id=invoice_id, duration_ms=duration_ms) -``` +For stdlib, retain the existing adapter, filter, or record factory. Check the supported Python version and adapter behavior before relying on per-call `extra` merging. -Bad: +## Exception ownership and sensitive output -```python -logger.info(f"invoice {invoice_id} processed in {duration_ms} ms") -``` +Choose the owner based on the call chain: a request boundary, worker, or command may already record failures. Adding another exception log below it can duplicate alerts. If a lower layer owns the only failure record and propagates the exception, document that its caller must not log it again. -## Field Naming Conventions +`logger.exception` normally renders the exception message too. Allowlisting structured fields alone does not sanitize credentials embedded in a URL, exception text, or captured locals. Exercise the configured sanitizer with synthetic sensitive values and inspect its final output. Never use real secrets as fixtures. -Use stable `snake_case` field names and explicit units. +The paired examples use a non-retryable negative amount to illustrate preserved behavior. Both versions raise the same exception for the same input. The good version changes logging only; it does not add retry logic or invent payment metadata. -Preferred fields: +## Event contracts and migration -```text -request_id -correlation_id -job_id -user_id -entity_id -status -reason -error_code -duration_ms -delay_seconds -size_bytes -attempt -max_attempts -``` +Before renaming an event, inspect repository-owned dashboards, alerts, queries, and tests when available. Keep existing conventions such as dotted events when the task does not authorize a schema migration. If downstream consumers are external and cannot be checked, report that limitation. -Guidelines: +For requested migrations, explain old-to-new names and consumer updates. Diagnostic prints can become logs; intentional CLI results must remain on the expected output stream. -- One concept should keep one name across the project. -- IDs should normally end with `_id`. -- Units belong in the key name, not only in the value. -- Avoid repeating the same shared fields on every log if the stack supports binding or adapters. +## Sources -When logging payload-derived data, prefer allowlisted fragments over whole payloads. For example, log `card_last4`, `amount_cents`, or `item_count`, not the raw request body. - -## Level Guide - -- `DEBUG`: local diagnostics and temporary deep inspection. -- `INFO`: expected business or operational events. -- `WARNING`: degraded but handled situations such as retries or fallbacks. -- `ERROR`: a concrete operation failed and needs attention. -- `CRITICAL`: service-threatening state or probable data-loss scenario. - -Do not log every function entry and exit at `INFO`. Use `DEBUG` sparingly, and only when the details are actionable. - -## Exception Logging - -Use `logger.exception(...)` inside `except` when you need traceback data. - -Good: - -```python -try: - publish(message) -except ProviderTimeoutError: - logger.exception("publish_failed", message_id=message_id, retryable=True) - raise -``` - -Bad: - -```python -try: - publish(message) -except Exception as exc: - logger.error(f"publish failed: {exc}") -``` - -Rules: - -- Do not log and swallow unless that is the intended control flow. -- Do not duplicate the same exception log at every layer. -- Add enough context for operators to know what failed and whether it will retry. -- Avoid `logger.error(str(exc))` as the only record for an unexpected failure. - -## Sensitive Data - -Never log: - -- passwords -- tokens -- API keys -- cookies -- authorization headers -- private keys -- raw secrets -- raw request bodies -- raw response bodies -- session data -- personal data -- payment data -- raw payloads containing PII or credentials - -Prefer allowlisted payload logging. - -Good: - -```python -logger.info( - "payment_authorized", - payment={"amount_cents": amount_cents, "card_last4": card_last4}, -) -``` - -Bad: - -```python -logger.info("payment_authorized", payload=payment_payload, auth_header=auth_header) -``` - -## structlog and stdlib Patterns - -`structlog`: - -```python -log = logger.bind(request_id=request_id, job_id=job_id) -log.info("job_started", task_name=task_name) -``` - -Stdlib `logging`: - -```python -logger.info( - "job_started", - extra={"request_id": request_id, "job_id": job_id, "task_name": task_name}, -) -``` - -In both styles, keep the event name stable and treat the surrounding fields as the query surface. If a downstream formatter or adapter already shapes the record, follow that path instead of inventing a parallel one. - -## Migration Notes - -From `print` debugging: - -```python -print("processing invoice", invoice_id) -``` - -To structured logging: - -```python -logger.debug("invoice_processing", invoice_id=invoice_id) -``` - -From prose logging: - -```python -logger.info(f"user {user_id} updated account status to {status}") -``` - -To structured events: - -```python -logger.info("account_status_updated", user_id=user_id, status=status) -``` - -From repeated manual context: - -```python -logger.info("step_one", request_id=request_id, user_id=user_id) -logger.info("step_two", request_id=request_id, user_id=user_id) -``` - -To bound context: - -```python -log = logger.bind(request_id=request_id, user_id=user_id) -log.info("step_one") -log.info("step_two") -``` +- [Python logging API](https://docs.python.org/3/library/logging.html) +- [Python logging cookbook](https://docs.python.org/3/howto/logging-cookbook.html) +- [structlog context variables](https://www.structlog.org/en/stable/contextvars.html) diff --git a/requirements-dev.txt b/requirements-dev.txt new file mode 100644 index 0000000..2334466 --- /dev/null +++ b/requirements-dev.txt @@ -0,0 +1,2 @@ +PyYAML==6.0.2 +structlog==25.1.0 diff --git a/scripts/validate_repo.py b/scripts/validate_repo.py new file mode 100644 index 0000000..8d6d673 --- /dev/null +++ b/scripts/validate_repo.py @@ -0,0 +1,145 @@ +#!/usr/bin/env python3 +"""Validate this repository's skill and distribution metadata.""" + +from __future__ import annotations + +import json +import re +from pathlib import Path +from urllib.parse import unquote, urlsplit + +import yaml + +ROOT = Path(__file__).resolve().parent.parent +SKILL_NAME = "python-structured-logging" +PLUGIN = Path("plugins") / SKILL_NAME +SKILL = PLUGIN / "skills" / SKILL_NAME + + +def validate(root: Path = ROOT) -> list[str]: + errors: list[str] = [] + + def mapping(path: Path, loader) -> dict: + try: + value = loader(path.read_text(encoding="utf-8")) + if not isinstance(value, dict): + raise ValueError("expected a mapping") + return value + except (OSError, ValueError, yaml.YAMLError) as exc: + errors.append(f"{path.relative_to(root)}: {exc}") + return {} + + skill_path = root / SKILL + entrypoint = skill_path / "SKILL.md" + try: + text = entrypoint.read_text(encoding="utf-8") + except OSError as exc: + return [str(exc)] + match = re.match(r"\A---\r?\n(.*?)\r?\n---(?:\r?\n|$)", text, re.DOTALL) + metadata = {} + if not match: + errors.append("SKILL.md: missing YAML frontmatter delimiters") + else: + try: + metadata = yaml.safe_load(match.group(1)) + if not isinstance(metadata, dict): + raise ValueError("frontmatter must be a mapping") + except (ValueError, yaml.YAMLError) as exc: + errors.append(f"SKILL.md: {exc}") + metadata = {} + name = metadata.get("name") + if name != skill_path.name: + errors.append("SKILL.md: name must match the skill directory") + if not isinstance(name, str) or not re.fullmatch(r"[a-z0-9]+(?:-[a-z0-9]+)*", name) or len(name) > 64: + errors.append("SKILL.md: invalid skill name") + description = metadata.get("description") + if not isinstance(description, str) or not description.strip() or len(description) > 1024: + errors.append("SKILL.md: description must be a nonempty string of at most 1024 characters") + + # Repository docs use inline Markdown links. Resolve local paths, not web links. + documents = [root / "README.md", *skill_path.rglob("*.md"), *(root / "evals").rglob("*.md")] + for document in documents: + if not document.is_file(): + errors.append(f"Missing document: {document.relative_to(root)}") + continue + for target in re.findall(r"\[[^\]]*\]\(([^)]+)\)", document.read_text()): + target = target.strip("<>") + parsed = urlsplit(target) + if parsed.scheme or parsed.netloc or not parsed.path: + continue + destination = (document.parent / unquote(parsed.path)).resolve() + if not destination.is_relative_to(root.resolve()) or not destination.exists(): + errors.append(f"{document.relative_to(root)}: missing or external local resource {target}") + + ui = mapping(skill_path / "agents/openai.yaml", yaml.safe_load) + interface = ui.get("interface") + if not isinstance(interface, dict): + errors.append("agents/openai.yaml: missing interface mapping") + else: + for key in ("display_name", "short_description", "default_prompt"): + if not isinstance(interface.get(key), str) or not interface[key].strip(): + errors.append(f"agents/openai.yaml: missing {key}") + prompt = interface.get("default_prompt") + if not isinstance(prompt, str) or f"${SKILL_NAME}" not in prompt: + errors.append("agents/openai.yaml: default_prompt must invoke the skill") + + for directory in (".codex-plugin", ".claude-plugin"): + data = mapping(root / PLUGIN / directory / "plugin.json", json.loads) + if data.get("name") != SKILL_NAME: + errors.append(f"{directory}/plugin.json: inconsistent plugin name") + + for directory in (".agents/plugins", ".claude-plugin"): + data = mapping(root / directory / "marketplace.json", json.loads) + plugins = data.get("plugins") + if not isinstance(plugins, list) or len(plugins) != 1 or not isinstance(plugins[0], dict): + errors.append(f"{directory}: expected one plugin entry") + continue + plugin = plugins[0] + if plugin.get("name") != SKILL_NAME or plugin.get("source") != f"./{PLUGIN.as_posix()}": + errors.append(f"{directory}: plugin name/source does not match the bundled plugin") + if not (root / PLUGIN).is_dir(): + errors.append(f"{directory}: plugin source directory is missing") + + cases = mapping(root / "evals/cases.json", json.loads).get("cases") + if not isinstance(cases, list) or not cases: + errors.append("evals/cases.json: expected nonempty cases list") + else: + seen = set() + for case in cases: + if not isinstance(case, dict): + errors.append("evals/cases.json: each case must be a mapping") + continue + case_id = case.get("id") + if not isinstance(case_id, str) or not case_id or case_id in seen: + errors.append("evals/cases.json: missing or duplicate case id") + else: + seen.add(case_id) + for key in ("prompt",): + if not isinstance(case.get(key), str) or not case[key].strip(): + errors.append(f"eval {case_id}: missing {key}") + if not isinstance(case.get("should_trigger"), bool): + errors.append(f"eval {case_id}: should_trigger must be boolean") + criteria = case.get("criteria") + if not isinstance(criteria, list) or not criteria or not all(isinstance(c, str) and c.strip() for c in criteria): + errors.append(f"eval {case_id}: missing acceptance criteria") + fixtures = case.get("fixtures") + if not isinstance(fixtures, list) or not fixtures: + errors.append(f"eval {case_id}: missing fixtures") + continue + for fixture in fixtures: + if not isinstance(fixture, str): + errors.append(f"eval {case_id}: invalid fixture path") + continue + path = (root / fixture).resolve() + if not path.is_relative_to(root.resolve()) or not path.is_file(): + errors.append(f"eval {case_id}: missing fixture {fixture}") + return errors + + +if __name__ == "__main__": + problems = validate() + for problem in problems: + print(problem) + if problems: + raise SystemExit(1) + print("Skill, resource links, plugin paths, and eval cases are valid") diff --git a/tests/test_examples.py b/tests/test_examples.py new file mode 100644 index 0000000..6984298 --- /dev/null +++ b/tests/test_examples.py @@ -0,0 +1,110 @@ +"""Exercise emitted records and business behavior, not source spelling.""" + +import importlib.util +import inspect +import io +import json +import logging +import unittest +from pathlib import Path + +import structlog + +ROOT = Path(__file__).resolve().parents[1] +EXAMPLES = ROOT / 'plugins/python-structured-logging/skills/python-structured-logging/examples' + + +def load(stack, quality): + name = f'example_{stack}_{quality}' + spec = importlib.util.spec_from_file_location(name, EXAMPLES / stack / f'{quality}.py') + module = importlib.util.module_from_spec(spec) + spec.loader.exec_module(module) + return module + + +class JsonFormatter(logging.Formatter): + """Test output pipeline; application modules do not install handlers.""" + + def format(self, record): + payload = {'event': record.getMessage()} + for key in ('request_id', 'invoice_id', 'customer_id', 'attempt', 'amount_cents', 'retryable'): + if hasattr(record, key): + payload[key] = getattr(record, key) + if record.exc_info: + payload['exception'] = self.formatException(record.exc_info) + return json.dumps(payload) + + +class ExampleTests(unittest.TestCase): + def test_pairs_preserve_signatures_and_business_behavior(self): + for stack in ('stdlib', 'structlog'): + with self.subTest(stack=stack): + good, bad = load(stack, 'good'), load(stack, 'bad') + self.assertEqual(inspect.signature(good.process_invoice), inspect.signature(bad.process_invoice)) + for module in (good, bad): + # Keep intentionally bad log output out of the test runner. + with structlog.testing.capture_logs(): + logger = logging.getLogger(module.__name__) + old_disabled = logger.disabled + logger.disabled = True + try: + self.assertIsNone(module.process_invoice('i', 'c', 'r', 1, 100)) + with self.assertRaisesRegex(module.PaymentGatewayError, '^negative amount$'): + module.process_invoice('i', 'c', 'r', 1, -1) + finally: + logger.disabled = old_disabled + + def test_stdlib_rendered_success_failure_and_context(self): + module = load('stdlib', 'good') + logger = module.logger + previous = logger.handlers[:], logger.level, logger.propagate + output = io.StringIO() + handler = logging.StreamHandler(output) + handler.setFormatter(JsonFormatter()) + logger.handlers = [handler] + logger.setLevel(logging.INFO) + logger.propagate = False + try: + module.process_invoice('i1', 'c1', 'r1', 1, 100) + with self.assertRaises(module.PaymentGatewayError): + module.process_invoice('i2', 'c2', 'r2', 2, -1) + finally: + logger.handlers, logger.level, logger.propagate = previous + self.check_records([json.loads(line) for line in output.getvalue().splitlines()]) + + def test_structlog_rendered_success_failure_and_context(self): + previous = structlog.get_config().copy() + configured = structlog.is_configured() + output = io.StringIO() + try: + structlog.configure( + processors=[structlog.processors.format_exc_info, structlog.processors.JSONRenderer()], + logger_factory=structlog.PrintLoggerFactory(file=output), + cache_logger_on_first_use=False, + ) + module = load('structlog', 'good') + module.process_invoice('i1', 'c1', 'r1', 1, 100) + with self.assertRaises(module.PaymentGatewayError): + module.process_invoice('i2', 'c2', 'r2', 2, -1) + finally: + if configured: + structlog.configure(**previous) + else: + structlog.reset_defaults() + self.check_records([json.loads(line) for line in output.getvalue().splitlines()]) + + def check_records(self, records): + self.assertEqual(len(records), 2) + success, failure = records + self.assertEqual(success['event'], 'invoice_processed') + self.assertEqual(success['request_id'], 'r1') + self.assertEqual(success['invoice_id'], 'i1') + self.assertEqual(success['amount_cents'], 100) + self.assertNotIn('exception', success) + self.assertEqual(failure['event'], 'invoice_processing_failed') + self.assertEqual(failure['request_id'], 'r2') + self.assertEqual(failure['invoice_id'], 'i2') + self.assertIs(failure['retryable'], False) + self.assertIn('Traceback', failure['exception']) + self.assertIn('PaymentGatewayError: negative amount', failure['exception']) + self.assertNotIn('payment', failure) diff --git a/tests/test_validation.py b/tests/test_validation.py new file mode 100644 index 0000000..b176720 --- /dev/null +++ b/tests/test_validation.py @@ -0,0 +1,53 @@ +import json +import shutil +import tempfile +import unittest +from pathlib import Path + +from scripts.validate_repo import ROOT, SKILL, validate + + +class ValidationTests(unittest.TestCase): + def setUp(self): + self.temp = tempfile.TemporaryDirectory() + self.addCleanup(self.temp.cleanup) + self.root = Path(self.temp.name) + for directory in ('plugins', '.agents', '.claude-plugin', 'evals'): + shutil.copytree(ROOT / directory, self.root / directory) + for filename in ('README.md', 'LICENSE'): + shutil.copyfile(ROOT / filename, self.root / filename) + + def test_repository_is_valid(self): + self.assertEqual(validate(self.root), []) + + def test_malformed_yaml_is_rejected(self): + (self.root / SKILL / 'SKILL.md').write_text('---\nname: [\ndescription: broken\n---\n') + self.assertTrue(validate(self.root)) + + def test_wrong_name_is_rejected(self): + path = self.root / SKILL / 'SKILL.md' + path.write_text(path.read_text().replace('name: python-structured-logging', 'name: different-name', 1)) + self.assertTrue(any('name must match' in e for e in validate(self.root))) + + def test_missing_resource_is_rejected(self): + (self.root / SKILL / 'examples/stdlib/good.py').unlink() + self.assertTrue(any('missing or external local resource' in e for e in validate(self.root))) + + def test_wrong_marketplace_path_is_rejected(self): + path = self.root / '.agents/plugins/marketplace.json' + data = json.loads(path.read_text()) + data['plugins'][0]['source'] = './missing' + path.write_text(json.dumps(data)) + self.assertTrue(any('name/source' in e for e in validate(self.root))) + + def test_missing_eval_fixture_is_rejected(self): + path = self.root / 'evals/cases.json' + data = json.loads(path.read_text()) + data['cases'][0]['fixtures'] = ['evals/fixtures/missing.py'] + path.write_text(json.dumps(data)) + self.assertTrue(any('missing fixture' in e for e in validate(self.root))) + + def test_invalid_ui_prompt_is_reported_without_crashing(self): + path = self.root / SKILL / 'agents/openai.yaml' + path.write_text('interface:\n default_prompt: 123\n') + self.assertTrue(any('default_prompt' in e for e in validate(self.root))) From e7818b30b254f2554fc0289be8dc7670809c5f23 Mon Sep 17 00:00:00 2001 From: mrKazzila Date: Tue, 22 Sep 2026 15:53:59 +0300 Subject: [PATCH 02/12] feat: add FastAPI logging demo generator and evaluator --- evals/demo/README.md | 58 ++++++++ evals/demo/backends/stdlib.py | 41 ++++++ evals/demo/backends/structlog.py | 37 +++++ evals/demo/grading.py | 104 ++++++++++++++ evals/demo/reference/safe_output.py | 12 ++ evals/demo/reference/service.py | 8 ++ evals/demo/reference/stdlib.py | 41 ++++++ evals/demo/reference/structlog.py | 38 +++++ evals/demo/requirements-stdlib.in | 3 + evals/demo/requirements-stdlib.txt | 45 ++++++ evals/demo/requirements-structlog.in | 2 + evals/demo/requirements-structlog.txt | 47 ++++++ evals/demo/runner.py | 100 +++++++++++++ evals/demo/template/.gitignore | 3 + evals/demo/template/PROMPT.md | 11 ++ evals/demo/template/README.md | 34 +++++ evals/demo/template/app/__init__.py | 1 + evals/demo/template/app/main.py | 36 +++++ evals/demo/template/app/middleware.py | 33 +++++ evals/demo/template/app/provider.py | 13 ++ evals/demo/template/app/service.py | 13 ++ evals/demo/template/tests/test_contract.py | 23 +++ scripts/demo.py | 107 ++++++++++++++ tests/demo/test_demo.py | 159 +++++++++++++++++++++ 24 files changed, 969 insertions(+) create mode 100644 evals/demo/README.md create mode 100644 evals/demo/backends/stdlib.py create mode 100644 evals/demo/backends/structlog.py create mode 100644 evals/demo/grading.py create mode 100644 evals/demo/reference/safe_output.py create mode 100644 evals/demo/reference/service.py create mode 100644 evals/demo/reference/stdlib.py create mode 100644 evals/demo/reference/structlog.py create mode 100644 evals/demo/requirements-stdlib.in create mode 100644 evals/demo/requirements-stdlib.txt create mode 100644 evals/demo/requirements-structlog.in create mode 100644 evals/demo/requirements-structlog.txt create mode 100644 evals/demo/runner.py create mode 100644 evals/demo/template/.gitignore create mode 100644 evals/demo/template/PROMPT.md create mode 100644 evals/demo/template/README.md create mode 100644 evals/demo/template/app/__init__.py create mode 100644 evals/demo/template/app/main.py create mode 100644 evals/demo/template/app/middleware.py create mode 100644 evals/demo/template/app/provider.py create mode 100644 evals/demo/template/app/service.py create mode 100644 evals/demo/template/tests/test_contract.py create mode 100644 scripts/demo.py create mode 100644 tests/demo/test_demo.py diff --git a/evals/demo/README.md b/evals/demo/README.md new file mode 100644 index 0000000..949d270 --- /dev/null +++ b/evals/demo/README.md @@ -0,0 +1,58 @@ +# FastAPI logging demo evaluation + +Generate disposable projects for manual agent trials in either stdlib logging or structlog. Business code is shared; only the logging backend and pinned dependencies differ. The templates intentionally contain logging defects. They are not deployment examples and are not bundled with the installed skill. + +## One trial + +From this repository: + +```sh +python3 scripts/demo.py create --stack stdlib --dest /tmp/logging-demo-stdlib +python3 -m venv /tmp/logging-demo-stdlib/.venv +/tmp/logging-demo-stdlib/.venv/bin/python -m pip install -r /tmp/logging-demo-stdlib/requirements.txt +(cd /tmp/logging-demo-stdlib && .venv/bin/python -m unittest discover -s tests -v) +``` + +From this repository, evaluate: + +```sh +python3 scripts/demo.py check --project /tmp/logging-demo-stdlib --report /tmp/stdlib-before.json +# Run the agent manually in /tmp/logging-demo-stdlib using PROMPT.md. +python3 scripts/demo.py check --project /tmp/logging-demo-stdlib --report /tmp/stdlib-after.json +``` + +Repeat with `--stack structlog` and a different project/report path. The initial check is expected to exit 1: the HTTP contract works, but logging defects are present. An improved project should exit 0. Exit 2 means a setup/probe error, not a failed logging criterion. Reports are created exclusively and are never overwritten; choose a new filename for each run. Setup errors are recorded with `passed: null` when a report can be created. + +`check` executes the generated application's code in a subprocess using its `.venv`, with a 60-second timeout. It does not install dependencies or edit application files. This is process isolation, not an operating-system security sandbox. Both output streams are captured, and only synthetic credentials are used. + +## What is measured + +The report includes dependency/Python versions, HTTP observations, rendered logs, backend call counts, and a pass/fail result with evidence for each criterion: + +- HTTP responses and request ID response headers. +- Provider return values and original exception type/message, checked directly so changing business exceptions cannot substitute for safe log rendering. +- JSON output, stable event names, existing event contracts, and emitted structured fields. +- Exactly one error record per failed order with traceback and error type. +- No synthetic secrets anywhere in stdout or stderr, including exception rendering. +- Correct correlation for overlapping requests and cleanup after successful, invalid, and failed requests. +- Runtime use of the selected logging backend. This probe observes Python logging/structlog emission calls; it is not a general proof against adversarial code or dependency migration. + +Probe events are emitted outside the request in the same coroutine, so task teardown cannot mask missing cleanup. Concurrency is deterministic: the provider yields control without using timing delays or external services. + +Compare `criteria` by `id` in the before/after JSON reports. Raw observations make failures inspectable. HTTP contract failures must not be traded for better logging scores. Do not claim agent activation from these checks: confirm skill loading separately in the agent trace. + +## Skill versus no skill + +Use two clean generated projects, the same model/client/dependencies, the same task text, and fresh sessions. Ensure the baseline client does not discover a globally installed skill or bundled plugin. The generator does not manage client configuration. Use the skill folder from this repository rather than an older installed copy. Keep evaluation sources and reference repairs out of the agent workspace; they are never copied by `create`. + +The external evaluator is held out by workspace separation, not by secrecy against a deliberately searching agent. The public README discloses behavioral contracts; graders test those contracts rather than a preferred implementation. Follow the trial-recording guidance in [the evaluation guide](../README.md) for repeated runs and model/skill version attribution. No agent benchmark results are claimed by the demo's CI. + +## Maintainer checks + +```sh +just demo-test +``` + +CI tests both dependency environments independently. Checks verify that original templates reproduce known failures, reference repairs pass every criterion, and individual regressions are detected. Reference files are test oracles and are not distributed to generated projects. The demo redactor handles synthetic credential markers only; it is not a production secret detection library. + +Dependencies are pinned in the two `requirements-*.txt` files. Their corresponding `.in` files specify direct requirements. Regenerate with `uv pip compile --python-version 3.12` after an intentional dependency update and rerun both variants. diff --git a/evals/demo/backends/stdlib.py b/evals/demo/backends/stdlib.py new file mode 100644 index 0000000..1cd6f33 --- /dev/null +++ b/evals/demo/backends/stdlib.py @@ -0,0 +1,41 @@ +import json +import logging +import sys + +_context = {} +logger = logging.getLogger('orders') + + +class JsonFormatter(logging.Formatter): + def format(self, record): + # This legacy formatter predates the application's structured fields. + result = {'event': record.getMessage(), 'level': record.levelname.lower()} + fields = getattr(record, 'fields', {}) + result.update({key: value for key, value in fields.items() if key not in ('order_id', 'amount_cents')}) + if record.exc_info: + result['exception'] = self.formatException(record.exc_info) + return json.dumps(result) + + +def configure(): + handler = logging.StreamHandler(sys.stderr) + handler.setFormatter(JsonFormatter()) + logger.handlers = [handler] + logger.setLevel(logging.INFO) + logger.propagate = False + + +def bind_request(request_id): + _context['request_id'] = request_id + + +def reset_request(token): + pass + + +def info(event, **fields): + logger.info(event, extra={'fields': {**_context, **fields}}) + + +def exception(event, **fields): + logger.exception(event, extra={'fields': {**_context, **fields}}) diff --git a/evals/demo/backends/structlog.py b/evals/demo/backends/structlog.py new file mode 100644 index 0000000..5b24c2d --- /dev/null +++ b/evals/demo/backends/structlog.py @@ -0,0 +1,37 @@ +import sys + +import structlog + +_context = {} +logger = structlog.get_logger('orders') + + +def legacy_fields(logger, method, event): + event.pop('order_id', None) + event.pop('amount_cents', None) + return event + + +def configure(): + structlog.configure( + processors=[structlog.processors.add_log_level, legacy_fields, + structlog.processors.format_exc_info, structlog.processors.JSONRenderer()], + logger_factory=structlog.PrintLoggerFactory(file=sys.stderr), + cache_logger_on_first_use=False, + ) + + +def bind_request(request_id): + _context['request_id'] = request_id + + +def reset_request(token): + pass + + +def info(event, **fields): + logger.info(event, **{**_context, **fields}) + + +def exception(event, **fields): + logger.exception(event, **{**_context, **fields}) diff --git a/evals/demo/grading.py b/evals/demo/grading.py new file mode 100644 index 0000000..95bd1e5 --- /dev/null +++ b/evals/demo/grading.py @@ -0,0 +1,104 @@ +"""Grade observable outcomes without prescribing a particular repair.""" + +import json + + +def grade(observations, stack): + criteria = [] + + def result(name, passed, evidence): + criteria.append({'id': name, 'passed': bool(passed), 'evidence': evidence}) + + records, malformed = [], [] + for stream in ('stdout', 'stderr'): + for line in observations[stream].splitlines(): + if not line.strip(): + continue + try: + record = json.loads(line) + if not isinstance(record, dict) or not isinstance(record.get('event'), str): + raise ValueError('expected JSON object with string event') + records.append(record) + except (ValueError, TypeError): + malformed.append(line) + result('json_output', bool(records) and not malformed, + {'records': len(records), 'malformed_lines': malformed}) + + responses = observations['responses'] + labels = {'health', 'success', 'failure', 'invalid', 'parallel_success', 'parallel_failure'} + business_errors = [] + for response in responses: + label = response['label'] + expected_status = 200 if label == 'health' else 422 if label == 'invalid' else 503 if response['mode'] == 'timeout' else 201 + expected_body = ({'status': 'ok'} if label == 'health' else + {'detail': 'provider unavailable'} if expected_status == 503 else + {'order_id': response['order_id'], 'status': 'created'}) + if response['status'] != expected_status or (expected_status != 422 and response['body'] != expected_body): + business_errors.append(response) + if not response['request_id'] or (response['expected_request_id'] and response['request_id'] != response['expected_request_id']): + business_errors.append(response) + result('http_contract', len(responses) == len(labels) and {r['label'] for r in responses} == labels and not business_errors, + business_errors or responses) + provider = observations['provider'] + result('provider_behavior', provider == { + 'success': {'order_id': 'direct', 'status': 'created'}, + 'failure': {'type': 'ProviderTimeout', + 'message': 'provider timed out; credential=TEST_SECRET_PAYMENT'}, + }, provider) + + successful = [r for r in responses if r['label'] in ('success', 'parallel_success')] + failed = [r for r in responses if r['label'] in ('failure', 'parallel_failure')] + created = [r for r in records if r['event'] == 'order.created'] + failures = [r for r in records if r['event'] == 'order.failed'] + completed = [r for r in records if r['event'] == 'request.completed'] + result('event_contracts', len(created) == 2 and len(failures) >= 2 and len(completed) == 6, + {'order.created': len(created), 'order.failed': len(failures), 'request.completed': len(completed)}) + variable_names = [r['event'] for r in records if any( + value and value in r['event'] for response in responses + for value in (response['order_id'], response['request_id']))] + result('stable_events', not variable_names, {'variable_events': variable_names}) + + field_errors = [] + for response in successful: + matches = [r for r in created if r.get('order_id') == response['order_id']] + if len(matches) != 1 or matches[0].get('amount_cents') != response['amount_cents']: + field_errors.append(response['label']) + for response in failed: + if not any(r.get('order_id') == response['order_id'] and r.get('retryable') is True for r in failures): + field_errors.append(response['label']) + result('structured_fields', not field_errors, {'missing_or_wrong_fields': field_errors}) + + # Count all ERROR/CRITICAL records, not only the contracted event name. + error_records = [r for r in records if str(r.get('level', r.get('log_level', r.get('levelname', '')))).lower() in ('error', 'critical')] + ownership_errors = [] + for response in failed: + matches = [r for r in error_records if r.get('order_id') == response['order_id']] + if len(matches) != 1 or matches[0]['event'] != 'order.failed': + ownership_errors.append(response['label']) + elif 'ProviderTimeout' not in json.dumps(matches[0]) or 'Traceback' not in json.dumps(matches[0]): + ownership_errors.append(response['label']) + result('single_failure_traceback', len(error_records) == 2 and not ownership_errors, + {'error_records': len(error_records), 'invalid_failures': ownership_errors}) + + raw = observations['stdout'] + observations['stderr'] + markers = [marker for marker in ('TEST_SECRET_HEADER', 'TEST_SECRET_PAYMENT', 'TEST_SECRET_DEFAULT') if marker in raw] + result('no_secrets', not markers, {'leaked_markers': markers}) + + correlation_errors = [] + for response in responses: + matches = [r for r in completed if r.get('request_id') == response['request_id']] + if len(matches) != 1 or matches[0].get('status_code') != response['status']: + correlation_errors.append(response['label']) + if response in successful + failed: + event = 'order.created' if response in successful else 'order.failed' + matches = [r for r in records if r['event'] == event and r.get('order_id') == response['order_id']] + if not matches or any(r.get('request_id') != response['request_id'] for r in matches): + correlation_errors.append(response['label']) + result('request_isolation', not correlation_errors, {'wrong_request_context': correlation_errors}) + probes = [r for r in records if r['event'] == 'demo.probe'] + result('context_cleanup', len(probes) == 6 and {r.get('probe_id') for r in probes} == labels and + all(r.get('request_id') is None for r in probes), {'probes': probes}) + usage = observations['backend_calls'] + preserved = usage[stack] > 0 and (stack != 'stdlib' or usage['structlog'] == 0) + result('original_stack', preserved, usage) + return criteria diff --git a/evals/demo/reference/safe_output.py b/evals/demo/reference/safe_output.py new file mode 100644 index 0000000..64dd5f8 --- /dev/null +++ b/evals/demo/reference/safe_output.py @@ -0,0 +1,12 @@ +import re + + +def sanitize(value): + """Demo redaction after exception rendering; not a general secret detector.""" + if isinstance(value, dict): + return {key: sanitize(item) for key, item in value.items()} + if isinstance(value, list): + return [sanitize(item) for item in value] + if isinstance(value, str): + return re.sub(r'TEST_SECRET_[A-Z0-9_]+', '[REDACTED]', value) + return value diff --git a/evals/demo/reference/service.py b/evals/demo/reference/service.py new file mode 100644 index 0000000..8cfa55e --- /dev/null +++ b/evals/demo/reference/service.py @@ -0,0 +1,8 @@ +from . import observability as log +from .provider import charge + + +async def create_order(order): + result = await charge(order) + log.info('order.created', order_id=order.order_id, amount_cents=order.amount_cents) + return result diff --git a/evals/demo/reference/stdlib.py b/evals/demo/reference/stdlib.py new file mode 100644 index 0000000..43b44bf --- /dev/null +++ b/evals/demo/reference/stdlib.py @@ -0,0 +1,41 @@ +import json +import logging +import sys +from contextvars import ContextVar + +from .safe_output import sanitize + +_context = ContextVar('request_context', default={}) +logger = logging.getLogger('orders') + + +class JsonFormatter(logging.Formatter): + def format(self, record): + result = {'event': record.getMessage(), 'level': record.levelname.lower(), **getattr(record, 'fields', {})} + if record.exc_info: + result['exception'] = self.formatException(record.exc_info) + return json.dumps(sanitize(result)) + + +def configure(): + handler = logging.StreamHandler(sys.stderr) + handler.setFormatter(JsonFormatter()) + logger.handlers = [handler] + logger.setLevel(logging.INFO) + logger.propagate = False + + +def bind_request(request_id): + return _context.set({'request_id': request_id}) + + +def reset_request(token): + _context.reset(token) + + +def info(event, **fields): + logger.info(event, extra={'fields': {**_context.get(), **fields}}) + + +def exception(event, **fields): + logger.exception(event, extra={'fields': {**_context.get(), **fields}}) diff --git a/evals/demo/reference/structlog.py b/evals/demo/reference/structlog.py new file mode 100644 index 0000000..04d7c09 --- /dev/null +++ b/evals/demo/reference/structlog.py @@ -0,0 +1,38 @@ +import sys +from contextvars import ContextVar + +import structlog + +from .safe_output import sanitize + +_context = ContextVar('request_context', default={}) +logger = structlog.get_logger('orders') + + +def safe_fields(logger, method, event): + return sanitize(event) + + +def configure(): + structlog.configure( + processors=[structlog.processors.add_log_level, structlog.processors.format_exc_info, + safe_fields, structlog.processors.JSONRenderer()], + logger_factory=structlog.PrintLoggerFactory(file=sys.stderr), + cache_logger_on_first_use=False, + ) + + +def bind_request(request_id): + return _context.set({'request_id': request_id}) + + +def reset_request(token): + _context.reset(token) + + +def info(event, **fields): + logger.info(event, **{**_context.get(), **fields}) + + +def exception(event, **fields): + logger.exception(event, **{**_context.get(), **fields}) diff --git a/evals/demo/requirements-stdlib.in b/evals/demo/requirements-stdlib.in new file mode 100644 index 0000000..e02b3c4 --- /dev/null +++ b/evals/demo/requirements-stdlib.in @@ -0,0 +1,3 @@ +fastapi==0.115.12 +httpx==0.28.1 +uvicorn==0.34.2 diff --git a/evals/demo/requirements-stdlib.txt b/evals/demo/requirements-stdlib.txt new file mode 100644 index 0000000..eb557c8 --- /dev/null +++ b/evals/demo/requirements-stdlib.txt @@ -0,0 +1,45 @@ +# This file was autogenerated by uv via the following command: +# uv pip compile evals/demo/requirements-stdlib.in --python-version 3.12 --output-file evals/demo/requirements-stdlib.txt +annotated-types==0.8.0 + # via pydantic +anyio==4.15.1 + # via + # httpx + # starlette +certifi==2026.7.22 + # via + # httpcore + # httpx +click==8.5.0 + # via uvicorn +fastapi==0.115.12 + # via -r evals/demo/requirements-stdlib.in +h11==0.16.0 + # via + # httpcore + # uvicorn +httpcore==1.0.9 + # via httpx +httpx==0.28.1 + # via -r evals/demo/requirements-stdlib.in +idna==3.20 + # via + # anyio + # httpx +pydantic==2.13.5 + # via fastapi +pydantic-core==2.46.5 + # via pydantic +starlette==0.46.2 + # via fastapi +typing-extensions==4.16.0 + # via + # anyio + # fastapi + # pydantic + # pydantic-core + # typing-inspection +typing-inspection==0.4.4 + # via pydantic +uvicorn==0.34.2 + # via -r evals/demo/requirements-stdlib.in diff --git a/evals/demo/requirements-structlog.in b/evals/demo/requirements-structlog.in new file mode 100644 index 0000000..773d24f --- /dev/null +++ b/evals/demo/requirements-structlog.in @@ -0,0 +1,2 @@ +-r requirements-stdlib.in +structlog==25.1.0 diff --git a/evals/demo/requirements-structlog.txt b/evals/demo/requirements-structlog.txt new file mode 100644 index 0000000..1de3313 --- /dev/null +++ b/evals/demo/requirements-structlog.txt @@ -0,0 +1,47 @@ +# This file was autogenerated by uv via the following command: +# uv pip compile evals/demo/requirements-structlog.in --python-version 3.12 --output-file evals/demo/requirements-structlog.txt +annotated-types==0.8.0 + # via pydantic +anyio==4.15.1 + # via + # httpx + # starlette +certifi==2026.7.22 + # via + # httpcore + # httpx +click==8.5.0 + # via uvicorn +fastapi==0.115.12 + # via -r evals/demo/requirements-stdlib.in +h11==0.16.0 + # via + # httpcore + # uvicorn +httpcore==1.0.9 + # via httpx +httpx==0.28.1 + # via -r evals/demo/requirements-stdlib.in +idna==3.20 + # via + # anyio + # httpx +pydantic==2.13.5 + # via fastapi +pydantic-core==2.46.5 + # via pydantic +starlette==0.46.2 + # via fastapi +structlog==25.1.0 + # via -r evals/demo/requirements-structlog.in +typing-extensions==4.16.0 + # via + # anyio + # fastapi + # pydantic + # pydantic-core + # typing-inspection +typing-inspection==0.4.4 + # via pydantic +uvicorn==0.34.2 + # via -r evals/demo/requirements-stdlib.in diff --git a/evals/demo/runner.py b/evals/demo/runner.py new file mode 100644 index 0000000..5c65a8c --- /dev/null +++ b/evals/demo/runner.py @@ -0,0 +1,100 @@ +"""External subprocess probe. Never copied into the agent's demo project.""" + +import asyncio +import contextlib +import importlib.metadata +import io +import json +import platform +import sys +import traceback +from pathlib import Path +from types import SimpleNamespace + + +def run(project): + sys.path.insert(0, str(project)) + stdout, stderr = io.StringIO(), io.StringIO() + usage = {'stdlib': 0, 'structlog': 0} + responses = [] + + def profile(frame, event, arg): + if event != 'call': + return + filename = frame.f_code.co_filename.replace('\\', '/') + name = frame.f_code.co_name + if filename.endswith('/logging/__init__.py') and name == '_log': + usage['stdlib'] += 1 + if '/structlog/' in filename and name == '_proxy_to_logger': + usage['structlog'] += 1 + + with contextlib.redirect_stdout(stdout), contextlib.redirect_stderr(stderr): + from httpx import ASGITransport, AsyncClient + from app.main import app + from app import observability as log + from app.provider import charge + + async def exercise(): + async with AsyncClient(transport=ASGITransport(app=app), base_url='http://demo') as client: + async def request(label, path, *, order_id=None, mode='success', request_id=None, amount=100): + headers = {'Authorization': 'Bearer TEST_SECRET_HEADER'} + if request_id: + headers['X-Request-ID'] = request_id + if order_id: + response = await client.post(path, headers=headers, json={ + 'order_id': order_id, 'amount_cents': amount, + 'provider_mode': mode, 'payment_token': 'TEST_SECRET_PAYMENT', + }) + else: + response = await client.get(path, headers=headers) + responses.append({ + 'label': label, 'status': response.status_code, 'body': response.json(), + 'request_id': response.headers.get('x-request-id'), + 'expected_request_id': request_id, 'order_id': order_id, + 'amount_cents': amount, 'mode': mode, + }) + # Same coroutine as the ASGI request: detects leaked context that + # a separate task/client wrapper could inadvertently conceal. + log.info('demo.probe', probe_id=label) + + await request('health', '/health') + await request('success', '/orders', order_id='order-alpha', request_id='req-alpha') + await request('failure', '/orders', order_id='order-beta', mode='timeout', request_id='req-beta') + await request('invalid', '/orders', order_id='order-invalid', amount=-1, request_id='req-invalid') + await asyncio.gather( + request('parallel_success', '/orders', order_id='order-parallel-a', request_id='req-parallel-a'), + request('parallel_failure', '/orders', order_id='order-parallel-b', mode='timeout', request_id='req-parallel-b'), + ) + provider_success = await charge(SimpleNamespace( + order_id='direct', amount_cents=100, provider_mode='success', + payment_token='TEST_SECRET_PAYMENT')) + try: + await charge(SimpleNamespace(order_id='direct', amount_cents=100, + provider_mode='timeout', payment_token='TEST_SECRET_PAYMENT')) + except Exception as exc: + provider_failure = {'type': type(exc).__name__, 'message': str(exc)} + else: + provider_failure = None + return {'success': provider_success, 'failure': provider_failure} + + sys.setprofile(profile) + try: + provider = asyncio.run(exercise()) + finally: + sys.setprofile(None) + versions = {'python': platform.python_version()} + for package in ('fastapi', 'starlette', 'pydantic', 'httpx', 'structlog', 'uvicorn'): + try: + versions[package] = importlib.metadata.version(package) + except importlib.metadata.PackageNotFoundError: + versions[package] = None + return {'responses': responses, 'stdout': stdout.getvalue(), 'stderr': stderr.getvalue(), + 'backend_calls': usage, 'versions': versions, 'provider': provider} + + +if __name__ == '__main__': + try: + print(json.dumps({'observations': run(Path(sys.argv[1]).resolve())})) + except Exception: + print(json.dumps({'error': traceback.format_exc()})) + raise SystemExit(2) diff --git a/evals/demo/template/.gitignore b/evals/demo/template/.gitignore new file mode 100644 index 0000000..f0ccc32 --- /dev/null +++ b/evals/demo/template/.gitignore @@ -0,0 +1,3 @@ +.venv/ +__pycache__/ +*.py[cod] diff --git a/evals/demo/template/PROMPT.md b/evals/demo/template/PROMPT.md new file mode 100644 index 0000000..61dfcca --- /dev/null +++ b/evals/demo/template/PROMPT.md @@ -0,0 +1,11 @@ +Improve logging in this FastAPI order API. Inspect the existing stack and README contracts first. Preserve the HTTP behavior, provider exception behavior, public logging facade, and existing event names consumed by alerts. Keep the current logging stack. + +Make the rendered logs structured and useful, remove duplicate failure records, protect credentials including those in exception text, and ensure request context remains correct during overlapping requests and is cleaned up afterward. Use synthetic data only. Run the business tests and add focused checks of the actual output. Explain the changes and verification performed. + +Do not change the demo manifest, dependency pins, or existing contract tests. You may add tests. Work only in this demo project. + +For an explicit skill-enabled trial, prepend this sentence to the task above: + +Use $python-structured-logging for this task. + +For implicit activation trials, send only the task above, without that sentence. Use your client's invocation syntax if it differs from Codex's `$` syntax. diff --git a/evals/demo/template/README.md b/evals/demo/template/README.md new file mode 100644 index 0000000..cd4df91 --- /dev/null +++ b/evals/demo/template/README.md @@ -0,0 +1,34 @@ +# Order API logging demo + +This is an intentionally flawed local training application. Improve its logging while keeping the HTTP behavior and existing logging stack. All credentials are synthetic. There are no external provider calls or database dependencies. + +## Setup and run + +Requires Python 3.12+: + +```sh +python3 -m venv .venv +.venv/bin/python -m pip install -r requirements.txt +.venv/bin/python -m unittest discover -s tests -v +.venv/bin/python -m uvicorn app.main:app --host 127.0.0.1 --port 8000 +``` + +On Windows use `.venv\Scripts\python.exe`. The server is optional: contract and external evaluation tests use an in-process ASGI transport. Interactive API documentation is at `http://127.0.0.1:8000/docs`. + +## Existing contracts + +- `GET /health`: 200, `{"status":"ok"}`. +- `POST /orders`: body with nonempty `order_id`, positive integer `amount_cents`, optional `provider_mode` (`success` by default or `timeout`), and optional synthetic `payment_token`. +- Success: 201, `{"order_id":"","status":"created"}`. Provider timeout: 503, `{"detail":"provider unavailable"}`. Invalid input: 422. +- Each response returns `X-Request-ID`: preserve a supplied value or generate one if absent. +- Consumers rely on `order.created`, `order.failed`, and `request.completed`. Preserve these names. The success event needs `order_id` and `amount_cents`; the failure event needs `order_id`, `retryable=true` (the simulated timeout is transient), error diagnostics, and traceback. Request completion needs `status_code` and request correlation. +- Emit JSON logs with `event` and `level`, including `request_id` for request-scoped records. Context must not cross requests or remain after a request completes. The logging facade `app.observability` is also used outside requests. +- Keep the facade's `configure`, `bind_request`, `reset_request`, `info`, and `exception` entrypoints, and the importable `app.main.app`. Their implementations may change. +- Keep `app.provider.charge(order)` callable with an object exposing the documented order fields. Its success result and `ProviderTimeout` exception type/message are business contracts, checked independently from log output. +- Preserve provider behavior, HTTP results, and the selected logging stack. Never log synthetic credentials from bodies, headers, or exception messages. Fix sanitization in the logging pipeline without altering the provider exception. + +The public tests cover business behavior only and already pass in the original project. An external evaluator checks logging after you finish. Do not modify `demo.json`, dependency pins, or public contract tests to make evaluation pass. Add your own tests as needed. + +## Task for the agent + +Use the text in `PROMPT.md` in a fresh agent session rooted in this directory. For a skill-enabled run, make the repository's logging skill available in your client. For a baseline, use a clean client configuration without that skill or a plugin that bundles it. Generating this project does not install or disable any skills. diff --git a/evals/demo/template/app/__init__.py b/evals/demo/template/app/__init__.py new file mode 100644 index 0000000..2d9c2a0 --- /dev/null +++ b/evals/demo/template/app/__init__.py @@ -0,0 +1 @@ +"""Local order API demonstration.""" diff --git a/evals/demo/template/app/main.py b/evals/demo/template/app/main.py new file mode 100644 index 0000000..4a7fc70 --- /dev/null +++ b/evals/demo/template/app/main.py @@ -0,0 +1,36 @@ +from typing import Literal + +from fastapi import FastAPI +from fastapi.responses import JSONResponse +from pydantic import BaseModel, Field + +from . import observability as log +from .middleware import RequestContextMiddleware +from .provider import ProviderTimeout +from .service import create_order + + +class Order(BaseModel): + order_id: str = Field(min_length=1) + amount_cents: int = Field(gt=0) + provider_mode: Literal['success', 'timeout'] = 'success' + payment_token: str = 'TEST_SECRET_DEFAULT' + + +log.configure() +app = FastAPI(title='Logging skill demo: orders') +app.add_middleware(RequestContextMiddleware) + + +@app.get('/health') +async def health(): + return {'status': 'ok'} + + +@app.post('/orders', status_code=201) +async def orders(order: Order): + try: + return await create_order(order) + except ProviderTimeout: + log.exception('order.failed', order_id=order.order_id, retryable=True) + return JSONResponse(status_code=503, content={'detail': 'provider unavailable'}) diff --git a/evals/demo/template/app/middleware.py b/evals/demo/template/app/middleware.py new file mode 100644 index 0000000..4fdf342 --- /dev/null +++ b/evals/demo/template/app/middleware.py @@ -0,0 +1,33 @@ +from uuid import uuid4 + +from . import observability as log + + +class RequestContextMiddleware: + def __init__(self, app): + self.app = app + + async def __call__(self, scope, receive, send): + if scope['type'] != 'http': + return await self.app(scope, receive, send) + headers = dict(scope['headers']) + request_id = headers.get(b'x-request-id', b'').decode() or str(uuid4()) + token = log.bind_request(request_id) + status = 500 + log.info('request.received', authorization=headers.get(b'authorization', b'').decode()) + + async def send_response(message): + nonlocal status + if message['type'] == 'http.response.start': + status = message['status'] + message = {**message, 'headers': [ + *message.get('headers', []), + (b'x-request-id', request_id.encode()), + ]} + await send(message) + + try: + await self.app(scope, receive, send_response) + finally: + log.info('request.completed', status_code=status, path=scope['path']) + log.reset_request(token) diff --git a/evals/demo/template/app/provider.py b/evals/demo/template/app/provider.py new file mode 100644 index 0000000..d76cc2f --- /dev/null +++ b/evals/demo/template/app/provider.py @@ -0,0 +1,13 @@ +import asyncio + + +class ProviderTimeout(RuntimeError): + pass + + +async def charge(order): + # Always yield so concurrent HTTP requests overlap without timing guesses. + await asyncio.sleep(0) + if order.provider_mode == 'timeout': + raise ProviderTimeout(f'provider timed out; credential={order.payment_token}') + return {'order_id': order.order_id, 'status': 'created'} diff --git a/evals/demo/template/app/service.py b/evals/demo/template/app/service.py new file mode 100644 index 0000000..55a6c2a --- /dev/null +++ b/evals/demo/template/app/service.py @@ -0,0 +1,13 @@ +from . import observability as log +from .provider import ProviderTimeout, charge + + +async def create_order(order): + log.info(f'order_{order.order_id}_accepted', payload=order.model_dump()) + try: + result = await charge(order) + except ProviderTimeout: + log.exception('order.failed', order_id=order.order_id, retryable=True) + raise + log.info('order.created', order_id=order.order_id, amount_cents=order.amount_cents) + return result diff --git a/evals/demo/template/tests/test_contract.py b/evals/demo/template/tests/test_contract.py new file mode 100644 index 0000000..6273e1d --- /dev/null +++ b/evals/demo/template/tests/test_contract.py @@ -0,0 +1,23 @@ +import unittest + +from httpx import ASGITransport, AsyncClient + +from app.main import app + + +class ContractTests(unittest.IsolatedAsyncioTestCase): + async def test_http_contract(self): + async with AsyncClient(transport=ASGITransport(app=app), base_url='http://demo') as client: + response = await client.get('/health') + self.assertEqual(response.status_code, 200) + self.assertEqual(response.json(), {'status': 'ok'}) + self.assertTrue(response.headers['x-request-id']) + response = await client.post('/orders', json={'order_id': 'one', 'amount_cents': 100}, headers={'X-Request-ID': 'request-one'}) + self.assertEqual(response.status_code, 201) + self.assertEqual(response.json(), {'order_id': 'one', 'status': 'created'}) + self.assertEqual(response.headers['x-request-id'], 'request-one') + response = await client.post('/orders', json={'order_id': 'two', 'amount_cents': 100, 'provider_mode': 'timeout'}) + self.assertEqual(response.status_code, 503) + self.assertEqual(response.json(), {'detail': 'provider unavailable'}) + response = await client.post('/orders', json={'order_id': 'three', 'amount_cents': -1}) + self.assertEqual(response.status_code, 422) diff --git a/scripts/demo.py b/scripts/demo.py new file mode 100644 index 0000000..5820ec0 --- /dev/null +++ b/scripts/demo.py @@ -0,0 +1,107 @@ +#!/usr/bin/env python3 +"""Generate an isolated logging demo or check one without installing dependencies.""" + +from __future__ import annotations + +import argparse +import importlib.util +import json +import os +import shutil +import subprocess +import sys +import tempfile +from datetime import datetime, timezone +from pathlib import Path + +ROOT = Path(__file__).resolve().parents[1] +DEMO = ROOT / 'evals/demo' + + +def create(stack: str, destination: Path) -> None: + destination = destination.absolute() + if destination.exists() or destination.is_symlink(): + raise ValueError(f'Destination already exists: {destination}') + destination.parent.mkdir(parents=True, exist_ok=True) + # Prepare the complete project before publishing it to the chosen destination. + with tempfile.TemporaryDirectory(prefix='.logging-demo-', dir=destination.parent) as temporary: + prepared = Path(temporary) / 'project' + shutil.copytree(DEMO / 'template', prepared, ignore=shutil.ignore_patterns('__pycache__', '*.pyc')) + shutil.copyfile(DEMO / 'backends' / f'{stack}.py', prepared / 'app/observability.py') + shutil.copyfile(DEMO / f'requirements-{stack}.txt', prepared / 'requirements.txt') + (prepared / 'demo.json').write_text(json.dumps({'schema_version': 1, 'stack': stack}, indent=2) + '\n') + destination.mkdir() # Exclusive reservation: never replace a competing create. + for source in prepared.iterdir(): + shutil.move(str(source), destination / source.name) + print(f'Created {stack} demo: {destination}') + + +def check(project: Path) -> dict: + project = project.resolve() + manifest = json.loads((project / 'demo.json').read_text()) + stack = manifest.get('stack') + if manifest.get('schema_version') != 1 or stack not in ('stdlib', 'structlog'): + raise ValueError('Unsupported demo manifest') + python = project / '.venv' / ('Scripts/python.exe' if os.name == 'nt' else 'bin/python') + if not python.is_file(): + raise ValueError(f'Missing virtual environment: {python}. Follow the generated README.') + environment = {key: value for key, value in os.environ.items() if key not in ('PYTHONPATH', 'PYTHONHOME')} + environment['PYTHONDONTWRITEBYTECODE'] = '1' + execution = subprocess.run( + [str(python), '-I', '-B', str(DEMO / 'runner.py'), str(project)], + cwd=project, env=environment, capture_output=True, text=True, timeout=60, + ) + try: + payload = json.loads(execution.stdout) + except ValueError as exc: + raise ValueError(f'Probe did not return JSON (exit {execution.returncode}): {execution.stderr[-4000:]}') from exc + if execution.returncode or 'error' in payload: + raise ValueError(payload.get('error', execution.stderr or 'Probe failed')) + spec = importlib.util.spec_from_file_location('demo_grading', DEMO / 'grading.py') + grading = importlib.util.module_from_spec(spec) + spec.loader.exec_module(grading) + observed = payload['observations'] + criteria = grading.grade(observed, stack) + return {'schema_version': 1, 'project': str(project), 'stack': stack, + 'checked_at': datetime.now(timezone.utc).isoformat(), 'versions': observed['versions'], + 'passed': all(item['passed'] for item in criteria), 'criteria': criteria, + 'observations': observed} + + +def main(argv=None) -> int: + parser = argparse.ArgumentParser(description=__doc__) + commands = parser.add_subparsers(dest='command', required=True) + generate = commands.add_parser('create') + generate.add_argument('--stack', choices=('stdlib', 'structlog'), required=True) + generate.add_argument('--dest', type=Path, required=True) + verify = commands.add_parser('check') + verify.add_argument('--project', type=Path, required=True) + verify.add_argument('--report', type=Path, required=True) + args = parser.parse_args(argv) + try: + if args.command == 'create': + create(args.stack, args.dest) + return 0 + # Reserve output exclusively before executing project code. + with args.report.open('x', encoding='utf-8') as output: + try: + report = check(args.project) + status = 0 if report['passed'] else 1 + except (OSError, ValueError, KeyError, TypeError, subprocess.TimeoutExpired) as exc: + report = {'schema_version': 1, 'passed': None, 'error': str(exc)} + status = 2 + json.dump(report, output, indent=2) + output.write('\n') + for criterion in report.get('criteria', []): + print(f"{'PASS' if criterion['passed'] else 'FAIL'} {criterion['id']}") + if 'error' in report: + print(report['error'], file=sys.stderr) + print(f'Report: {args.report}') + return status + except (OSError, ValueError) as exc: + print(str(exc), file=sys.stderr) + return 2 + + +if __name__ == '__main__': + raise SystemExit(main()) diff --git a/tests/demo/test_demo.py b/tests/demo/test_demo.py new file mode 100644 index 0000000..9906eae --- /dev/null +++ b/tests/demo/test_demo.py @@ -0,0 +1,159 @@ +import contextlib +import copy +import importlib.util +import io +import json +import os +import shutil +import subprocess +import sys +import tempfile +import unittest +from pathlib import Path +from unittest.mock import patch + +ROOT = Path(__file__).resolve().parents[2] +sys.path.insert(0, str(ROOT)) +from scripts import demo + +STACKS = [os.environ['DEMO_TEST_STACK']] if os.environ.get('DEMO_TEST_STACK') else ['stdlib', 'structlog'] + + +def repair(project, stack): + reference = demo.DEMO / 'reference' + shutil.copyfile(reference / f'{stack}.py', project / 'app/observability.py') + for filename in ('service.py', 'safe_output.py'): + shutil.copyfile(reference / filename, project / 'app' / filename) + middleware = project / 'app/middleware.py' + middleware.write_text(middleware.read_text().replace( + "log.info('request.received', authorization=headers.get(b'authorization', b'').decode())", + "log.info('request.received')", + )) + + +class DemoTests(unittest.TestCase): + def setUp(self): + self.temporary = tempfile.TemporaryDirectory() + self.addCleanup(self.temporary.cleanup) + self.root = Path(self.temporary.name) + + def project(self, stack, fixed=False): + project = self.root / stack + with contextlib.redirect_stdout(io.StringIO()): + demo.create(stack, project) + # Tests reuse the pinned test environment, never install from the checker. + (project / '.venv').symlink_to(Path(sys.prefix), target_is_directory=True) + if fixed: + repair(project, stack) + return project + + def test_originals_have_working_api_and_reproducible_logging_defects(self): + expected_failures = {'stable_events', 'structured_fields', 'single_failure_traceback', + 'no_secrets', 'request_isolation', 'context_cleanup'} + for stack in STACKS: + with self.subTest(stack=stack): + project = self.project(stack) + result = demo.check(project) + criteria = {c['id']: c['passed'] for c in result['criteria']} + self.assertTrue(criteria['http_contract']) + self.assertTrue(criteria['original_stack']) + self.assertTrue(criteria['json_output']) + self.assertTrue(criteria['event_contracts']) + self.assertEqual({name for name, passed in criteria.items() if not passed}, expected_failures) + business = subprocess.run( + [sys.executable, '-m', 'unittest', 'discover', '-s', 'tests', '-v'], + cwd=project, capture_output=True, text=True, timeout=30, + ) + self.assertEqual(business.returncode, 0, business.stderr) + + def test_reference_repairs_pass_every_criterion(self): + for stack in STACKS: + with self.subTest(stack=stack): + report = demo.check(self.project(stack, fixed=True)) + self.assertTrue(report['passed'], report['criteria']) + self.assertTrue(report['versions']['fastapi']) + + def test_each_regression_is_detected_in_rendered_observations(self): + spec = importlib.util.spec_from_file_location('grading_test', demo.DEMO / 'grading.py') + grading = importlib.util.module_from_spec(spec) + spec.loader.exec_module(grading) + for stack in STACKS: + with self.subTest(stack=stack): + original = demo.check(self.project(stack, fixed=True))['observations'] + records = [json.loads(line) for line in original['stderr'].splitlines()] + + def assert_fails(criterion, mutate): + observed = copy.deepcopy(original) + changed = copy.deepcopy(records) + mutate(changed, observed) + observed['stderr'] = '\n'.join(json.dumps(r) for r in changed) + results = {c['id']: c['passed'] for c in grading.grade(observed, stack)} + self.assertFalse(results[criterion], criterion) + + assert_fails('structured_fields', lambda rows, obs: [r.pop('amount_cents', None) for r in rows]) + assert_fails('stable_events', lambda rows, obs: rows.append({'event': 'order_order-alpha_accepted'})) + assert_fails('single_failure_traceback', lambda rows, obs: rows.append(copy.deepcopy(next(r for r in rows if r['event'] == 'order.failed')))) + assert_fails('single_failure_traceback', lambda rows, obs: [r.pop('exception', None) for r in rows]) + assert_fails('no_secrets', lambda rows, obs: next(r for r in rows if r['event'] == 'order.failed').update(exception='TEST_SECRET_PAYMENT')) + assert_fails('no_secrets', lambda rows, obs: obs.update(stdout='TEST_SECRET_HEADER')) + assert_fails('request_isolation', lambda rows, obs: next(r for r in rows if r['event'] == 'order.created').update(request_id='wrong')) + assert_fails('context_cleanup', lambda rows, obs: next(r for r in rows if r['event'] == 'demo.probe').update(request_id='leaked')) + assert_fails('event_contracts', lambda rows, obs: [r.update(event='renamed') for r in rows if r['event'] == 'order.created']) + assert_fails('http_contract', lambda rows, obs: obs['responses'][0].update(status=500)) + assert_fails('provider_behavior', lambda rows, obs: obs['provider']['failure'].update(message='redacted')) + assert_fails('original_stack', lambda rows, obs: obs.update(backend_calls={'stdlib': 0, 'structlog': 0})) + assert_fails('json_output', lambda rows, obs: obs.update(stdout='plain prose')) + + def test_source_regressions_fail_after_reference_repair(self): + for stack in STACKS: + with self.subTest(stack=stack): + project = self.project(stack, fixed=True) + backend = project / 'app/observability.py' + backend.write_text(backend.read_text().replace('_context.reset(token)', 'pass')) + result = demo.check(project) + self.assertFalse(next(c['passed'] for c in result['criteria'] if c['id'] == 'context_cleanup')) + + def test_create_excludes_graders_and_refuses_existing_destination(self): + project = self.project(STACKS[0]) + self.assertTrue((project / 'PROMPT.md').is_file()) + self.assertTrue((project / 'requirements.txt').is_file()) + self.assertFalse((project / 'runner.py').exists()) + self.assertFalse((project / 'reference').exists()) + before = (project / 'app/main.py').read_bytes() + with self.assertRaises(ValueError): + demo.create(STACKS[0], project) + self.assertEqual((project / 'app/main.py').read_bytes(), before) + + def test_report_exit_codes_and_no_overwrite(self): + project = self.project(STACKS[0]) + args = ['check', '--project', str(project), '--report', str(self.root / 'before.json')] + with contextlib.redirect_stdout(io.StringIO()), contextlib.redirect_stderr(io.StringIO()): + self.assertEqual(demo.main(args), 1) + content = (self.root / 'before.json').read_bytes() + self.assertEqual(demo.main(args), 2) + self.assertEqual((self.root / 'before.json').read_bytes(), content) + repair(project, STACKS[0]) + args[-1] = str(self.root / 'after.json') + self.assertEqual(demo.main(args), 0) + self.assertTrue(json.loads((self.root / 'after.json').read_text())['passed']) + + def test_missing_environment_and_probe_failure_are_setup_errors(self): + project = self.project(STACKS[0]) + (project / '.venv').unlink() + with self.assertRaisesRegex(ValueError, 'Missing virtual environment'): + demo.check(project) + (project / '.venv').symlink_to(Path(sys.prefix), target_is_directory=True) + (project / 'app/main.py').write_text('raise RuntimeError("broken startup")\n') + with self.assertRaisesRegex(ValueError, 'broken startup'): + demo.check(project) + report = self.root / 'error.json' + with contextlib.redirect_stdout(io.StringIO()), contextlib.redirect_stderr(io.StringIO()): + self.assertEqual(demo.main(['check', '--project', str(project), '--report', str(report)]), 2) + self.assertIsNone(json.loads(report.read_text())['passed']) + + def test_timeout_is_a_setup_error(self): + project = self.project(STACKS[0]) + with patch.object(demo.subprocess, 'run', side_effect=subprocess.TimeoutExpired('probe', 60)): + with contextlib.redirect_stdout(io.StringIO()), contextlib.redirect_stderr(io.StringIO()): + status = demo.main(['check', '--project', str(project), '--report', str(self.root / 'timeout.json')]) + self.assertEqual(status, 2) From 626e0b5b1bb7ece4d691f1b26950cccfba0c3703 Mon Sep 17 00:00:00 2001 From: mrKazzila Date: Tue, 22 Sep 2026 15:53:59 +0300 Subject: [PATCH 03/12] ci: validate stdlib and structlog demo variants --- .github/workflows/quality.yml | 17 +++++++++++++++++ just/quality.just | 5 +++++ 2 files changed, 22 insertions(+) diff --git a/.github/workflows/quality.yml b/.github/workflows/quality.yml index 308f9cf..fe56a62 100644 --- a/.github/workflows/quality.yml +++ b/.github/workflows/quality.yml @@ -21,3 +21,20 @@ jobs: - run: python scripts/validate_repo.py - run: python -m unittest discover -s tests -v - run: python scripts/check_release_state.py + + demo: + runs-on: ubuntu-latest + strategy: + matrix: + stack: [stdlib, structlog] + steps: + - uses: actions/checkout@v4 + - uses: actions/setup-python@v5 + with: + python-version: '3.12' + cache: pip + cache-dependency-path: evals/demo/requirements-${{ matrix.stack }}.txt + - run: python -m pip install -r evals/demo/requirements-${{ matrix.stack }}.txt + - run: python -m unittest discover -s tests/demo -v + env: + DEMO_TEST_STACK: ${{ matrix.stack }} diff --git a/just/quality.just b/just/quality.just index 29ffc6c..207d862 100644 --- a/just/quality.just +++ b/just/quality.just @@ -12,3 +12,8 @@ test: [doc('Run all deterministic checks')] check: validate test @python3 scripts/check_release_state.py + +[group('Quality')] +[doc('Test both generated FastAPI demo variants and the external evaluator')] +demo-test: + @uv run --with-requirements evals/demo/requirements-structlog.txt python -m unittest discover -s tests/demo -v From a8be9e495c51d519cc567cdc7e767c30964bcf53 Mon Sep 17 00:00:00 2001 From: mrKazzila Date: Tue, 22 Sep 2026 15:54:00 +0300 Subject: [PATCH 04/12] docs: document logging demo evaluation workflow --- README.md | 10 ++++++++++ evals/README.md | 2 ++ 2 files changed, 12 insertions(+) diff --git a/README.md b/README.md index 5cb408c..beab494 100644 --- a/README.md +++ b/README.md @@ -98,6 +98,16 @@ Behavioral agent evaluation is separate: see [evals/README.md](evals/README.md) Keep changes scoped and update examples or eval cases when the recommended behavior changes. +## Generated demo project + +Try the skill on a disposable FastAPI order API with stdlib or structlog logging. The application starts with intentional logging defects; an external checker measures HTTP behavior, rendered logs, exception ownership, secret handling, and request context before and after the agent's changes. + +```sh +python3 scripts/demo.py create --stack stdlib --dest /tmp/logging-demo-stdlib +``` + +See the [demo guide](evals/demo/README.md) for environment setup, evaluation commands, and skill/no-skill trials. Run `just demo-test` to test the generator and evaluator; these tests are separate from `just check` and run in their own CI matrix. + ## License This project is licensed under the terms in [LICENSE](LICENSE). diff --git a/evals/README.md b/evals/README.md index 10f0c39..ed94217 100644 --- a/evals/README.md +++ b/evals/README.md @@ -2,6 +2,8 @@ These cases evaluate agent decisions separately from deterministic repository checks. They have not been benchmarked yet. `cases.json` contains prompts, input files, expected implicit activation, and outcome criteria. Keep cases and results outside the installed skill so the agent does not see the grading answers. +For a complete generated HTTP application with before/after checks, see the [FastAPI demo](demo/README.md). + ## Run a case 1. Create a fresh temporary project and copy only the listed fixtures into it, keeping their basenames. Install any fixture dependencies in an isolated environment. Record initial file checksums. From 484db321918c28498f90456bbcdfc31a2a800f89 Mon Sep 17 00:00:00 2001 From: mrKazzila Date: Tue, 22 Sep 2026 16:07:00 +0300 Subject: [PATCH 05/12] ci: fix pip cache dependency path --- .github/workflows/quality.yml | 1 + 1 file changed, 1 insertion(+) diff --git a/.github/workflows/quality.yml b/.github/workflows/quality.yml index fe56a62..b8e2cc3 100644 --- a/.github/workflows/quality.yml +++ b/.github/workflows/quality.yml @@ -17,6 +17,7 @@ jobs: with: python-version: '3.12' cache: pip + cache-dependency-path: requirements-dev.txt - run: python -m pip install -r requirements-dev.txt - run: python scripts/validate_repo.py - run: python -m unittest discover -s tests -v From c707116f59efad668aa0698d195709a6dc8d5d3b Mon Sep 17 00:00:00 2001 From: mrKazzila Date: Thu, 24 Sep 2026 13:25:32 +0300 Subject: [PATCH 06/12] chore: install structured logging skill for project agents --- .../skills/python-structured-logging/SKILL.md | 147 ++++++++++++ .../agents/openai.yaml | 4 + .../examples/stdlib/bad.py | 30 +++ .../examples/stdlib/good.py | 50 +++++ .../examples/structlog/bad.py | 26 +++ .../examples/structlog/good.py | 44 ++++ .../references/Python Logging Style Guide.md | 210 ++++++++++++++++++ skills-lock.json | 11 + 8 files changed, 522 insertions(+) create mode 100644 .agents/skills/python-structured-logging/SKILL.md create mode 100644 .agents/skills/python-structured-logging/agents/openai.yaml create mode 100644 .agents/skills/python-structured-logging/examples/stdlib/bad.py create mode 100644 .agents/skills/python-structured-logging/examples/stdlib/good.py create mode 100644 .agents/skills/python-structured-logging/examples/structlog/bad.py create mode 100644 .agents/skills/python-structured-logging/examples/structlog/good.py create mode 100644 .agents/skills/python-structured-logging/references/Python Logging Style Guide.md create mode 100644 skills-lock.json diff --git a/.agents/skills/python-structured-logging/SKILL.md b/.agents/skills/python-structured-logging/SKILL.md new file mode 100644 index 0000000..f79bdbf --- /dev/null +++ b/.agents/skills/python-structured-logging/SKILL.md @@ -0,0 +1,147 @@ +--- +name: python-structured-logging +description: Use when reviewing or changing Python logging behavior, including structlog, stdlib logging, event naming, structured fields, bound context, exception logging, correlation IDs, or sensitive-data-safe observability. +--- + +# Python Structured Logging + +## Core Rule + +Logs are operational events, not developer diary entries. + +## Workflow + +1. Inspect the current stack first: `structlog`, stdlib `logging`, or a project wrapper. +2. Preserve the current direction unless it is harmful or migration was explicitly requested. +3. If the project uses stdlib `logging` intentionally, improve message shape and `extra` fields instead of forcing `structlog`. +4. Replace prose or dynamic event names with stable `snake_case` events. +5. Move variable data into structured fields and bind shared context once near the request or job boundary. +6. Keep one meaningful exception log at the layer that owns the failure, with a traceback when needed. +7. Remove or redact sensitive data before it reaches bound context or payload fields. +8. Verify output shape, levels, and noise after the change. + +## Event Naming + +- Use stable `snake_case` event names. +- Prefer action or action-plus-result names such as `invoice_processed` or `broker_publish_failed`. +- Do not put IDs, emails, statuses, or exception text into the event name. +- Do not use generic events such as `error`, `failed`, or `something_went_wrong` without the operation name. + +Good: + +```python +logger.info("invoice_processed", invoice_id=invoice_id, duration_ms=duration_ms) +logger.warning("retry_scheduled", attempt=attempt, delay_seconds=delay_seconds) +``` + +Bad: + +```python +logger.info(f"invoice {invoice_id} processed in {duration_ms} ms") +logger.error(f"publish failed for order {order_id}") +logger.info(f"user_{user_id}_updated") +``` + +## Fields and Context + +- Use stable field names such as `request_id`, `correlation_id`, `job_id`, `user_id`, `entity_id`, `status`, and `duration_ms` when they are relevant. +- Bind shared context once when possible instead of passing the same fields manually everywhere. +- Keep units in the key name: `duration_ms`, `delay_seconds`, `size_bytes`. +- Avoid renaming the same concept across modules. +- Prefer allowlisted payload fragments such as `{"amount_cents": ..., "card_last4": ...}` over raw payload logging. + +Good: + +```python +log = logger.bind(request_id=request_id, job_id=job_id) +log.info("job_started", task_name=task_name) +``` + +Bad: + +```python +logger.info("job started", extra={"req": request_id, "job": job_id}) +logger.info("job_started", request_id=request_id, job_id=job_id) +logger.info("job_finished", request_id=request_id, job_id=job_id) +``` + +## Exception Logging + +- Use `logger.exception(...)` inside `except` when you need the traceback. +- Use `exc_info=True` only when the logger API requires it. +- Do not log and swallow unless that behavior is intentional and the caller does not need the failure. +- Do not duplicate the same exception log at every layer. +- Do not use `logger.error(str(exc))` as the only exception log for unexpected failures. + +Good: + +```python +try: + send_invoice(invoice) +except ProviderTimeoutError: + logger.exception("invoice_send_failed", invoice_id=invoice.id, retryable=True) + raise +``` + +Bad: + +```python +try: + send_invoice(invoice) +except Exception as exc: + logger.error(f"invoice failed: {exc}") +``` + +## Sensitive Data + +- Never log passwords, tokens, API keys, cookies, authorization headers, private keys, or raw secrets. +- Never log raw request bodies, raw response bodies, session data, personal data, or payment data unless the user explicitly asks for a safe, scoped format. +- Prefer allowlisted fields over blocklists when logging payload-derived data. +- Redact at boundaries before binding context. + +Good: + +```python +safe_payment = { + "card_last4": payment.card_last4, + "amount_cents": payment.amount_cents, +} +logger.info("payment_authorized", payment=safe_payment) +``` + +Bad: + +```python +logger.info("payment_authorized", payload=payment_payload, auth_header=auth_header) +``` + +## Noise Control + +- `INFO` for business or operational events that matter. +- `DEBUG` for local diagnostics that can be turned off safely. +- `WARNING` for degraded but handled situations such as retries or fallbacks. +- `ERROR` for failed operations that need attention. +- Avoid logs inside tight loops unless they are sampled or aggregated. +- Remove `started` and `finished` chatter unless the boundary is operationally meaningful. +- Prefer one outcome log over multiple step-by-step logs when the extra detail does not change operator action. + +## Bundled Resources + +- [`examples/structlog/good.py`](examples/structlog/good.py) +- [`examples/structlog/bad.py`](examples/structlog/bad.py) +- [`examples/stdlib/good.py`](examples/stdlib/good.py) +- [`examples/stdlib/bad.py`](examples/stdlib/bad.py) +- [`references/Python Logging Style Guide.md`](references/Python Logging Style Guide.md) + +- Read the examples that match the stack already in use. +- Read the reference guide when you need human-oriented rationale, level guidance, or migration examples. + +## Verification Checklist + +- Current logging style is preserved or intentionally migrated. +- Event names are stable and `snake_case`. +- Variable data is in fields, not prose strings. +- Shared context is bound or injected once where the stack supports it. +- Exceptions include stack traces where needed. +- Sensitive data is redacted or omitted. +- Output still fits the project's log pipeline. diff --git a/.agents/skills/python-structured-logging/agents/openai.yaml b/.agents/skills/python-structured-logging/agents/openai.yaml new file mode 100644 index 0000000..38d5a20 --- /dev/null +++ b/.agents/skills/python-structured-logging/agents/openai.yaml @@ -0,0 +1,4 @@ +interface: + display_name: "Python Structured Logging" + short_description: "Practical guidance for safer, more useful Python logs" + default_prompt: "Use $python-structured-logging to inspect the current Python logging stack, tighten event names and fields, and improve exception logging without forcing an unnecessary migration." diff --git a/.agents/skills/python-structured-logging/examples/stdlib/bad.py b/.agents/skills/python-structured-logging/examples/stdlib/bad.py new file mode 100644 index 0000000..184ccfa --- /dev/null +++ b/.agents/skills/python-structured-logging/examples/stdlib/bad.py @@ -0,0 +1,30 @@ +import logging + + +logger = logging.getLogger(__name__) + + +def process_invoice( + invoice_id: str, + customer_id: str, + request_id: str, + attempt: int, + payment_payload: dict, +) -> None: + print("starting invoice processing", invoice_id, customer_id, request_id) + logger.info( + f"processing invoice {invoice_id} for customer {customer_id} attempt={attempt}" + ) + + try: + logger.info( + f"invoice_{invoice_id}_processed", + extra={ + "payload": payment_payload, + "request": request_id, + "authorization_header": "Bearer secret-token", + }, + ) + except Exception as exc: + logger.error(f"invoice processing failed for {invoice_id}: {exc}") + return diff --git a/.agents/skills/python-structured-logging/examples/stdlib/good.py b/.agents/skills/python-structured-logging/examples/stdlib/good.py new file mode 100644 index 0000000..80153df --- /dev/null +++ b/.agents/skills/python-structured-logging/examples/stdlib/good.py @@ -0,0 +1,50 @@ +import logging + + +logger = logging.getLogger(__name__) + + +class PaymentGatewayError(RuntimeError): + pass + + +def process_invoice( + invoice_id: str, + customer_id: str, + request_id: str, + attempt: int, + amount_cents: int, +) -> None: + shared_context = { + "request_id": request_id, + "invoice_id": invoice_id, + "customer_id": customer_id, + "attempt": attempt, + } + safe_payment = { + "amount_cents": amount_cents, + "card_last4": "4242", + } + + try: + if amount_cents < 0: + raise PaymentGatewayError("negative amount") + + logger.info( + "invoice_processed", + extra={ + **shared_context, + "status": "success", + "payment": safe_payment, + }, + ) + except PaymentGatewayError: + logger.exception( + "invoice_processing_failed", + extra={ + **shared_context, + "retryable": True, + "payment": safe_payment, + }, + ) + raise diff --git a/.agents/skills/python-structured-logging/examples/structlog/bad.py b/.agents/skills/python-structured-logging/examples/structlog/bad.py new file mode 100644 index 0000000..3b6f5c3 --- /dev/null +++ b/.agents/skills/python-structured-logging/examples/structlog/bad.py @@ -0,0 +1,26 @@ +import structlog + + +logger = structlog.get_logger(__name__) + + +def process_invoice( + invoice_id: str, + customer_id: str, + request_id: str, + attempt: int, + payment_payload: dict, +) -> None: + try: + logger.info( + f"starting invoice processing for invoice={invoice_id}, customer={customer_id}, request={request_id}" + ) + logger.info( + f"invoice_{invoice_id}_processed", + payload=payment_payload, + attempt=attempt, + authorization_header="Bearer secret-token", + ) + except Exception as exc: + logger.error(f"invoice processing failed for {invoice_id}: {exc}") + raise diff --git a/.agents/skills/python-structured-logging/examples/structlog/good.py b/.agents/skills/python-structured-logging/examples/structlog/good.py new file mode 100644 index 0000000..8e7fb07 --- /dev/null +++ b/.agents/skills/python-structured-logging/examples/structlog/good.py @@ -0,0 +1,44 @@ +import structlog + + +logger = structlog.get_logger(__name__) + + +class PaymentGatewayError(RuntimeError): + pass + + +def process_invoice( + invoice_id: str, + customer_id: str, + request_id: str, + attempt: int, + amount_cents: int, +) -> None: + log = logger.bind( + request_id=request_id, + invoice_id=invoice_id, + customer_id=customer_id, + attempt=attempt, + ) + safe_payment = { + "amount_cents": amount_cents, + "card_last4": "4242", + } + + try: + if amount_cents < 0: + raise PaymentGatewayError("negative amount") + + log.info( + "invoice_processed", + status="success", + payment=safe_payment, + ) + except PaymentGatewayError: + log.exception( + "invoice_processing_failed", + retryable=True, + payment=safe_payment, + ) + raise diff --git a/.agents/skills/python-structured-logging/references/Python Logging Style Guide.md b/.agents/skills/python-structured-logging/references/Python Logging Style Guide.md new file mode 100644 index 0000000..517d384 --- /dev/null +++ b/.agents/skills/python-structured-logging/references/Python Logging Style Guide.md @@ -0,0 +1,210 @@ +# Python Logging Style Guide + +Use this reference when you need human-oriented guidance for reviewing or improving logs in Python code. The skill file is the execution checklist; this guide adds rationale, examples, and migration patterns. Prefer `structlog` when the project already uses it, and keep stdlib `logging` when the project intentionally standardized on it. + +## Core Rules + +- Treat each log as an operational event. +- Keep event names short, stable, and in `snake_case`. +- Put variable data into fields, not interpolated prose. +- Bind shared context once when possible. +- Preserve stack traces for unexpected failures. +- Redact sensitive data before it reaches logs. +- Keep debug noise on a short leash. + +## Event Naming + +Prefer event names like: + +```python +"invoice_processed" +"retry_scheduled" +"broker_publish_failed" +``` + +Avoid event names like: + +```python +"Invoice processed successfully!" +f"invoice_{invoice_id}_processed" +"something went wrong" +``` + +Good: + +```python +logger.info("invoice_processed", invoice_id=invoice_id, duration_ms=duration_ms) +``` + +Bad: + +```python +logger.info(f"invoice {invoice_id} processed in {duration_ms} ms") +``` + +## Field Naming Conventions + +Use stable `snake_case` field names and explicit units. + +Preferred fields: + +```text +request_id +correlation_id +job_id +user_id +entity_id +status +reason +error_code +duration_ms +delay_seconds +size_bytes +attempt +max_attempts +``` + +Guidelines: + +- One concept should keep one name across the project. +- IDs should normally end with `_id`. +- Units belong in the key name, not only in the value. +- Avoid repeating the same shared fields on every log if the stack supports binding or adapters. + +When logging payload-derived data, prefer allowlisted fragments over whole payloads. For example, log `card_last4`, `amount_cents`, or `item_count`, not the raw request body. + +## Level Guide + +- `DEBUG`: local diagnostics and temporary deep inspection. +- `INFO`: expected business or operational events. +- `WARNING`: degraded but handled situations such as retries or fallbacks. +- `ERROR`: a concrete operation failed and needs attention. +- `CRITICAL`: service-threatening state or probable data-loss scenario. + +Do not log every function entry and exit at `INFO`. Use `DEBUG` sparingly, and only when the details are actionable. + +## Exception Logging + +Use `logger.exception(...)` inside `except` when you need traceback data. + +Good: + +```python +try: + publish(message) +except ProviderTimeoutError: + logger.exception("publish_failed", message_id=message_id, retryable=True) + raise +``` + +Bad: + +```python +try: + publish(message) +except Exception as exc: + logger.error(f"publish failed: {exc}") +``` + +Rules: + +- Do not log and swallow unless that is the intended control flow. +- Do not duplicate the same exception log at every layer. +- Add enough context for operators to know what failed and whether it will retry. +- Avoid `logger.error(str(exc))` as the only record for an unexpected failure. + +## Sensitive Data + +Never log: + +- passwords +- tokens +- API keys +- cookies +- authorization headers +- private keys +- raw secrets +- raw request bodies +- raw response bodies +- session data +- personal data +- payment data +- raw payloads containing PII or credentials + +Prefer allowlisted payload logging. + +Good: + +```python +logger.info( + "payment_authorized", + payment={"amount_cents": amount_cents, "card_last4": card_last4}, +) +``` + +Bad: + +```python +logger.info("payment_authorized", payload=payment_payload, auth_header=auth_header) +``` + +## structlog and stdlib Patterns + +`structlog`: + +```python +log = logger.bind(request_id=request_id, job_id=job_id) +log.info("job_started", task_name=task_name) +``` + +Stdlib `logging`: + +```python +logger.info( + "job_started", + extra={"request_id": request_id, "job_id": job_id, "task_name": task_name}, +) +``` + +In both styles, keep the event name stable and treat the surrounding fields as the query surface. If a downstream formatter or adapter already shapes the record, follow that path instead of inventing a parallel one. + +## Migration Notes + +From `print` debugging: + +```python +print("processing invoice", invoice_id) +``` + +To structured logging: + +```python +logger.debug("invoice_processing", invoice_id=invoice_id) +``` + +From prose logging: + +```python +logger.info(f"user {user_id} updated account status to {status}") +``` + +To structured events: + +```python +logger.info("account_status_updated", user_id=user_id, status=status) +``` + +From repeated manual context: + +```python +logger.info("step_one", request_id=request_id, user_id=user_id) +logger.info("step_two", request_id=request_id, user_id=user_id) +``` + +To bound context: + +```python +log = logger.bind(request_id=request_id, user_id=user_id) +log.info("step_one") +log.info("step_two") +``` diff --git a/skills-lock.json b/skills-lock.json new file mode 100644 index 0000000..7f2234a --- /dev/null +++ b/skills-lock.json @@ -0,0 +1,11 @@ +{ + "version": 1, + "skills": { + "python-structured-logging": { + "source": "mrKazzila/python-structured-logging-skill", + "sourceType": "github", + "skillPath": "plugins/python-structured-logging/skills/python-structured-logging/SKILL.md", + "computedHash": "afa4c67a1da5167d6316a82991e480c15a7bcd6006126e3858bdf0d58e3c220e" + } + } +} From af71c3dbafb505073d1de0e99241160f93a6cd31 Mon Sep 17 00:00:00 2001 From: mrKazzila Date: Fri, 25 Sep 2026 14:07:05 +0300 Subject: [PATCH 07/12] test: cover runtime logging safety and unexpected failures --- evals/demo/grading.py | 62 +++++++++ evals/demo/reference/runtime_boundary.py | 37 ++++++ evals/demo/reference/safe_output.py | 24 ++++ evals/demo/reference/stdlib.py | 3 +- evals/demo/reference/structlog.py | 3 +- .../regressions/reviewed_worker/README.md | 15 +++ .../demo/regressions/reviewed_worker/main.py | 46 +++++++ .../regressions/reviewed_worker/middleware.py | 45 +++++++ .../reviewed_worker/observability.py | 121 ++++++++++++++++++ .../regressions/reviewed_worker/service.py | 9 ++ evals/demo/runtime_probe.py | 89 +++++++++++++ scripts/demo.py | 16 +++ tests/demo/test_demo.py | 99 +++++++++++++- 13 files changed, 565 insertions(+), 4 deletions(-) create mode 100644 evals/demo/reference/runtime_boundary.py create mode 100644 evals/demo/regressions/reviewed_worker/README.md create mode 100644 evals/demo/regressions/reviewed_worker/main.py create mode 100644 evals/demo/regressions/reviewed_worker/middleware.py create mode 100644 evals/demo/regressions/reviewed_worker/observability.py create mode 100644 evals/demo/regressions/reviewed_worker/service.py create mode 100644 evals/demo/runtime_probe.py diff --git a/evals/demo/grading.py b/evals/demo/grading.py index 95bd1e5..b473594 100644 --- a/evals/demo/grading.py +++ b/evals/demo/grading.py @@ -3,6 +3,67 @@ import json +def rendered(observation): + """Strict JSON, including RFC-invalid NaN/Infinity, across both streams.""" + records, malformed = [], [] + + def invalid_constant(value): + raise ValueError(value) + + for stream in ('stdout', 'stderr'): + for line in observation[stream].splitlines(): + if not line.strip(): + continue + try: + record = json.loads(line, parse_constant=invalid_constant) + if (not isinstance(record, dict) or not isinstance(record.get('event'), str) + or not isinstance(record.get('level'), str)): + raise ValueError('expected JSON event and level') + records.append(record) + except (ValueError, TypeError): + malformed.append(line) + return records, malformed + + +def runtime_criteria(runtime): + """Independent evidence for server safety, ownership, fallback and correlation.""" + server, formatter = runtime['server'], runtime['formatter'] + records, malformed = rendered(server) + raw = server['stdout'] + server['stderr'] + leaks = [secret for secret in server['secrets'] if secret in raw] + errors = [r for r in records if r['level'].lower() in ('error', 'critical')] + # Count raw Uvicorn exception reports too, rather than overlooking ownership + # simply because the duplicate failed the JSON contract already. + raw_errors = [line for line in malformed if 'Exception in ASGI application' in line] + error_count = len(errors) + len(raw_errors) + correlated = [r for r in records if r.get('request_id') == server['expected_request_id']] + fmt_records, fmt_malformed = rendered(formatter) + fmt_raw = formatter['stdout'] + formatter['stderr'] + unsafe = [marker for marker in [*formatter['secrets'], '--- Logging error ---', + 'FORMATTER_SOURCE_SENTINEL'] if marker in fmt_raw] + return [ + {'id': 'whole_process_output', + 'passed': bool(records) and not malformed and not leaks, + 'evidence': {'records': len(records), 'malformed_lines': malformed, 'leaked_markers': leaks}}, + {'id': 'unexpected_failure_ownership', + 'passed': error_count == 1, + 'evidence': {'error_records': len(errors), 'raw_server_errors': len(raw_errors)}}, + {'id': 'formatter_fallback_safety', + 'passed': formatter['raised'] is None and not unsafe and not fmt_malformed and + any(r['event'] == 'demo.serialization_recovery' for r in fmt_records), + 'evidence': {'raised': formatter['raised'], 'unsafe_markers': unsafe, + 'malformed_lines': fmt_malformed, 'records': len(fmt_records)}}, + {'id': 'unexpected_500_correlation', + 'passed': server['status'] == 500 and + server['request_id'] == server['expected_request_id'] and bool(correlated) and + any(r['event'] == 'request.completed' and r.get('status_code') == 500 + for r in correlated), + 'evidence': {'status': server['status'], 'response_request_id': server['request_id'], + 'expected_request_id': server['expected_request_id'], + 'correlated_events': [r['event'] for r in correlated]}}, + ] + + def grade(observations, stack): criteria = [] @@ -101,4 +162,5 @@ def result(name, passed, evidence): usage = observations['backend_calls'] preserved = usage[stack] > 0 and (stack != 'stdlib' or usage['structlog'] == 0) result('original_stack', preserved, usage) + criteria.extend(runtime_criteria(observations['runtime'])) return criteria diff --git a/evals/demo/reference/runtime_boundary.py b/evals/demo/reference/runtime_boundary.py new file mode 100644 index 0000000..14627c6 --- /dev/null +++ b/evals/demo/reference/runtime_boundary.py @@ -0,0 +1,37 @@ +"""Test oracle only: an outer boundary owns unexpected HTTP failures.""" + +from uuid import uuid4 + +from . import observability as log + + +class RuntimeBoundary: + def __init__(self, app): + self.app = app + + async def __call__(self, scope, receive, send): + if scope['type'] != 'http': + return await self.app(scope, receive, send) + request_id = dict(scope['headers']).get(b'x-request-id', b'').decode() or str(uuid4()) + scope = {**scope, 'headers': [*scope['headers'], (b'x-request-id', request_id.encode())]} + token = log.bind_request(request_id) + started = False + + async def correlated_send(message): + nonlocal started + if message['type'] == 'http.response.start': + started = True + headers = [(key, value) for key, value in message.get('headers', []) + if key.lower() != b'x-request-id'] + message = {**message, 'headers': [*headers, (b'x-request-id', request_id.encode())]} + await send(message) + + try: + await self.app(scope, receive, correlated_send) + except Exception: + log.exception('request.failed', request_id=request_id) + # Starlette already sent its 500; this boundary owns the outcome. + if not started: + raise + finally: + log.reset_request(token) diff --git a/evals/demo/reference/safe_output.py b/evals/demo/reference/safe_output.py index 64dd5f8..ced6cbe 100644 --- a/evals/demo/reference/safe_output.py +++ b/evals/demo/reference/safe_output.py @@ -1,4 +1,8 @@ import re +import json +import logging +import math +import sys def sanitize(value): @@ -9,4 +13,24 @@ def sanitize(value): return [sanitize(item) for item in value] if isinstance(value, str): return re.sub(r'TEST_SECRET_[A-Z0-9_]+', '[REDACTED]', value) + if isinstance(value, float) and not math.isfinite(value): + return None return value + + +class ServerFormatter(logging.Formatter): + def format(self, record): + event = {'event': 'server.log', 'level': record.levelname.lower(), + 'message': record.getMessage()} + if record.exc_info: + event['exception'] = self.formatException(record.exc_info) + return json.dumps(sanitize(event), allow_nan=False) + + +def configure_server(): + handler = logging.StreamHandler(sys.stderr) + handler.setFormatter(ServerFormatter()) + for name in ('uvicorn', 'uvicorn.error', 'uvicorn.access'): + logger = logging.getLogger(name) + logger.handlers = [handler] + logger.propagate = False diff --git a/evals/demo/reference/stdlib.py b/evals/demo/reference/stdlib.py index 43b44bf..7288024 100644 --- a/evals/demo/reference/stdlib.py +++ b/evals/demo/reference/stdlib.py @@ -3,7 +3,7 @@ import sys from contextvars import ContextVar -from .safe_output import sanitize +from .safe_output import configure_server, sanitize _context = ContextVar('request_context', default={}) logger = logging.getLogger('orders') @@ -18,6 +18,7 @@ def format(self, record): def configure(): + configure_server() handler = logging.StreamHandler(sys.stderr) handler.setFormatter(JsonFormatter()) logger.handlers = [handler] diff --git a/evals/demo/reference/structlog.py b/evals/demo/reference/structlog.py index 04d7c09..8a5c2dc 100644 --- a/evals/demo/reference/structlog.py +++ b/evals/demo/reference/structlog.py @@ -3,7 +3,7 @@ import structlog -from .safe_output import sanitize +from .safe_output import configure_server, sanitize _context = ContextVar('request_context', default={}) logger = structlog.get_logger('orders') @@ -14,6 +14,7 @@ def safe_fields(logger, method, event): def configure(): + configure_server() structlog.configure( processors=[structlog.processors.add_log_level, structlog.processors.format_exc_info, safe_fields, structlog.processors.JSONRenderer()], diff --git a/evals/demo/regressions/reviewed_worker/README.md b/evals/demo/regressions/reviewed_worker/README.md new file mode 100644 index 0000000..ae5a99f --- /dev/null +++ b/evals/demo/regressions/reviewed_worker/README.md @@ -0,0 +1,15 @@ +# Deliberately defective worker snapshot + +These four files preserve the reviewed stdlib worker from +`/private/tmp/logging-skill-review-20260925/app` on 2026-09-25. The remaining app +files are unchanged demo template files. This is a regression fixture, not a +recommended implementation. It is never copied by `demo.py create`. + +The old evaluator accepted it (11/11). The new runtime checks reject its unsafe +Uvicorn output, duplicate failure ownership, NaN formatter diagnostic fallback, +and missing correlation header on unexpected 500 responses. + +`test_minimal_reviewed_worker_repairs_pass` applies corrections only to a temporary +copy: finite-value normalization, server logging configuration, and an outer +HTTP failure/correlation boundary with one failure owner. The snapshot stays +intentionally defective. See `../../runtime-regressions.md` for evidence. diff --git a/evals/demo/regressions/reviewed_worker/main.py b/evals/demo/regressions/reviewed_worker/main.py new file mode 100644 index 0000000..3acb1f9 --- /dev/null +++ b/evals/demo/regressions/reviewed_worker/main.py @@ -0,0 +1,46 @@ +from contextlib import asynccontextmanager +from typing import Literal + +from fastapi import FastAPI +from fastapi.responses import JSONResponse +from pydantic import BaseModel, Field + +from . import observability as log +from .middleware import RequestContextMiddleware +from .provider import ProviderTimeout +from .service import create_order + + +class Order(BaseModel): + order_id: str = Field(min_length=1) + amount_cents: int = Field(gt=0) + provider_mode: Literal['success', 'timeout'] = 'success' + payment_token: str = 'TEST_SECRET_DEFAULT' + + +@asynccontextmanager +async def lifespan(app): + log.info('application.started') + try: + yield + finally: + log.info('application.stopped') + + +log.configure() +app = FastAPI(title='Logging skill demo: orders', lifespan=lifespan) +app.add_middleware(RequestContextMiddleware) + + +@app.get('/health') +async def health(): + return {'status': 'ok'} + + +@app.post('/orders', status_code=201) +async def orders(order: Order): + try: + return await create_order(order) + except ProviderTimeout: + log.exception('order.failed', order_id=order.order_id, retryable=True, error_type='ProviderTimeout') + return JSONResponse(status_code=503, content={'detail': 'provider unavailable'}) diff --git a/evals/demo/regressions/reviewed_worker/middleware.py b/evals/demo/regressions/reviewed_worker/middleware.py new file mode 100644 index 0000000..16a503e --- /dev/null +++ b/evals/demo/regressions/reviewed_worker/middleware.py @@ -0,0 +1,45 @@ +from time import perf_counter +from uuid import uuid4 + +from . import observability as log + + +class RequestContextMiddleware: + def __init__(self, app): + self.app = app + + async def __call__(self, scope, receive, send): + if scope['type'] != 'http': + return await self.app(scope, receive, send) + headers = dict(scope['headers']) + request_id = headers.get(b'x-request-id', b'').decode() or str(uuid4()) + token = log.bind_request(request_id) + status = 500 + started = perf_counter() + + async def send_response(message): + nonlocal status + if message['type'] == 'http.response.start': + status = message['status'] + message = {**message, 'headers': [ + *message.get('headers', []), + (b'x-request-id', request_id.encode()), + ]} + await send(message) + + try: + await self.app(scope, receive, send_response) + except Exception: + # Handled provider failures never reach this boundary. + log.exception('request.failed', status_code=status) + raise + finally: + try: + route = scope.get('route') + log.info( + 'request.completed', status_code=status, + path=getattr(route, 'path', None), + duration_ms=round((perf_counter() - started) * 1000, 3), + ) + finally: + log.reset_request(token) diff --git a/evals/demo/regressions/reviewed_worker/observability.py b/evals/demo/regressions/reviewed_worker/observability.py new file mode 100644 index 0000000..aa5a304 --- /dev/null +++ b/evals/demo/regressions/reviewed_worker/observability.py @@ -0,0 +1,121 @@ +"""Application-owned stdlib JSON pipeline, also usable outside HTTP requests.""" + +from contextvars import ContextVar +from datetime import datetime, timezone +import json +import logging +from pathlib import Path +import re +import sys +import traceback + +_context = ContextVar('logging_request_context', default=None) +logger = logging.getLogger('orders') +_SENSITIVE_KEYS = re.compile(r'authorization|cookie|credential|password|secret|token|api[_-]?key', re.I) +_SENSITIVE_TEXT = re.compile( + r'(?i)\b(authorization|credential|password|secret|token|api[_-]?key)\s*[:=]\s*[^\r\n]*' +) +_RESERVED = frozenset(logging.makeLogRecord({}).__dict__) | {'message', 'asctime', 'fields'} + + +def _safe(value): + """Defense in depth; callers still select fields instead of logging payloads.""" + if isinstance(value, dict): + return { + str(key): '[REDACTED]' if _SENSITIVE_KEYS.search(str(key)) else _safe(item) + for key, item in value.items() + } + if isinstance(value, (tuple, list)): + return [_safe(item) for item in value] + if isinstance(value, str): + return _SENSITIVE_TEXT.sub(lambda match: match.group(1) + '=[REDACTED]', value) + if value is None or isinstance(value, (bool, int, float)): + return value + # repr/str of arbitrary objects can expose payloads and credentials. + return '[unsupported value]' + + +def _safe_exception(exc_info): + """Retain traceback locations/types, never exception text, locals or source.""" + seen = set() + + def render(error, tb): + if error is None or id(error) in seen: + return [] + seen.add(id(error)) + lines = [] + cause = error.__cause__ + if cause is not None: + lines.extend(render(cause, cause.__traceback__)) + lines.append('The above exception was the direct cause of the following exception:') + elif error.__context__ is not None and not error.__suppress_context__: + lines.extend(render(error.__context__, error.__context__.__traceback__)) + lines.append('During handling of the above exception, another exception occurred:') + lines.append('Traceback (most recent call last):') + for frame, lineno in traceback.walk_tb(tb): + lines.append(f' File "{Path(frame.f_code.co_filename).name}", line {lineno}, in {frame.f_code.co_name}') + lines.append(f'{type(error).__name__}: [exception message omitted]') + if isinstance(error, BaseExceptionGroup): + for nested in error.exceptions: + lines.extend(render(nested, nested.__traceback__)) + return lines + + return '\n'.join(render(exc_info[1], exc_info[2])) + + +class ContextFilter(logging.Filter): + def filter(self, record): + fields = dict(getattr(record, 'fields', {})) + request_id = _context.get() + if request_id is not None: + fields['request_id'] = request_id + record.fields = fields + return True + + +class JsonFormatter(logging.Formatter): + def format(self, record): + fields = {key: value for key, value in record.__dict__.items() if key not in _RESERVED} + fields.update(getattr(record, 'fields', {})) + result = _safe(fields) + # Fields cannot override the envelope or inject an unsanitized traceback. + result.pop('exception', None) + result.update({ + 'event': _safe(record.getMessage()), + 'level': record.levelname.lower(), + 'timestamp': datetime.fromtimestamp(record.created, timezone.utc).isoformat(), + 'logger': record.name, + }) + if record.exc_info and record.exc_info[1] is not None: + result['exception'] = _safe_exception(record.exc_info) + return json.dumps(result, allow_nan=False) + + +def configure(): + # Only manage our own handler; do not configure root or third-party loggers. + for handler in logger.handlers: + if getattr(handler, '_orders_json_handler', False): + return + handler = logging.StreamHandler(sys.stderr) + handler._orders_json_handler = True + handler.setFormatter(JsonFormatter()) + handler.addFilter(ContextFilter()) + logger.addHandler(handler) + logger.setLevel(logging.INFO) + logger.propagate = False + + +def bind_request(request_id): + return _context.set(request_id) + + +def reset_request(token): + _context.reset(token) + + +def info(event, **fields): + logger.info(event, extra={'fields': fields}) + + +def exception(event, **fields): + logger.exception(event, extra={'fields': fields}) diff --git a/evals/demo/regressions/reviewed_worker/service.py b/evals/demo/regressions/reviewed_worker/service.py new file mode 100644 index 0000000..7128421 --- /dev/null +++ b/evals/demo/regressions/reviewed_worker/service.py @@ -0,0 +1,9 @@ +from . import observability as log +from .provider import charge + + +async def create_order(order): + # HTTP owns failures and retry policy; this layer records the business success. + result = await charge(order) + log.info('order.created', order_id=order.order_id, amount_cents=order.amount_cents) + return result diff --git a/evals/demo/runtime_probe.py b/evals/demo/runtime_probe.py new file mode 100644 index 0000000..9915f23 --- /dev/null +++ b/evals/demo/runtime_probe.py @@ -0,0 +1,89 @@ +"""Held-out real-server and public-facade probes, each in a fresh process. + +stdout/stderr belong to the application. Metadata goes to a separate file so +logging diagnostics (including writes to file descriptors) cannot escape grading. +""" + +import asyncio +import json +import logging +import sys +from pathlib import Path +from uuid import uuid4 + + +def formatter(): + from app import observability as log + + log.configure() + logging.raiseExceptions = True # Exercise stdlib's development diagnostic path. + secret = 'TEST_SECRET_FORMATTER_' + uuid4().hex.upper() + local_secret = 'TEST_SECRET_LOCAL_' + uuid4().hex.upper() + raised = None + try: + raise RuntimeError(secret) + except RuntimeError: + try: + log.exception('demo.serialization', measurement=float('nan')) # FORMATTER_SOURCE_SENTINEL + except Exception as error: + raised = type(error).__name__ + log.info('demo.serialization_recovery') + return {'secrets': [secret, local_secret], 'raised': raised} + + +async def server(): + import httpx + import uvicorn + + secret = 'TEST_SECRET_UNEXPECTED_' + uuid4().hex.upper() + query_secret = 'TEST_SECRET_QUERY_' + uuid4().hex.upper() + request_id = 'req-unexpected-' + uuid4().hex + # Match the documented CLI: Uvicorn configures its logging before importing + # app.main, allowing the project's configure() to own the final pipeline. + config = uvicorn.Config('app.main:app', host='127.0.0.1', port=0, + access_log=True, http='h11', lifespan='on') + config.load() + from app.main import app + + async def unexpected(): + raise RuntimeError(secret) + + # Standard FastAPI routing API; outer ASGI wrappers may delegate to .app. + router_app = app + while not hasattr(router_app, 'add_api_route') and hasattr(router_app, 'app'): + router_app = router_app.app + router_app.add_api_route('/__evaluation_unexpected__', unexpected, methods=['GET']) + ready = asyncio.Event() + + class ReadyServer(uvicorn.Server): + async def startup(self, sockets=None): + await super().startup(sockets=sockets) + ready.set() + + instance = ReadyServer(config) + task = asyncio.create_task(instance.serve()) + readiness = asyncio.create_task(ready.wait()) + try: + done, _ = await asyncio.wait([task, readiness], return_when=asyncio.FIRST_COMPLETED) + if task in done: + await task + raise RuntimeError('Uvicorn exited before readiness') + port = instance.servers[0].sockets[0].getsockname()[1] + async with httpx.AsyncClient(trust_env=False, timeout=10) as client: + response = await client.get( + f'http://127.0.0.1:{port}/__evaluation_unexpected__', + params={'credential': query_secret}, headers={'X-Request-ID': request_id}) + return {'status': response.status_code, + 'request_id': response.headers.get('x-request-id'), + 'expected_request_id': request_id, 'secrets': [secret, query_secret]} + finally: + readiness.cancel() + instance.should_exit = True + await task + + +if __name__ == '__main__': + sys.path.insert(0, str(Path(sys.argv[1]).resolve())) + observed = (asyncio.run(asyncio.wait_for(server(), timeout=30)) + if sys.argv[2] == 'server' else formatter()) + Path(sys.argv[3]).write_text(json.dumps(observed), encoding='utf-8') diff --git a/scripts/demo.py b/scripts/demo.py index 5820ec0..babe9a0 100644 --- a/scripts/demo.py +++ b/scripts/demo.py @@ -61,6 +61,22 @@ def check(project: Path) -> dict: grading = importlib.util.module_from_spec(spec) spec.loader.exec_module(grading) observed = payload['observations'] + observed['runtime'] = {} + with tempfile.TemporaryDirectory(prefix='logging-runtime-') as temporary: + for mode in ('server', 'formatter'): + metadata = Path(temporary) / f'{mode}.json' + runtime = subprocess.run( + [str(python), '-I', '-B', str(DEMO / 'runtime_probe.py'), + str(project), mode, str(metadata)], + cwd=project, env=environment, capture_output=True, text=True, timeout=45, + ) + if runtime.returncode or not metadata.is_file(): + raise ValueError(f'{mode} runtime probe failed (exit {runtime.returncode}): ' + f'{runtime.stderr[-4000:]}') + observed['runtime'][mode] = { + **json.loads(metadata.read_text(encoding='utf-8')), + 'stdout': runtime.stdout, 'stderr': runtime.stderr, + } criteria = grading.grade(observed, stack) return {'schema_version': 1, 'project': str(project), 'stack': stack, 'checked_at': datetime.now(timezone.utc).isoformat(), 'versions': observed['versions'], diff --git a/tests/demo/test_demo.py b/tests/demo/test_demo.py index 9906eae..0a17782 100644 --- a/tests/demo/test_demo.py +++ b/tests/demo/test_demo.py @@ -22,13 +22,16 @@ def repair(project, stack): reference = demo.DEMO / 'reference' shutil.copyfile(reference / f'{stack}.py', project / 'app/observability.py') - for filename in ('service.py', 'safe_output.py'): + for filename in ('service.py', 'safe_output.py', 'runtime_boundary.py'): shutil.copyfile(reference / filename, project / 'app' / filename) middleware = project / 'app/middleware.py' middleware.write_text(middleware.read_text().replace( "log.info('request.received', authorization=headers.get(b'authorization', b'').decode())", "log.info('request.received')", )) + main = project / 'app/main.py' + main.write_text(main.read_text() + + '\nfrom .runtime_boundary import RuntimeBoundary\napp = RuntimeBoundary(app)\n') class DemoTests(unittest.TestCase): @@ -49,7 +52,9 @@ def project(self, stack, fixed=False): def test_originals_have_working_api_and_reproducible_logging_defects(self): expected_failures = {'stable_events', 'structured_fields', 'single_failure_traceback', - 'no_secrets', 'request_isolation', 'context_cleanup'} + 'no_secrets', 'request_isolation', 'context_cleanup', + 'whole_process_output', + 'formatter_fallback_safety', 'unexpected_500_correlation'} for stack in STACKS: with self.subTest(stack=stack): project = self.project(stack) @@ -73,6 +78,96 @@ def test_reference_repairs_pass_every_criterion(self): self.assertTrue(report['passed'], report['criteria']) self.assertTrue(report['versions']['fastapi']) + def reviewed_worker(self): + project = self.project('stdlib') + for source in (demo.DEMO / 'regressions/reviewed_worker').glob('*.py'): + shutil.copyfile(source, project / 'app' / source.name) + return project + + def reviewed_report(self): + report = demo.check(self.reviewed_worker()) + self.assertEqual(len(report['criteria']), 15) + self.assertTrue(all(c['passed'] for c in report['criteria'][:11])) + self.assertFalse(report['passed']) + return report + + def test_reviewed_worker_whole_process_output(self): + report = self.reviewed_report() + check = next(c for c in report['criteria'] if c['id'] == 'whole_process_output') + self.assertFalse(check['passed']) + self.assertEqual(len(check['evidence']['leaked_markers']), 2) + + def test_reviewed_worker_duplicate_failure_ownership(self): + report = self.reviewed_report() + check = next(c for c in report['criteria'] if c['id'] == 'unexpected_failure_ownership') + self.assertFalse(check['passed']) + self.assertEqual(check['evidence'], {'error_records': 1, 'raw_server_errors': 1}) + + def test_reviewed_worker_formatter_fallback(self): + report = self.reviewed_report() + check = next(c for c in report['criteria'] if c['id'] == 'formatter_fallback_safety') + self.assertFalse(check['passed']) + self.assertIn('--- Logging error ---', check['evidence']['unsafe_markers']) + self.assertIn('FORMATTER_SOURCE_SENTINEL', check['evidence']['unsafe_markers']) + self.assertTrue(any('TEST_SECRET_FORMATTER_' in s for s in check['evidence']['unsafe_markers'])) + + def test_reviewed_worker_unexpected_500_correlation(self): + report = self.reviewed_report() + check = next(c for c in report['criteria'] if c['id'] == 'unexpected_500_correlation') + self.assertFalse(check['passed']) + self.assertEqual(check['evidence']['status'], 500) + self.assertIsNone(check['evidence']['response_request_id']) + self.assertIn('request.completed', check['evidence']['correlated_events']) + + def test_minimal_reviewed_worker_repairs_pass(self): + project = self.reviewed_worker() + for filename in ('safe_output.py', 'runtime_boundary.py'): + shutil.copyfile(demo.DEMO / 'reference' / filename, project / 'app' / filename) + backend = project / 'app/observability.py' + backend.write_text(backend.read_text().replace( + 'import json', 'import json\nimport math\nfrom .safe_output import configure_server', + ).replace('def _safe(value):', + 'def _safe(value):\n if isinstance(value, float) and not math.isfinite(value):\n return None' + ).replace('def configure():', 'def configure():\n configure_server()')) + middleware = project / 'app/middleware.py' + middleware.write_text(middleware.read_text().replace( + "log.exception('request.failed', status_code=status)", 'pass # Outer boundary owns failure')) + main = project / 'app/main.py' + main.write_text(main.read_text() + + '\nfrom .runtime_boundary import RuntimeBoundary\napp = RuntimeBoundary(app)\n') + report = demo.check(project) + self.assertTrue(report['passed'], report['criteria']) + + def test_independent_runtime_source_regressions(self): + mutations = { + 'whole_process_output': ('observability.py', ' configure_server()', ' pass'), + 'unexpected_failure_ownership': ( + 'runtime_boundary.py', "log.exception('request.failed', request_id=request_id)", + "log.exception('request.failed', request_id=request_id)\n" + " log.exception('duplicate.failure', request_id=request_id)"), + 'formatter_fallback_safety': ('safe_output.py', + 'if isinstance(value, float) and not math.isfinite(value):', + 'if False:'), + 'unexpected_500_correlation': ('runtime_boundary.py', + "message = {**message, 'headers': [*headers, (b'x-request-id', request_id.encode())]}", + 'message = message'), + } + for stack in STACKS: + for criterion, (filename, before, after) in mutations.items(): + with self.subTest(stack=stack, criterion=criterion): + with tempfile.TemporaryDirectory(dir=self.root) as temporary: + project = Path(temporary) / 'project' + with contextlib.redirect_stdout(io.StringIO()): + demo.create(stack, project) + (project / '.venv').symlink_to(Path(sys.prefix), target_is_directory=True) + repair(project, stack) + target = project / 'app' / filename + self.assertIn(before, target.read_text()) + target.write_text(target.read_text().replace(before, after)) + report = demo.check(project) + self.assertEqual([c['id'] for c in report['criteria'] if not c['passed']], + [criterion], report['criteria']) + def test_each_regression_is_detected_in_rendered_observations(self): spec = importlib.util.spec_from_file_location('grading_test', demo.DEMO / 'grading.py') grading = importlib.util.module_from_spec(spec) From 66cc30531a2070fcf014291b4f85b2536d240923 Mon Sep 17 00:00:00 2001 From: mrKazzila Date: Fri, 25 Sep 2026 14:07:05 +0300 Subject: [PATCH 08/12] docs: record runtime evaluator evidence and limitations --- evals/demo/README.md | 10 +- evals/demo/regressions/before-after.json | 134 +++++++++++++++++++++++ evals/demo/runtime-regressions.md | 121 ++++++++++++++++++++ evals/demo/template/README.md | 2 +- 4 files changed, 265 insertions(+), 2 deletions(-) create mode 100644 evals/demo/regressions/before-after.json create mode 100644 evals/demo/runtime-regressions.md diff --git a/evals/demo/README.md b/evals/demo/README.md index 949d270..60234c1 100644 --- a/evals/demo/README.md +++ b/evals/demo/README.md @@ -23,7 +23,7 @@ python3 scripts/demo.py check --project /tmp/logging-demo-stdlib --report /tmp/s Repeat with `--stack structlog` and a different project/report path. The initial check is expected to exit 1: the HTTP contract works, but logging defects are present. An improved project should exit 0. Exit 2 means a setup/probe error, not a failed logging criterion. Reports are created exclusively and are never overwritten; choose a new filename for each run. Setup errors are recorded with `passed: null` when a report can be created. -`check` executes the generated application's code in a subprocess using its `.venv`, with a 60-second timeout. It does not install dependencies or edit application files. This is process isolation, not an operating-system security sandbox. Both output streams are captured, and only synthetic credentials are used. +`check` executes the generated application's code using its `.venv`: the original ASGI probe has a 60-second timeout, and two fresh runtime subprocesses each have a 45-second timeout. It does not install dependencies or edit application files. This is process isolation, not an operating-system security sandbox. Both output streams are captured, and only synthetic credentials are used. The server probe requires permission to bind a loopback socket; a blocked socket is a setup error, never a passing result. ## What is measured @@ -36,6 +36,14 @@ The report includes dependency/Python versions, HTTP observations, rendered logs - No synthetic secrets anywhere in stdout or stderr, including exception rendering. - Correct correlation for overlapping requests and cleanup after successful, invalid, and failed requests. - Runtime use of the selected logging backend. This probe observes Python logging/structlog emission calls; it is not a general proof against adversarial code or dependency migration. +- Whole-process stdout/stderr from real Uvicorn startup, an unexpected HTTP failure, access logging, and shutdown: strict JSON `event`/`level` records and no exception/query sentinels. +- One failure owner across application and server output, including Uvicorn's raw exception fallback. +- Safe public-facade exception logging with a NaN structured field while stdlib diagnostic fallback is enabled; recovery logging must still work. +- HTTP 500 response correlation with application completion logs. Requiring a header on 500 follows this fixture's **each response** contract; it is not a universal framework rule. + +The real-server probe uses the documented Uvicorn import/configuration order, an OS-assigned loopback port, an explicit readiness event, and graceful shutdown. It adds an unexpected-failure route through FastAPI's public routing API (unwrapping outer ASGI `.app` wrappers where needed). It neither installs a sanitizing handler nor changes exception ownership in the application under evaluation. Separate metadata files keep actual process output, including direct file-descriptor writes, inside the grading boundary. + +See [runtime regression evidence and evaluator review](runtime-regressions.md) for the original worker's **11/11 → 11/15**, source mutation tests, positive controls, assumptions, and remaining gaps. Probe events are emitted outside the request in the same coroutine, so task teardown cannot mask missing cleanup. Concurrency is deterministic: the provider yields control without using timing delays or external services. diff --git a/evals/demo/regressions/before-after.json b/evals/demo/regressions/before-after.json new file mode 100644 index 0000000..31ca816 --- /dev/null +++ b/evals/demo/regressions/before-after.json @@ -0,0 +1,134 @@ +{ + "source": "Reviewed worker /private/tmp/logging-skill-review-20260925, re-run unchanged on 2026-09-25", + "versions": { + "python": "3.12.13", + "fastapi": "0.115.12", + "starlette": "0.46.2", + "pydantic": "2.13.5", + "httpx": "0.28.1", + "structlog": null, + "uvicorn": "0.34.2" + }, + "snapshot_sha256": { + "main.py": "bf20b85b386cab1b9d3069f24ab5ac65d216714763715d6708ff55c598b03521", + "middleware.py": "ed2d7a83317fff5cfac2d9e65655cac416c35d16bdaca2a4e89d4eb14667962f", + "observability.py": "8aa000e5fb01cbaec2cf6b477d21c2c5c0d96eeca7f3df0e44817225dac78400", + "service.py": "c1f71420735c02a04bfffcb9b0c282974f8c62f11300b7a2d0219c3ac267dd09" + }, + "before": { + "passed": true, + "passed_checks": 11, + "total_checks": 11, + "exit_code": 0 + }, + "after": { + "passed": false, + "passed_checks": 11, + "total_checks": 15, + "exit_code": 1, + "criteria": [ + { + "id": "json_output", + "passed": true + }, + { + "id": "http_contract", + "passed": true + }, + { + "id": "provider_behavior", + "passed": true + }, + { + "id": "event_contracts", + "passed": true + }, + { + "id": "stable_events", + "passed": true + }, + { + "id": "structured_fields", + "passed": true + }, + { + "id": "single_failure_traceback", + "passed": true + }, + { + "id": "no_secrets", + "passed": true + }, + { + "id": "request_isolation", + "passed": true + }, + { + "id": "context_cleanup", + "passed": true + }, + { + "id": "original_stack", + "passed": true + }, + { + "id": "whole_process_output", + "passed": false + }, + { + "id": "unexpected_failure_ownership", + "passed": false + }, + { + "id": "formatter_fallback_safety", + "passed": false + }, + { + "id": "unexpected_500_correlation", + "passed": false + } + ] + }, + "runtime_evidence": { + "whole_process_output": { + "records": 4, + "leaked_markers": [ + "TEST_SECRET_UNEXPECTED_9B4462D3B59449AE9DBC157BC7645A43", + "TEST_SECRET_QUERY_4F1997048BE44E3AAA4986A9E8E5B175" + ], + "malformed_line_count": 57, + "selected_output_lines": [ + "INFO: 127.0.0.1:64869 - \"GET /__evaluation_unexpected__?credential=TEST_SECRET_QUERY_4F1997048BE44E3AAA4986A9E8E5B175 HTTP/1.1\" 500 Internal Server Error", + "RuntimeError: TEST_SECRET_UNEXPECTED_9B4462D3B59449AE9DBC157BC7645A43" + ] + }, + "unexpected_failure_ownership": { + "error_records": 1, + "raw_server_errors": 1 + }, + "formatter_fallback_safety": { + "raised": null, + "unsafe_markers": [ + "TEST_SECRET_FORMATTER_013BE1730DCF405BA1C80973CFC2174C", + "--- Logging error ---", + "FORMATTER_SOURCE_SENTINEL" + ], + "records": 1, + "malformed_line_count": 35, + "selected_output_lines": [ + "--- Logging error ---", + "RuntimeError: TEST_SECRET_FORMATTER_013BE1730DCF405BA1C80973CFC2174C", + " log.exception('demo.serialization', measurement=float('nan')) # FORMATTER_SOURCE_SENTINEL" + ] + }, + "unexpected_500_correlation": { + "status": 500, + "response_request_id": null, + "expected_request_id": "req-unexpected-524c4608f7d147ddbb63192ff416e8c0", + "correlated_events": [ + "request.failed", + "request.completed" + ] + } + } +} diff --git a/evals/demo/runtime-regressions.md b/evals/demo/runtime-regressions.md new file mode 100644 index 0000000..4f18446 --- /dev/null +++ b/evals/demo/runtime-regressions.md @@ -0,0 +1,121 @@ +# Runtime regression coverage + +## Changes made / failure mapping + +All four checks run from `scripts/demo.py check`; implementation is in +`runtime_probe.py` and `grading.py`. Regression test names below are in +`../../tests/demo/test_demo.py`. + +| Criterion / test | Observable behavior | Why the old evaluator missed it | +| --- | --- | --- | +| `whole_process_output` / `test_reviewed_worker_whole_process_output` | Both actual process streams, including Uvicorn startup/error/access/shutdown, contain only JSON event/level objects and neither unique exception nor query secret. | ASGITransport never exercised Uvicorn handlers or access logging. | +| `unexpected_failure_ownership` / `test_reviewed_worker_duplicate_failure_ownership` | One error/critical event across application and server; raw Uvicorn exception reports also count. | Only handled provider failures and application output were checked. | +| `formatter_fallback_safety` / `test_reviewed_worker_formatter_fallback` | Public `log.exception` with NaN during an active secret-bearing exception neither raises nor produces raw diagnostics, secret, local sentinel, source marker, or invalid JSON. A following public info call still renders. | Normal structured fields did not make the JSON encoder fail; logging.handleError was never exercised. | +| `unexpected_500_correlation` / `test_reviewed_worker_unexpected_500_correlation` | Actual HTTP 500 carries the supplied request ID, matching application `request.completed` with status 500. | Handled 503 and validation 422 did not exercise the outer framework error middleware. | + +The fixture already promises JSON logs, no credentials in rendered exceptions, +one failure owner, and a request ID on **each response**. These checks enforce +those contracts; they do not introduce a universal rule that all frameworks must +add correlation headers to 500s. No skill instructions or production code were +changed. Corrections live exclusively in held-out reference fixtures and temporary +test projects. + +## Before / After + +The actual reviewed project was still available at +`/private/tmp/logging-skill-review-20260925`. It was re-evaluated unchanged before +editing the evaluator, then with the new checks: + +| Implementation | Evaluator | Result | +| --- | --- | --- | +| Reviewed stdlib worker | Original | **11/11**, passed=true, exit 0 | +| Same worker | Extended | **11/15**, passed=false, exit 1 | +| Temporary minimally corrected worker | Extended | **15/15** | +| Positive reference, stdlib and structlog | Extended | **15/15** on each | + +The compact machine-readable evidence is in +[`regressions/before-after.json`](regressions/before-after.json). Full local +reports were saved under `/tmp/logging-harness-evidence/before.json` and +`/tmp/logging-harness-evidence/after-runtime.json`; these temporary paths are not +required by the tests. The intentionally defective worker snapshot is preserved +in `regressions/reviewed_worker`, with hashes in the evidence file. + +Observed failures on the unchanged worker: + +- Both unique sentinels appeared: exception text in `uvicorn.error`, query in + `uvicorn.access`. Plain Uvicorn records also violated the JSON contract. +- One application error plus one raw Uvicorn error reported the same request. +- NaN passed normalization but failed `json.dumps(..., allow_nan=False)`. + stdlib printed `--- Logging error ---`, the original exception secret, and + `FORMATTER_SOURCE_SENTINEL` from the public logging call's source line. +- HTTP status was 500; the response header was absent, while application failure + and completion records carried the expected request ID. + +`test_minimal_reviewed_worker_repairs_pass` verifies a corrected temporary copy. +`test_reference_repairs_pass_every_criterion` covers both supported backends. +`test_independent_runtime_source_regressions` then independently breaks server +configuration, failure ownership, finite-value normalization, and the outer +response header. For each backend and mutation, **only the corresponding new +criterion fails**. Thus the four checks are not aliases for one broad failure. + +## Evaluator quality review + +- **Implementation coupling:** the evaluator calls the documented logging facade, + imports the public app, and registers an HTTP route using FastAPI's routing API. + It does not call `_safe`, a formatter class, or application middleware internals. + Private names occur only in a test-local patch of the frozen worker snapshot. + An outer wrapper must expose its wrapped app through `.app` to permit route + registration. Unsupported application shapes are setup errors, not passes. +- **Server fidelity:** real Uvicorn, h11, FastAPI/Starlette, lifespan, TCP, and an + HTTP client are exercised. Uvicorn configures logging before importing the app, + matching the documented CLI. No evaluator-installed redaction hides output. + stdout/stderr are captured at the subprocess boundary; metadata uses a separate + file. Cross-stream ordering is not assumed. +- **Timing/flakiness:** an explicit startup event replaces sleeps and polling; + port 0 avoids a fixed-port race. The client, server coroutine, and subprocess + have bounded timeouts. Shutdown completes before output is graded. Extreme CI + slowness can still cause setup failures, which are reported as inconclusive. +- **Platform:** no shell server process, Unix signal, or fixed executable path is + needed. Sandbox environments must permit loopback binding. Existing maintainer + tests use virtualenv symlinks and may need privileges on Windows. This run + verified macOS; Windows was not tested. +- **False positives:** JSON event/level and each-response headers are explicit + fixture contracts. No particular exception formatting, private function names, + arbitrary-object stringification, or access-event name is prescribed. Safe + disabling of access logs is allowed. Server lifecycle prose is rejected because + this fixture promises JSON output throughout the process. +- **False negatives:** finite normalization or a safe fallback/drop may pass; + formatter safety does not promise delivery of the failed event, but recovery + logging must work. Error ownership recognizes JSON error/critical levels and + pinned Uvicorn's raw ASGI-error banner. Adversarial relabeling/dropping, alternate + encodings of secrets, unrelated sink files, and custom background processes are + outside this check. Unique per-run secrets prevent fixed-string redaction from + appearing sufficient, but synthetic markers are not a general secret detector. +- **Duplication:** the old criteria remain separate for comparability. Runtime + format/secrets, ownership, fallback, and correlation have distinct evidence and + isolated source mutation controls. One real defect may legitimately violate + several contracts; results are not statistically independent scores. + +## Final assessment + +The evaluation now closes the real-server output boundary, formatter diagnostic +fallback, and framework-generated 500 correlation gaps. Updating `SKILL.md` is +not necessary to enforce these existing rules. + +Remaining risks include non-h11 protocols, multiple workers, streaming responses +that fail after headers/body start, background tasks, exception groups/chains, +other nonserializable fields, production `logging.raiseExceptions=False`, and +application-specific logging launch configurations. Startup failures are setup +errors rather than scored logging failures. + +Next high-value improvements: + +1. Exercise streaming/background-task errors and cancellation through real server + pipelines, with explicit ownership and post-response semantics. +2. Add a serialization matrix (Infinity, nested fields, unsupported objects, + exception chains/groups) and both stdlib diagnostic modes. +3. Extend concurrent real-HTTP correlation tests to generated IDs and nested + context restoration, plus supported worker/protocol configurations. + +Reproduce maintained checks with `just demo-test`. No commits are made by these +checks or by this change. diff --git a/evals/demo/template/README.md b/evals/demo/template/README.md index cd4df91..b1924c3 100644 --- a/evals/demo/template/README.md +++ b/evals/demo/template/README.md @@ -13,7 +13,7 @@ python3 -m venv .venv .venv/bin/python -m uvicorn app.main:app --host 127.0.0.1 --port 8000 ``` -On Windows use `.venv\Scripts\python.exe`. The server is optional: contract and external evaluation tests use an in-process ASGI transport. Interactive API documentation is at `http://127.0.0.1:8000/docs`. +On Windows use `.venv\Scripts\python.exe`. Starting the server manually is optional: the external evaluator starts its own temporary loopback Uvicorn server as well as using an in-process ASGI transport. Interactive API documentation is at `http://127.0.0.1:8000/docs`. ## Existing contracts From a6e0f1c58a64c7cf0801efed2c0cccb6888876f7 Mon Sep 17 00:00:00 2001 From: mrKazzila Date: Fri, 25 Sep 2026 16:55:34 +0300 Subject: [PATCH 09/12] refactor: streamline logging skill and clarify runtime safety --- .../skills/python-structured-logging/SKILL.md | 158 +++---------- .../agents/openai.yaml | 2 +- .../examples/stdlib/bad.py | 28 +-- .../examples/stdlib/good.py | 27 +-- .../examples/structlog/bad.py | 22 +- .../examples/structlog/good.py | 30 +-- .../references/Python Logging Style Guide.md | 216 +----------------- .../references/context-lifecycle.md | 9 + .../exceptions-and-sensitive-data.md | 7 + .../references/output-pipeline.md | 11 + .../skills/python-structured-logging/SKILL.md | 65 +++--- .../references/Python Logging Style Guide.md | 37 +-- .../references/context-lifecycle.md | 9 + .../exceptions-and-sensitive-data.md | 7 + .../references/output-pipeline.md | 11 + 15 files changed, 163 insertions(+), 476 deletions(-) create mode 100644 .agents/skills/python-structured-logging/references/context-lifecycle.md create mode 100644 .agents/skills/python-structured-logging/references/exceptions-and-sensitive-data.md create mode 100644 .agents/skills/python-structured-logging/references/output-pipeline.md create mode 100644 plugins/python-structured-logging/skills/python-structured-logging/references/context-lifecycle.md create mode 100644 plugins/python-structured-logging/skills/python-structured-logging/references/exceptions-and-sensitive-data.md create mode 100644 plugins/python-structured-logging/skills/python-structured-logging/references/output-pipeline.md diff --git a/.agents/skills/python-structured-logging/SKILL.md b/.agents/skills/python-structured-logging/SKILL.md index f79bdbf..fc05f82 100644 --- a/.agents/skills/python-structured-logging/SKILL.md +++ b/.agents/skills/python-structured-logging/SKILL.md @@ -1,147 +1,49 @@ --- name: python-structured-logging -description: Use when reviewing or changing Python logging behavior, including structlog, stdlib logging, event naming, structured fields, bound context, exception logging, correlation IDs, or sensitive-data-safe observability. +description: Review or improve Python logging with structlog, stdlib logging, or existing wrappers. Use for logging changes, not unrelated Python refactoring. --- # Python Structured Logging -## Core Rule +Make logs useful operational events while preserving the user's scope and project contracts. -Logs are operational events, not developer diary entries. +## Scope and contracts -## Workflow +- Review requests need findings with locations and concrete effects, not edits. +- Inspect the logger API, formatter/processors, event conventions, and failure ownership. Keep the stack and wrappers; migration requires authorization. +- Preserve business behavior, signatures, exception propagation, and retry decisions. +- Event names and fields may feed alerts, dashboards, and queries. Preserve existing contracts, including dotted names. Before an authorized rename, inspect available consumers and explain their updates; report external consumers you cannot verify. +- With no existing convention, use stable `snake_case` events such as `invoice_processed` and put variable values in fields. Follow existing field names; give new units explicit keys such as `duration_ms`. +- Replace diagnostic prints only in scope; preserve intentional CLI output. -1. Inspect the current stack first: `structlog`, stdlib `logging`, or a project wrapper. -2. Preserve the current direction unless it is harmful or migration was explicitly requested. -3. If the project uses stdlib `logging` intentionally, improve message shape and `extra` fields instead of forcing `structlog`. -4. Replace prose or dynamic event names with stable `snake_case` events. -5. Move variable data into structured fields and bind shared context once near the request or job boundary. -6. Keep one meaningful exception log at the layer that owns the failure, with a traceback when needed. -7. Remove or redact sensitive data before it reaches bound context or payload fields. -8. Verify output shape, levels, and noise after the change. +## API and selective reading -## Event Naming +Read the matching example pair for substantial refactoring, integration setup, or API uncertainty. Simple field additions and local reviews do not require examples. -- Use stable `snake_case` event names. -- Prefer action or action-plus-result names such as `invoice_processed` or `broker_publish_failed`. -- Do not put IDs, emails, statuses, or exception text into the event name. -- Do not use generic events such as `error`, `failed`, or `something_went_wrong` without the operation name. +- **structlog:** keyword fields and a locally bound logger; [good](examples/structlog/good.py), [bad](examples/structlog/bad.py). +- **stdlib:** `extra` or existing adapters; no arbitrary keyword fields or `.bind()`. Avoid reserved LogRecord keys. The formatter must emit added attributes; [good](examples/stdlib/good.py), [bad](examples/stdlib/bad.py). +- **Wrappers:** inspect their interface and output before adapting either pattern. -Good: +Read only the relevant reference when: -```python -logger.info("invoice_processed", invoice_id=invoice_id, duration_ms=duration_ms) -logger.warning("retry_scheduled", attempt=attempt, delay_seconds=delay_seconds) -``` +- Changing formatters/processors, diagnosing missing fields, serialization, or duplicate handlers: [output pipeline](references/output-pipeline.md). +- Working with cross-module or concurrent context or cleanup: [context lifecycle](references/context-lifecycle.md). +- Resolving failure ownership or sanitizing exception output: [exceptions and sensitive data](references/exceptions-and-sensitive-data.md). -Bad: +## Context, exceptions, and noise -```python -logger.info(f"invoice {invoice_id} processed in {duration_ms} ms") -logger.error(f"publish failed for order {order_id}") -logger.info(f"user_{user_id}_updated") -``` +- Bind/inject shared context at request/job boundaries where supported; repeating `extra` is acceptable. A local `.bind()` does not enrich independent loggers. Clean up scoped context on success and failure without leaking between operations. +- Allowlist needed payload fields before binding. Never log credentials, tokens, authorization headers, or raw sensitive payloads. Identifiers and payment-derived fields still require the project's data policy; masking is not blanket permission. +- Log a failure once at the layer owning its operational outcome. Lower layers may propagate without logging. Use `logger.exception(...)` inside `except` when a traceback is appropriate; preserve control flow and derive retryability from the real policy. +- Exception messages and tracebacks can expose secrets despite safe fields. Inspect rendered output and use the existing sanitization path. +- Follow project levels: `INFO` for outcomes, `DEBUG` for optional diagnostics, `WARNING` for actionable degradation, `ERROR` for failed operations needing attention. Avoid per-item noise and redundant boundaries; retain useful progress for stalled or long-running work. -## Fields and Context +## Verify -- Use stable field names such as `request_id`, `correlation_id`, `job_id`, `user_id`, `entity_id`, `status`, and `duration_ms` when they are relevant. -- Bind shared context once when possible instead of passing the same fields manually everywhere. -- Keep units in the key name: `duration_ms`, `delay_seconds`, `size_bytes`. -- Avoid renaming the same concept across modules. -- Prefer allowlisted payload fragments such as `{"amount_cents": ..., "card_last4": ...}` over raw payload logging. +Use focused tests/output capture proportional to the change, through the complete configured runtime output boundary (see [output pipeline](references/output-pipeline.md)): -Good: +- Contracts and application behavior preserved; fields survive formatting without API errors. +- One appropriate failure record, with traceback when needed; no sensitive values in fields, messages, or rendered exceptions. +- Request/job context isolated and cleaned up. -```python -log = logger.bind(request_id=request_id, job_id=job_id) -log.info("job_started", task_name=task_name) -``` - -Bad: - -```python -logger.info("job started", extra={"req": request_id, "job": job_id}) -logger.info("job_started", request_id=request_id, job_id=job_id) -logger.info("job_finished", request_id=request_id, job_id=job_id) -``` - -## Exception Logging - -- Use `logger.exception(...)` inside `except` when you need the traceback. -- Use `exc_info=True` only when the logger API requires it. -- Do not log and swallow unless that behavior is intentional and the caller does not need the failure. -- Do not duplicate the same exception log at every layer. -- Do not use `logger.error(str(exc))` as the only exception log for unexpected failures. - -Good: - -```python -try: - send_invoice(invoice) -except ProviderTimeoutError: - logger.exception("invoice_send_failed", invoice_id=invoice.id, retryable=True) - raise -``` - -Bad: - -```python -try: - send_invoice(invoice) -except Exception as exc: - logger.error(f"invoice failed: {exc}") -``` - -## Sensitive Data - -- Never log passwords, tokens, API keys, cookies, authorization headers, private keys, or raw secrets. -- Never log raw request bodies, raw response bodies, session data, personal data, or payment data unless the user explicitly asks for a safe, scoped format. -- Prefer allowlisted fields over blocklists when logging payload-derived data. -- Redact at boundaries before binding context. - -Good: - -```python -safe_payment = { - "card_last4": payment.card_last4, - "amount_cents": payment.amount_cents, -} -logger.info("payment_authorized", payment=safe_payment) -``` - -Bad: - -```python -logger.info("payment_authorized", payload=payment_payload, auth_header=auth_header) -``` - -## Noise Control - -- `INFO` for business or operational events that matter. -- `DEBUG` for local diagnostics that can be turned off safely. -- `WARNING` for degraded but handled situations such as retries or fallbacks. -- `ERROR` for failed operations that need attention. -- Avoid logs inside tight loops unless they are sampled or aggregated. -- Remove `started` and `finished` chatter unless the boundary is operationally meaningful. -- Prefer one outcome log over multiple step-by-step logs when the extra detail does not change operator action. - -## Bundled Resources - -- [`examples/structlog/good.py`](examples/structlog/good.py) -- [`examples/structlog/bad.py`](examples/structlog/bad.py) -- [`examples/stdlib/good.py`](examples/stdlib/good.py) -- [`examples/stdlib/bad.py`](examples/stdlib/bad.py) -- [`references/Python Logging Style Guide.md`](references/Python Logging Style Guide.md) - -- Read the examples that match the stack already in use. -- Read the reference guide when you need human-oriented rationale, level guidance, or migration examples. - -## Verification Checklist - -- Current logging style is preserved or intentionally migrated. -- Event names are stable and `snake_case`. -- Variable data is in fields, not prose strings. -- Shared context is bound or injected once where the stack supports it. -- Exceptions include stack traces where needed. -- Sensitive data is redacted or omitted. -- Output still fits the project's log pipeline. +Report checks performed and unverified pipeline assumptions. diff --git a/.agents/skills/python-structured-logging/agents/openai.yaml b/.agents/skills/python-structured-logging/agents/openai.yaml index 38d5a20..7655245 100644 --- a/.agents/skills/python-structured-logging/agents/openai.yaml +++ b/.agents/skills/python-structured-logging/agents/openai.yaml @@ -1,4 +1,4 @@ interface: display_name: "Python Structured Logging" short_description: "Practical guidance for safer, more useful Python logs" - default_prompt: "Use $python-structured-logging to inspect the current Python logging stack, tighten event names and fields, and improve exception logging without forcing an unnecessary migration." + default_prompt: "Use $python-structured-logging to review Python logging, report concrete findings, and preserve the existing stack and event contracts. Apply changes only when requested." diff --git a/.agents/skills/python-structured-logging/examples/stdlib/bad.py b/.agents/skills/python-structured-logging/examples/stdlib/bad.py index 184ccfa..e582354 100644 --- a/.agents/skills/python-structured-logging/examples/stdlib/bad.py +++ b/.agents/skills/python-structured-logging/examples/stdlib/bad.py @@ -1,30 +1,24 @@ import logging - logger = logging.getLogger(__name__) +class PaymentGatewayError(RuntimeError): + pass + + def process_invoice( invoice_id: str, customer_id: str, request_id: str, attempt: int, - payment_payload: dict, + amount_cents: int, ) -> None: - print("starting invoice processing", invoice_id, customer_id, request_id) - logger.info( - f"processing invoice {invoice_id} for customer {customer_id} attempt={attempt}" - ) - try: - logger.info( - f"invoice_{invoice_id}_processed", - extra={ - "payload": payment_payload, - "request": request_id, - "authorization_header": "Bearer secret-token", - }, - ) - except Exception as exc: + if amount_cents < 0: + raise PaymentGatewayError("negative amount") + + logger.info(f"invoice_{invoice_id}_processed for customer {customer_id} request={request_id} attempt={attempt}") + except PaymentGatewayError as exc: logger.error(f"invoice processing failed for {invoice_id}: {exc}") - return + raise diff --git a/.agents/skills/python-structured-logging/examples/stdlib/good.py b/.agents/skills/python-structured-logging/examples/stdlib/good.py index 80153df..30e4107 100644 --- a/.agents/skills/python-structured-logging/examples/stdlib/good.py +++ b/.agents/skills/python-structured-logging/examples/stdlib/good.py @@ -1,6 +1,5 @@ import logging - logger = logging.getLogger(__name__) @@ -15,36 +14,18 @@ def process_invoice( attempt: int, amount_cents: int, ) -> None: - shared_context = { + # This operation owns the failure record; callers propagate without logging. + context = { "request_id": request_id, "invoice_id": invoice_id, "customer_id": customer_id, "attempt": attempt, } - safe_payment = { - "amount_cents": amount_cents, - "card_last4": "4242", - } - try: if amount_cents < 0: raise PaymentGatewayError("negative amount") - logger.info( - "invoice_processed", - extra={ - **shared_context, - "status": "success", - "payment": safe_payment, - }, - ) + logger.info("invoice_processed", extra={**context, "amount_cents": amount_cents}) except PaymentGatewayError: - logger.exception( - "invoice_processing_failed", - extra={ - **shared_context, - "retryable": True, - "payment": safe_payment, - }, - ) + logger.exception("invoice_processing_failed", extra={**context, "retryable": False}) raise diff --git a/.agents/skills/python-structured-logging/examples/structlog/bad.py b/.agents/skills/python-structured-logging/examples/structlog/bad.py index 3b6f5c3..3a23c9c 100644 --- a/.agents/skills/python-structured-logging/examples/structlog/bad.py +++ b/.agents/skills/python-structured-logging/examples/structlog/bad.py @@ -1,26 +1,24 @@ import structlog - logger = structlog.get_logger(__name__) +class PaymentGatewayError(RuntimeError): + pass + + def process_invoice( invoice_id: str, customer_id: str, request_id: str, attempt: int, - payment_payload: dict, + amount_cents: int, ) -> None: try: - logger.info( - f"starting invoice processing for invoice={invoice_id}, customer={customer_id}, request={request_id}" - ) - logger.info( - f"invoice_{invoice_id}_processed", - payload=payment_payload, - attempt=attempt, - authorization_header="Bearer secret-token", - ) - except Exception as exc: + if amount_cents < 0: + raise PaymentGatewayError("negative amount") + + logger.info(f"invoice_{invoice_id}_processed for customer {customer_id} request={request_id} attempt={attempt}") + except PaymentGatewayError as exc: logger.error(f"invoice processing failed for {invoice_id}: {exc}") raise diff --git a/.agents/skills/python-structured-logging/examples/structlog/good.py b/.agents/skills/python-structured-logging/examples/structlog/good.py index 8e7fb07..043d003 100644 --- a/.agents/skills/python-structured-logging/examples/structlog/good.py +++ b/.agents/skills/python-structured-logging/examples/structlog/good.py @@ -1,6 +1,5 @@ import structlog - logger = structlog.get_logger(__name__) @@ -15,30 +14,19 @@ def process_invoice( attempt: int, amount_cents: int, ) -> None: - log = logger.bind( - request_id=request_id, - invoice_id=invoice_id, - customer_id=customer_id, - attempt=attempt, - ) - safe_payment = { - "amount_cents": amount_cents, - "card_last4": "4242", + # This operation owns the failure record; callers propagate without logging. + context = { + "request_id": request_id, + "invoice_id": invoice_id, + "customer_id": customer_id, + "attempt": attempt, } - + log = logger.bind(**context) try: if amount_cents < 0: raise PaymentGatewayError("negative amount") - log.info( - "invoice_processed", - status="success", - payment=safe_payment, - ) + log.info("invoice_processed", amount_cents=amount_cents) except PaymentGatewayError: - log.exception( - "invoice_processing_failed", - retryable=True, - payment=safe_payment, - ) + log.exception("invoice_processing_failed", retryable=False) raise diff --git a/.agents/skills/python-structured-logging/references/Python Logging Style Guide.md b/.agents/skills/python-structured-logging/references/Python Logging Style Guide.md index 517d384..6fa2b2b 100644 --- a/.agents/skills/python-structured-logging/references/Python Logging Style Guide.md +++ b/.agents/skills/python-structured-logging/references/Python Logging Style Guide.md @@ -1,210 +1,14 @@ -# Python Logging Style Guide +# Python Logging Integration Notes -Use this reference when you need human-oriented guidance for reviewing or improving logs in Python code. The skill file is the execution checklist; this guide adds rationale, examples, and migration patterns. Prefer `structlog` when the project already uses it, and keep stdlib `logging` when the project intentionally standardized on it. +Shared scope, event contracts, and naming rules live in [SKILL.md](../SKILL.md). +Read only the reference needed for the current change: -## Core Rules +- [Output pipeline](output-pipeline.md): formatter/processor changes, missing fields, serialization, or duplicate handlers. +- [Context lifecycle](context-lifecycle.md): cross-module context, concurrent requests/jobs, or cleanup. +- [Exceptions and sensitive data](exceptions-and-sensitive-data.md): failure ownership or sanitizing rendered exceptions. -- Treat each log as an operational event. -- Keep event names short, stable, and in `snake_case`. -- Put variable data into fields, not interpolated prose. -- Bind shared context once when possible. -- Preserve stack traces for unexpected failures. -- Redact sensitive data before it reaches logs. -- Keep debug noise on a short leash. +## Sources -## Event Naming - -Prefer event names like: - -```python -"invoice_processed" -"retry_scheduled" -"broker_publish_failed" -``` - -Avoid event names like: - -```python -"Invoice processed successfully!" -f"invoice_{invoice_id}_processed" -"something went wrong" -``` - -Good: - -```python -logger.info("invoice_processed", invoice_id=invoice_id, duration_ms=duration_ms) -``` - -Bad: - -```python -logger.info(f"invoice {invoice_id} processed in {duration_ms} ms") -``` - -## Field Naming Conventions - -Use stable `snake_case` field names and explicit units. - -Preferred fields: - -```text -request_id -correlation_id -job_id -user_id -entity_id -status -reason -error_code -duration_ms -delay_seconds -size_bytes -attempt -max_attempts -``` - -Guidelines: - -- One concept should keep one name across the project. -- IDs should normally end with `_id`. -- Units belong in the key name, not only in the value. -- Avoid repeating the same shared fields on every log if the stack supports binding or adapters. - -When logging payload-derived data, prefer allowlisted fragments over whole payloads. For example, log `card_last4`, `amount_cents`, or `item_count`, not the raw request body. - -## Level Guide - -- `DEBUG`: local diagnostics and temporary deep inspection. -- `INFO`: expected business or operational events. -- `WARNING`: degraded but handled situations such as retries or fallbacks. -- `ERROR`: a concrete operation failed and needs attention. -- `CRITICAL`: service-threatening state or probable data-loss scenario. - -Do not log every function entry and exit at `INFO`. Use `DEBUG` sparingly, and only when the details are actionable. - -## Exception Logging - -Use `logger.exception(...)` inside `except` when you need traceback data. - -Good: - -```python -try: - publish(message) -except ProviderTimeoutError: - logger.exception("publish_failed", message_id=message_id, retryable=True) - raise -``` - -Bad: - -```python -try: - publish(message) -except Exception as exc: - logger.error(f"publish failed: {exc}") -``` - -Rules: - -- Do not log and swallow unless that is the intended control flow. -- Do not duplicate the same exception log at every layer. -- Add enough context for operators to know what failed and whether it will retry. -- Avoid `logger.error(str(exc))` as the only record for an unexpected failure. - -## Sensitive Data - -Never log: - -- passwords -- tokens -- API keys -- cookies -- authorization headers -- private keys -- raw secrets -- raw request bodies -- raw response bodies -- session data -- personal data -- payment data -- raw payloads containing PII or credentials - -Prefer allowlisted payload logging. - -Good: - -```python -logger.info( - "payment_authorized", - payment={"amount_cents": amount_cents, "card_last4": card_last4}, -) -``` - -Bad: - -```python -logger.info("payment_authorized", payload=payment_payload, auth_header=auth_header) -``` - -## structlog and stdlib Patterns - -`structlog`: - -```python -log = logger.bind(request_id=request_id, job_id=job_id) -log.info("job_started", task_name=task_name) -``` - -Stdlib `logging`: - -```python -logger.info( - "job_started", - extra={"request_id": request_id, "job_id": job_id, "task_name": task_name}, -) -``` - -In both styles, keep the event name stable and treat the surrounding fields as the query surface. If a downstream formatter or adapter already shapes the record, follow that path instead of inventing a parallel one. - -## Migration Notes - -From `print` debugging: - -```python -print("processing invoice", invoice_id) -``` - -To structured logging: - -```python -logger.debug("invoice_processing", invoice_id=invoice_id) -``` - -From prose logging: - -```python -logger.info(f"user {user_id} updated account status to {status}") -``` - -To structured events: - -```python -logger.info("account_status_updated", user_id=user_id, status=status) -``` - -From repeated manual context: - -```python -logger.info("step_one", request_id=request_id, user_id=user_id) -logger.info("step_two", request_id=request_id, user_id=user_id) -``` - -To bound context: - -```python -log = logger.bind(request_id=request_id, user_id=user_id) -log.info("step_one") -log.info("step_two") -``` +- [Python logging API](https://docs.python.org/3/library/logging.html) +- [Python logging cookbook](https://docs.python.org/3/howto/logging-cookbook.html) +- [structlog context variables](https://www.structlog.org/en/stable/contextvars.html) diff --git a/.agents/skills/python-structured-logging/references/context-lifecycle.md b/.agents/skills/python-structured-logging/references/context-lifecycle.md new file mode 100644 index 0000000..385cb12 --- /dev/null +++ b/.agents/skills/python-structured-logging/references/context-lifecycle.md @@ -0,0 +1,9 @@ +# Context lifecycle + +`logger.bind(...)` returns a logger with additional context; pass that logger to code that needs it. It does not automatically enrich independent loggers elsewhere. + +For a structlog application already using contextvars, check that `merge_contextvars` is in the processor chain. Clear context at the start of a request/job, then bind its identifiers. Reset or clear context when the operation ends, including failure paths. Use scoped binding/token reset for nested operations that must restore parent context instead of clearing it. + +Test two overlapping requests with distinct IDs and a subsequent operation with no ID. Their outputs must not share identifiers. Thread/task boundaries and hybrid sync/async frameworks may require explicit propagation; do not assume every execution context shares the same values. + +For stdlib, retain the existing adapter, filter, or record factory. Check the supported Python version and adapter behavior before relying on per-call `extra` merging. diff --git a/.agents/skills/python-structured-logging/references/exceptions-and-sensitive-data.md b/.agents/skills/python-structured-logging/references/exceptions-and-sensitive-data.md new file mode 100644 index 0000000..127d3d7 --- /dev/null +++ b/.agents/skills/python-structured-logging/references/exceptions-and-sensitive-data.md @@ -0,0 +1,7 @@ +# Exception ownership and sensitive output + +Choose the owner based on the call chain: a request boundary, worker, or command may already record failures. Adding another exception log below it can duplicate alerts. If a lower layer owns the only failure record and propagates the exception, document that its caller must not log it again. + +`logger.exception` normally renders the exception message too. Allowlisting structured fields alone does not sanitize credentials embedded in a URL, exception text, or captured locals. Exercise the configured sanitizer with synthetic sensitive values and inspect its final output. Never use real secrets as fixtures. + +The paired examples use a non-retryable negative amount to illustrate preserved behavior. Both versions raise the same exception for the same input. The good version changes logging only; it does not add retry logic or invent payment metadata. diff --git a/.agents/skills/python-structured-logging/references/output-pipeline.md b/.agents/skills/python-structured-logging/references/output-pipeline.md new file mode 100644 index 0000000..da0cd06 --- /dev/null +++ b/.agents/skills/python-structured-logging/references/output-pipeline.md @@ -0,0 +1,11 @@ +# Output pipeline + +Stdlib `extra` adds attributes to a LogRecord; a default text formatter does not include arbitrary attributes. Inspect the project's formatter before claiming the output is structured. Preserve the existing handler configuration; reusable modules should not call `basicConfig()` or install root handlers. + +Use `extra={"invoice_id": invoice_id}` with stdlib, and `invoice_id=invoice_id` with structlog. Do not use reserved LogRecord keys such as `name`, `message`, or `levelname` as `extra` fields. Formatter-required fields must also be handled for third-party records that lack them. + +Capture the final rendered output as well as records. Check JSON decoding where JSON is the configured format, field types, exception rendering, and duplicate records from handler propagation. A test that only captures the pre-render event dictionary cannot establish downstream compatibility. + +At the application's configuration boundary, include framework/server/access/error/lifecycle loggers and the actual stdout/stderr or collector path, not just the application logger. Exercise an unexpected failure through that runtime: a safe application formatter is insufficient if another output path can emit raw data. Keep reusable modules free of global logging configuration. + +Formatter failure is part of this safety boundary. Probe non-finite numbers, unsupported objects and cyclic structured values through the public logging API, including stdlib `handleError`/diagnostic fallback. Use bounded safe normalization or a safe structured fallback: logging must not raise into application code, disclose the original exception/source through fallback, or emit invalid JSON when JSON is the output contract. Capture both streams and verify that a subsequent event still emits; silent record loss is not a successful fallback. diff --git a/plugins/python-structured-logging/skills/python-structured-logging/SKILL.md b/plugins/python-structured-logging/skills/python-structured-logging/SKILL.md index fccb1dc..fc05f82 100644 --- a/plugins/python-structured-logging/skills/python-structured-logging/SKILL.md +++ b/plugins/python-structured-logging/skills/python-structured-logging/SKILL.md @@ -5,52 +5,45 @@ description: Review or improve Python logging with structlog, stdlib logging, or # Python Structured Logging -Make logs useful operational events while preserving the user's scope and the project's contracts. +Make logs useful operational events while preserving the user's scope and project contracts. -## Scope and workflow +## Scope and contracts -- For review requests, report findings with file locations and concrete effects; edit only when requested. -- Inspect the existing logger API, formatter/processors, exception ownership, and event conventions before proposing changes. -- Keep the current stack and wrappers. If migration would help, explain why; do not migrate without authorization. -- Preserve business behavior, function signatures, exception propagation, and retry decisions during logging refactors. -- Treat existing event names and fields as contracts that may feed alerts, dashboards, and queries. Preserve them unless changing that contract is in scope. -- When no convention exists, use stable `snake_case` events such as `invoice_processed`; put variable values in fields. -- Replace diagnostic `print` calls only when in scope. Preserve intentional CLI output. +- Review requests need findings with locations and concrete effects, not edits. +- Inspect the logger API, formatter/processors, event conventions, and failure ownership. Keep the stack and wrappers; migration requires authorization. +- Preserve business behavior, signatures, exception propagation, and retry decisions. +- Event names and fields may feed alerts, dashboards, and queries. Preserve existing contracts, including dotted names. Before an authorized rename, inspect available consumers and explain their updates; report external consumers you cannot verify. +- With no existing convention, use stable `snake_case` events such as `invoice_processed` and put variable values in fields. Follow existing field names; give new units explicit keys such as `duration_ms`. +- Replace diagnostic prints only in scope; preserve intentional CLI output. -## Choose the matching API +## API and selective reading -Read only the examples for the project's stack: +Read the matching example pair for substantial refactoring, integration setup, or API uncertainty. Simple field additions and local reviews do not require examples. -- **structlog:** [good](examples/structlog/good.py), [bad](examples/structlog/bad.py). Use keyword fields and a locally bound logger. -- **stdlib logging:** [good](examples/stdlib/good.py), [bad](examples/stdlib/bad.py). Use `extra` or the existing adapter; arbitrary keyword fields and `.bind()` are not stdlib APIs. `extra` adds LogRecord attributes, but the formatter must emit them. Avoid reserved LogRecord keys. -- **Project wrappers:** inspect their interface and output before adapting either pattern. +- **structlog:** keyword fields and a locally bound logger; [good](examples/structlog/good.py), [bad](examples/structlog/bad.py). +- **stdlib:** `extra` or existing adapters; no arbitrary keyword fields or `.bind()`. Avoid reserved LogRecord keys. The formatter must emit added attributes; [good](examples/stdlib/good.py), [bad](examples/stdlib/bad.py). +- **Wrappers:** inspect their interface and output before adapting either pattern. -The example pairs have identical inputs and business behavior. Their operation owns the failure log; a caller must not log the same failure again. +Read only the relevant reference when: -## Fields and context +- Changing formatters/processors, diagnosing missing fields, serialization, or duplicate handlers: [output pipeline](references/output-pipeline.md). +- Working with cross-module or concurrent context or cleanup: [context lifecycle](references/context-lifecycle.md). +- Resolving failure ownership or sanitizing exception output: [exceptions and sensitive data](references/exceptions-and-sensitive-data.md). -- Follow existing field names. For new fields, use explicit units such as `duration_ms` and `size_bytes`. -- Bind or inject shared context at a meaningful request/job boundary where supported. Repeating `extra` is acceptable when it is simpler and correct. -- A locally bound structlog logger does not automatically attach context to every logger in a request. For cross-module or concurrent context, read the [context lifecycle guidance](references/Python%20Logging%20Style%20Guide.md#context-lifecycle). -- Allowlist necessary payload fields before binding them. Do not log credentials, tokens, authorization headers, or raw sensitive payloads. Identifiers and payment-derived fields still need the project's data policy; masking alone does not make them universally safe. +## Context, exceptions, and noise -## Exceptions and levels +- Bind/inject shared context at request/job boundaries where supported; repeating `extra` is acceptable. A local `.bind()` does not enrich independent loggers. Clean up scoped context on success and failure without leaking between operations. +- Allowlist needed payload fields before binding. Never log credentials, tokens, authorization headers, or raw sensitive payloads. Identifiers and payment-derived fields still require the project's data policy; masking is not blanket permission. +- Log a failure once at the layer owning its operational outcome. Lower layers may propagate without logging. Use `logger.exception(...)` inside `except` when a traceback is appropriate; preserve control flow and derive retryability from the real policy. +- Exception messages and tracebacks can expose secrets despite safe fields. Inspect rendered output and use the existing sanitization path. +- Follow project levels: `INFO` for outcomes, `DEBUG` for optional diagnostics, `WARNING` for actionable degradation, `ERROR` for failed operations needing attention. Avoid per-item noise and redundant boundaries; retain useful progress for stalled or long-running work. -- Identify the layer responsible for the final operational outcome. Log a failure once there; lower layers can propagate it without logging. -- Use `logger.exception(...)` inside `except` when a traceback is appropriate. Preserve the original control flow; do not introduce swallowing, re-raising, or retries merely to improve a log. -- Derive retryability from the real failure and retry policy, never from the presence of an exception. -- Tracebacks and exception messages can contain sensitive values even if structured fields are safe. Inspect the rendered output and use the existing sanitization path when needed. -- Use `INFO` for meaningful outcomes, `DEBUG` for optional diagnostics, `WARNING` for actionable degradation, and `ERROR` for failed operations needing attention, subject to project conventions. -- Avoid per-item loop noise and redundant boundary logs; retain start/progress events when they help diagnose long-running or stalled work. +## Verify -## Verify the result +Use focused tests/output capture proportional to the change, through the complete configured runtime output boundary (see [output pipeline](references/output-pipeline.md)): -Check a representative success and failure through the configured output pipeline: +- Contracts and application behavior preserved; fields survive formatting without API errors. +- One appropriate failure record, with traceback when needed; no sensitive values in fields, messages, or rendered exceptions. +- Request/job context isolated and cleaned up. -- Existing event/field contracts and application behavior are preserved. -- Fields survive formatting and serialization; no logger API errors occur. -- One appropriate failure record appears, with a traceback when needed. -- Sensitive values are absent from fields, messages, and rendered exceptions. -- Request/job context does not leak into another operation. - -Use focused tests or output capture proportional to the change. Report what was checked and any unverified pipeline assumptions. Read the [reference guide](references/Python%20Logging%20Style%20Guide.md) for formatter, context, and exception edge cases. +Report checks performed and unverified pipeline assumptions. diff --git a/plugins/python-structured-logging/skills/python-structured-logging/references/Python Logging Style Guide.md b/plugins/python-structured-logging/skills/python-structured-logging/references/Python Logging Style Guide.md index 93d2f4a..6fa2b2b 100644 --- a/plugins/python-structured-logging/skills/python-structured-logging/references/Python Logging Style Guide.md +++ b/plugins/python-structured-logging/skills/python-structured-logging/references/Python Logging Style Guide.md @@ -1,38 +1,11 @@ # Python Logging Integration Notes -Read the section relevant to the current stack or failure mode. Shared scope and naming rules live in `SKILL.md`. +Shared scope, event contracts, and naming rules live in [SKILL.md](../SKILL.md). +Read only the reference needed for the current change: -## Output pipeline - -Stdlib `extra` adds attributes to a LogRecord; a default text formatter does not include arbitrary attributes. Inspect the project's formatter before claiming the output is structured. Preserve the existing handler configuration; reusable modules should not call `basicConfig()` or install root handlers. - -Use `extra={"invoice_id": invoice_id}` with stdlib, and `invoice_id=invoice_id` with structlog. Do not use reserved LogRecord keys such as `name`, `message`, or `levelname` as `extra` fields. Formatter-required fields must also be handled for third-party records that lack them. - -Capture the final rendered output as well as records. Check JSON decoding where JSON is the configured format, field types, exception rendering, and duplicate records from handler propagation. A test that only captures the pre-render event dictionary cannot establish downstream compatibility. - -## Context lifecycle - -`logger.bind(...)` returns a logger with additional context; pass that logger to code that needs it. It does not automatically enrich independent loggers elsewhere. - -For a structlog application already using contextvars, check that `merge_contextvars` is in the processor chain. Clear context at the start of a request/job, then bind its identifiers. Reset or clear context when the operation ends, including failure paths. Use scoped binding/token reset for nested operations that must restore parent context instead of clearing it. - -Test two overlapping requests with distinct IDs and a subsequent operation with no ID. Their outputs must not share identifiers. Thread/task boundaries and hybrid sync/async frameworks may require explicit propagation; do not assume every execution context shares the same values. - -For stdlib, retain the existing adapter, filter, or record factory. Check the supported Python version and adapter behavior before relying on per-call `extra` merging. - -## Exception ownership and sensitive output - -Choose the owner based on the call chain: a request boundary, worker, or command may already record failures. Adding another exception log below it can duplicate alerts. If a lower layer owns the only failure record and propagates the exception, document that its caller must not log it again. - -`logger.exception` normally renders the exception message too. Allowlisting structured fields alone does not sanitize credentials embedded in a URL, exception text, or captured locals. Exercise the configured sanitizer with synthetic sensitive values and inspect its final output. Never use real secrets as fixtures. - -The paired examples use a non-retryable negative amount to illustrate preserved behavior. Both versions raise the same exception for the same input. The good version changes logging only; it does not add retry logic or invent payment metadata. - -## Event contracts and migration - -Before renaming an event, inspect repository-owned dashboards, alerts, queries, and tests when available. Keep existing conventions such as dotted events when the task does not authorize a schema migration. If downstream consumers are external and cannot be checked, report that limitation. - -For requested migrations, explain old-to-new names and consumer updates. Diagnostic prints can become logs; intentional CLI results must remain on the expected output stream. +- [Output pipeline](output-pipeline.md): formatter/processor changes, missing fields, serialization, or duplicate handlers. +- [Context lifecycle](context-lifecycle.md): cross-module context, concurrent requests/jobs, or cleanup. +- [Exceptions and sensitive data](exceptions-and-sensitive-data.md): failure ownership or sanitizing rendered exceptions. ## Sources diff --git a/plugins/python-structured-logging/skills/python-structured-logging/references/context-lifecycle.md b/plugins/python-structured-logging/skills/python-structured-logging/references/context-lifecycle.md new file mode 100644 index 0000000..385cb12 --- /dev/null +++ b/plugins/python-structured-logging/skills/python-structured-logging/references/context-lifecycle.md @@ -0,0 +1,9 @@ +# Context lifecycle + +`logger.bind(...)` returns a logger with additional context; pass that logger to code that needs it. It does not automatically enrich independent loggers elsewhere. + +For a structlog application already using contextvars, check that `merge_contextvars` is in the processor chain. Clear context at the start of a request/job, then bind its identifiers. Reset or clear context when the operation ends, including failure paths. Use scoped binding/token reset for nested operations that must restore parent context instead of clearing it. + +Test two overlapping requests with distinct IDs and a subsequent operation with no ID. Their outputs must not share identifiers. Thread/task boundaries and hybrid sync/async frameworks may require explicit propagation; do not assume every execution context shares the same values. + +For stdlib, retain the existing adapter, filter, or record factory. Check the supported Python version and adapter behavior before relying on per-call `extra` merging. diff --git a/plugins/python-structured-logging/skills/python-structured-logging/references/exceptions-and-sensitive-data.md b/plugins/python-structured-logging/skills/python-structured-logging/references/exceptions-and-sensitive-data.md new file mode 100644 index 0000000..127d3d7 --- /dev/null +++ b/plugins/python-structured-logging/skills/python-structured-logging/references/exceptions-and-sensitive-data.md @@ -0,0 +1,7 @@ +# Exception ownership and sensitive output + +Choose the owner based on the call chain: a request boundary, worker, or command may already record failures. Adding another exception log below it can duplicate alerts. If a lower layer owns the only failure record and propagates the exception, document that its caller must not log it again. + +`logger.exception` normally renders the exception message too. Allowlisting structured fields alone does not sanitize credentials embedded in a URL, exception text, or captured locals. Exercise the configured sanitizer with synthetic sensitive values and inspect its final output. Never use real secrets as fixtures. + +The paired examples use a non-retryable negative amount to illustrate preserved behavior. Both versions raise the same exception for the same input. The good version changes logging only; it does not add retry logic or invent payment metadata. diff --git a/plugins/python-structured-logging/skills/python-structured-logging/references/output-pipeline.md b/plugins/python-structured-logging/skills/python-structured-logging/references/output-pipeline.md new file mode 100644 index 0000000..da0cd06 --- /dev/null +++ b/plugins/python-structured-logging/skills/python-structured-logging/references/output-pipeline.md @@ -0,0 +1,11 @@ +# Output pipeline + +Stdlib `extra` adds attributes to a LogRecord; a default text formatter does not include arbitrary attributes. Inspect the project's formatter before claiming the output is structured. Preserve the existing handler configuration; reusable modules should not call `basicConfig()` or install root handlers. + +Use `extra={"invoice_id": invoice_id}` with stdlib, and `invoice_id=invoice_id` with structlog. Do not use reserved LogRecord keys such as `name`, `message`, or `levelname` as `extra` fields. Formatter-required fields must also be handled for third-party records that lack them. + +Capture the final rendered output as well as records. Check JSON decoding where JSON is the configured format, field types, exception rendering, and duplicate records from handler propagation. A test that only captures the pre-render event dictionary cannot establish downstream compatibility. + +At the application's configuration boundary, include framework/server/access/error/lifecycle loggers and the actual stdout/stderr or collector path, not just the application logger. Exercise an unexpected failure through that runtime: a safe application formatter is insufficient if another output path can emit raw data. Keep reusable modules free of global logging configuration. + +Formatter failure is part of this safety boundary. Probe non-finite numbers, unsupported objects and cyclic structured values through the public logging API, including stdlib `handleError`/diagnostic fallback. Use bounded safe normalization or a safe structured fallback: logging must not raise into application code, disclose the original exception/source through fallback, or emit invalid JSON when JSON is the output contract. Capture both streams and verify that a subsequent event still emits; silent record loss is not a successful fallback. From 5ba5e0437f2d81f58e96a59797f97c040f905808 Mon Sep 17 00:00:00 2001 From: mrKazzila Date: Fri, 25 Sep 2026 16:55:34 +0300 Subject: [PATCH 10/12] test: validate packaged and local skill consistency --- scripts/validate_repo.py | 17 +++++++++++++++++ tests/test_validation.py | 17 +++++++++++++++++ 2 files changed, 34 insertions(+) diff --git a/scripts/validate_repo.py b/scripts/validate_repo.py index 8d6d673..a3be1af 100644 --- a/scripts/validate_repo.py +++ b/scripts/validate_repo.py @@ -16,8 +16,25 @@ SKILL = PLUGIN / "skills" / SKILL_NAME +def resource_files(directory: Path) -> dict[str, bytes]: + """Compare distributed resources, excluding generated/editor files.""" + return { + path.relative_to(directory).as_posix(): path.read_bytes() + for path in directory.rglob('*') + if path.is_file() + and not any(part.startswith('.') or part == '__pycache__' + for part in path.relative_to(directory).parts) + and path.suffix not in ('.pyc', '.pyo') + and not path.name.endswith('~') + } + + def validate(root: Path = ROOT) -> list[str]: errors: list[str] = [] + packaged = resource_files(root / SKILL) + local = resource_files(root / '.agents/skills' / SKILL_NAME) + if not packaged or packaged != local: + errors.append('Skill copies differ: synchronize .agents/skills from plugins (contents and resource list)') def mapping(path: Path, loader) -> dict: try: diff --git a/tests/test_validation.py b/tests/test_validation.py index b176720..b2d5c47 100644 --- a/tests/test_validation.py +++ b/tests/test_validation.py @@ -20,6 +20,23 @@ def setUp(self): def test_repository_is_valid(self): self.assertEqual(validate(self.root), []) + def test_local_copy_drift_is_rejected(self): + local = self.root / '.agents/skills/python-structured-logging' + (local / 'SKILL.md').write_text('outdated') + self.assertTrue(any('Skill copies differ' in e for e in validate(self.root))) + + def test_extra_local_resource_is_rejected(self): + local = self.root / '.agents/skills/python-structured-logging' + (local / 'unexpected.md').write_text('stale resource') + self.assertTrue(any('Skill copies differ' in e for e in validate(self.root))) + + def test_generated_files_do_not_count_as_drift(self): + local = self.root / '.agents/skills/python-structured-logging' + (local / '__pycache__').mkdir(exist_ok=True) + (local / '__pycache__/example.pyc').write_bytes(b'cache') + (local / '.DS_Store').write_bytes(b'editor') + self.assertEqual(validate(self.root), []) + def test_malformed_yaml_is_rejected(self): (self.root / SKILL / 'SKILL.md').write_text('---\nname: [\ndescription: broken\n---\n') self.assertTrue(validate(self.root)) From cd8db2b2e6c6f999949ef8740c934920c7cdb711 Mon Sep 17 00:00:00 2001 From: mrKazzila Date: Fri, 25 Sep 2026 16:55:34 +0300 Subject: [PATCH 11/12] test: cover malformed logging values and safe recovery --- evals/demo/grading.py | 22 +++++++-- evals/demo/reference/safe_output.py | 26 +++++++--- evals/demo/runtime-regressions.md | 10 ++-- evals/demo/runtime_probe.py | 73 +++++++++++++++++++++++++---- tests/demo/test_demo.py | 36 +++++++++++++- 5 files changed, 141 insertions(+), 26 deletions(-) diff --git a/evals/demo/grading.py b/evals/demo/grading.py index b473594..e49f209 100644 --- a/evals/demo/grading.py +++ b/evals/demo/grading.py @@ -41,6 +41,21 @@ def runtime_criteria(runtime): fmt_raw = formatter['stdout'] + formatter['stderr'] unsafe = [marker for marker in [*formatter['secrets'], '--- Logging error ---', 'FORMATTER_SOURCE_SENTINEL'] if marker in fmt_raw] + cases = [] + for case in formatter['cases']: + emitted, bad_emission = rendered(case['emission']) + recovered, bad_recovery = rendered(case['recovery']) + case_raw = ''.join(case[stage][stream] for stage in ('emission', 'recovery') + for stream in ('stdout', 'stderr')) + cases.append({'case': case['case'], 'raised': case['raised'], + 'recovery_raised': case['recovery_raised'], + 'emitted_records': len(emitted), + 'recovered': any(r['event'] == 'demo.serialization_recovery' for r in recovered), + 'unsafe_markers': [marker for marker in unsafe if marker in case_raw], + 'malformed_lines': bad_emission + bad_recovery}) + complete_cases = {c['case'] for c in cases} == { + 'ordinary_object', 'hostile_mapping_key', 'cycle', 'nan', + 'positive_infinity', 'negative_infinity'} and len(cases) == 6 return [ {'id': 'whole_process_output', 'passed': bool(records) and not malformed and not leaks, @@ -49,9 +64,10 @@ def runtime_criteria(runtime): 'passed': error_count == 1, 'evidence': {'error_records': len(errors), 'raw_server_errors': len(raw_errors)}}, {'id': 'formatter_fallback_safety', - 'passed': formatter['raised'] is None and not unsafe and not fmt_malformed and - any(r['event'] == 'demo.serialization_recovery' for r in fmt_records), - 'evidence': {'raised': formatter['raised'], 'unsafe_markers': unsafe, + 'passed': complete_cases and not unsafe and not fmt_malformed and all( + c['raised'] is None and c['recovery_raised'] is None and c['emitted_records'] > 0 + and c['recovered'] and not c['malformed_lines'] for c in cases), + 'evidence': {'cases': cases, 'unsafe_markers': unsafe, 'malformed_lines': fmt_malformed, 'records': len(fmt_records)}}, {'id': 'unexpected_500_correlation', 'passed': server['status'] == 500 and diff --git a/evals/demo/reference/safe_output.py b/evals/demo/reference/safe_output.py index ced6cbe..a0b1562 100644 --- a/evals/demo/reference/safe_output.py +++ b/evals/demo/reference/safe_output.py @@ -5,17 +5,29 @@ import sys -def sanitize(value): - """Demo redaction after exception rendering; not a general secret detector.""" - if isinstance(value, dict): - return {key: sanitize(item) for key, item in value.items()} - if isinstance(value, list): - return [sanitize(item) for item in value] +def sanitize(value, active=None): + """Bounded demo normalization/redaction; not a general secret detector.""" + if active is None: + active = set() + if isinstance(value, (dict, list, tuple)): + if id(value) in active or len(active) >= 32: + return '[unsupported value]' + active.add(id(value)) + try: + if isinstance(value, dict): + # Omit unsupported keys without invoking user str/repr methods. + return {key: sanitize(item, active) for key, item in value.items() + if isinstance(key, str)} + return [sanitize(item, active) for item in value] + finally: + active.remove(id(value)) if isinstance(value, str): return re.sub(r'TEST_SECRET_[A-Z0-9_]+', '[REDACTED]', value) if isinstance(value, float) and not math.isfinite(value): return None - return value + if value is None or isinstance(value, (bool, int, float)): + return value + return '[unsupported value]' class ServerFormatter(logging.Formatter): diff --git a/evals/demo/runtime-regressions.md b/evals/demo/runtime-regressions.md index 4f18446..6cf46f6 100644 --- a/evals/demo/runtime-regressions.md +++ b/evals/demo/runtime-regressions.md @@ -10,7 +10,7 @@ All four checks run from `scripts/demo.py check`; implementation is in | --- | --- | --- | | `whole_process_output` / `test_reviewed_worker_whole_process_output` | Both actual process streams, including Uvicorn startup/error/access/shutdown, contain only JSON event/level objects and neither unique exception nor query secret. | ASGITransport never exercised Uvicorn handlers or access logging. | | `unexpected_failure_ownership` / `test_reviewed_worker_duplicate_failure_ownership` | One error/critical event across application and server; raw Uvicorn exception reports also count. | Only handled provider failures and application output were checked. | -| `formatter_fallback_safety` / `test_reviewed_worker_formatter_fallback` | Public `log.exception` with NaN during an active secret-bearing exception neither raises nor produces raw diagnostics, secret, local sentinel, source marker, or invalid JSON. A following public info call still renders. | Normal structured fields did not make the JSON encoder fail; logging.handleError was never exercised. | +| `formatter_fallback_safety` / `test_reviewed_worker_formatter_fallback` | Public `log.exception` with an ordinary object, hostile non-string mapping key, cycle, NaN, +Infinity and -Infinity during an active secret-bearing exception neither raises nor produces raw diagnostics, secret, local sentinel, source marker, or invalid JSON. Every attempt emits a safe structured record or fallback, and a following public info call still renders. | Normal structured fields did not make the JSON encoder fail; the original NaN-only probe missed unsupported-key, object and cycle failures. | | `unexpected_500_correlation` / `test_reviewed_worker_unexpected_500_correlation` | Actual HTTP 500 carries the supplied request ID, matching application `request.completed` with status 500. | Handled 503 and validation 422 did not exercise the outer framework error middleware. | The fixture already promises JSON logs, no credentials in rendered exceptions, @@ -84,9 +84,11 @@ criterion fails**. Thus the four checks are not aliases for one broad failure. arbitrary-object stringification, or access-event name is prescribed. Safe disabling of access logs is allowed. Server lifecycle prose is rejected because this fixture promises JSON output throughout the process. -- **False negatives:** finite normalization or a safe fallback/drop may pass; - formatter safety does not promise delivery of the failed event, but recovery - logging must work. Error ownership recognizes JSON error/critical levels and +- **False negatives:** safe normalization, field omission or a structured fallback + may pass; silent dropping of an entire attempted event fails. Each synchronous + call has descriptor-level stdout/stderr evidence, replayed into the complete + process streams. Queued/asynchronous delivery is outside this fixture's current + synchronous facade contract. Error ownership recognizes JSON error/critical levels and pinned Uvicorn's raw ASGI-error banner. Adversarial relabeling/dropping, alternate encodings of secrets, unrelated sink files, and custom background processes are outside this check. Unique per-run secrets prevent fixed-string redaction from diff --git a/evals/demo/runtime_probe.py b/evals/demo/runtime_probe.py index 9915f23..e54dfbe 100644 --- a/evals/demo/runtime_probe.py +++ b/evals/demo/runtime_probe.py @@ -7,11 +7,43 @@ import asyncio import json import logging +import os import sys +import tempfile +from contextlib import contextmanager from pathlib import Path from uuid import uuid4 +@contextmanager +def capture_streams(): + """Attribute synchronous emissions, including raw fd writes, to one call. + + Replay captured bytes to the original descriptors so the complete process + streams remain authoritative too. No candidate logger internals are used. + """ + observed = {} + sys.stdout.flush() + sys.stderr.flush() + with tempfile.TemporaryFile() as stdout, tempfile.TemporaryFile() as stderr: + saved = [os.dup(1), os.dup(2)] + try: + os.dup2(stdout.fileno(), 1) + os.dup2(stderr.fileno(), 2) + yield observed + finally: + sys.stdout.flush() + sys.stderr.flush() + for fd, original, stream, name in zip((1, 2), saved, (stdout, stderr), ('stdout', 'stderr')): + os.dup2(original, fd) + os.close(original) + stream.seek(0) + raw = stream.read() + observed[name] = raw.decode('utf-8', errors='replace') + while raw: + raw = raw[os.write(fd, raw):] + + def formatter(): from app import observability as log @@ -19,16 +51,37 @@ def formatter(): logging.raiseExceptions = True # Exercise stdlib's development diagnostic path. secret = 'TEST_SECRET_FORMATTER_' + uuid4().hex.upper() local_secret = 'TEST_SECRET_LOCAL_' + uuid4().hex.upper() - raised = None - try: - raise RuntimeError(secret) - except RuntimeError: - try: - log.exception('demo.serialization', measurement=float('nan')) # FORMATTER_SOURCE_SENTINEL - except Exception as error: - raised = type(error).__name__ - log.info('demo.serialization_recovery') - return {'secrets': [secret, local_secret], 'raised': raised} + class HostileKey: + def __str__(self): + raise RuntimeError(secret) + + def __repr__(self): + return local_secret + + cycle = [] + cycle.append(cycle) + cases = [('ordinary_object', object()), ('hostile_mapping_key', {HostileKey(): 'value'}), + ('cycle', cycle), ('nan', float('nan')), ('positive_infinity', float('inf')), + ('negative_infinity', float('-inf'))] + observed = [] + for name, value in cases: + raised = recovery_raised = None + with capture_streams() as emission: + try: + raise RuntimeError(secret) + except RuntimeError: + try: + log.exception('demo.serialization', case=name, measurement=value) # FORMATTER_SOURCE_SENTINEL + except Exception as error: + raised = type(error).__name__ + with capture_streams() as recovery: + try: + log.info('demo.serialization_recovery', case=name) + except Exception as error: + recovery_raised = type(error).__name__ + observed.append({'case': name, 'raised': raised, 'recovery_raised': recovery_raised, + 'emission': emission, 'recovery': recovery}) + return {'secrets': [secret, local_secret], 'cases': observed} async def server(): diff --git a/tests/demo/test_demo.py b/tests/demo/test_demo.py index 0a17782..d004af1 100644 --- a/tests/demo/test_demo.py +++ b/tests/demo/test_demo.py @@ -125,9 +125,9 @@ def test_minimal_reviewed_worker_repairs_pass(self): shutil.copyfile(demo.DEMO / 'reference' / filename, project / 'app' / filename) backend = project / 'app/observability.py' backend.write_text(backend.read_text().replace( - 'import json', 'import json\nimport math\nfrom .safe_output import configure_server', + 'import json', 'import json\nfrom .safe_output import configure_server, sanitize', ).replace('def _safe(value):', - 'def _safe(value):\n if isinstance(value, float) and not math.isfinite(value):\n return None' + 'def _safe(value):\n value = sanitize(value)' ).replace('def configure():', 'def configure():\n configure_server()')) middleware = project / 'app/middleware.py' middleware.write_text(middleware.read_text().replace( @@ -138,6 +138,38 @@ def test_minimal_reviewed_worker_repairs_pass(self): report = demo.check(project) self.assertTrue(report['passed'], report['criteria']) + def test_formatter_cases_require_emission_and_accept_safe_fallback(self): + spec = importlib.util.spec_from_file_location('formatter_grading', demo.DEMO / 'grading.py') + grading = importlib.util.module_from_spec(spec) + spec.loader.exec_module(grading) + for stack in STACKS: + original = demo.check(self.project(stack, fixed=True))['observations']['runtime'] + + def passed(runtime): + return next(c['passed'] for c in grading.runtime_criteria(runtime) + if c['id'] == 'formatter_fallback_safety') + + for index, case in enumerate(original['formatter']['cases']): + with self.subTest(stack=stack, case=case['case']): + for defect in ('drop', 'raise', 'recovery', 'raw_stdout', 'invalid_json'): + runtime = copy.deepcopy(original) + target = runtime['formatter']['cases'][index] + if defect == 'drop': + target['emission'] = {'stdout': '', 'stderr': ''} + elif defect == 'raise': + target['raised'] = 'TypeError' + elif defect == 'recovery': + target['recovery'] = {'stdout': '', 'stderr': ''} + elif defect == 'raw_stdout': + target['emission']['stdout'] += 'raw formatter diagnostic\n' + else: + target['emission']['stderr'] += '{"event":"bad","level":"error","x":Infinity}\n' + self.assertFalse(passed(runtime), (stack, case['case'], defect)) + runtime = copy.deepcopy(original) + runtime['formatter']['cases'][index]['emission'] = { + 'stdout': '{"event":"logging.failed","level":"error"}\n', 'stderr': ''} + self.assertTrue(passed(runtime)) + def test_independent_runtime_source_regressions(self): mutations = { 'whole_process_output': ('observability.py', ' configure_server()', ' pass'), From d52eaf9cd0a8ae1af172ccc18dc84304d44cf5e5 Mon Sep 17 00:00:00 2001 From: mrKazzila Date: Fri, 25 Sep 2026 16:55:35 +0300 Subject: [PATCH 12/12] test: add async consumer logging evaluation fixture --- evals/worker_consumer/README.md | 48 +++++ evals/worker_consumer/evaluate.py | 170 +++++++++++++++++ evals/worker_consumer/probe.py | 174 ++++++++++++++++++ .../reference/observability.py | 65 +++++++ evals/worker_consumer/repair.py | 22 +++ evals/worker_consumer/template/README.md | 40 ++++ .../template/consumer/__init__.py | 0 .../template/consumer/__main__.py | 12 ++ .../template/consumer/broker.py | 24 +++ .../template/consumer/dependency.py | 38 ++++ .../template/consumer/observability.py | 43 +++++ .../template/consumer/runtime.py | 19 ++ .../template/consumer/service.py | 12 ++ .../template/consumer/worker.py | 47 +++++ .../template/tests/test_contract.py | 37 ++++ tests/worker_consumer/test_evaluator.py | 79 ++++++++ 16 files changed, 830 insertions(+) create mode 100644 evals/worker_consumer/README.md create mode 100644 evals/worker_consumer/evaluate.py create mode 100644 evals/worker_consumer/probe.py create mode 100644 evals/worker_consumer/reference/observability.py create mode 100644 evals/worker_consumer/repair.py create mode 100644 evals/worker_consumer/template/README.md create mode 100644 evals/worker_consumer/template/consumer/__init__.py create mode 100644 evals/worker_consumer/template/consumer/__main__.py create mode 100644 evals/worker_consumer/template/consumer/broker.py create mode 100644 evals/worker_consumer/template/consumer/dependency.py create mode 100644 evals/worker_consumer/template/consumer/observability.py create mode 100644 evals/worker_consumer/template/consumer/runtime.py create mode 100644 evals/worker_consumer/template/consumer/service.py create mode 100644 evals/worker_consumer/template/consumer/worker.py create mode 100644 evals/worker_consumer/template/tests/test_contract.py create mode 100644 tests/worker_consumer/test_evaluator.py diff --git a/evals/worker_consumer/README.md b/evals/worker_consumer/README.md new file mode 100644 index 0000000..dae1a43 --- /dev/null +++ b/evals/worker_consumer/README.md @@ -0,0 +1,48 @@ +# Worker/consumer evaluation + +Independent non-HTTP stdlib fixture. `template/` is a deliberately flawed logging baseline; +its business contracts are valid. `reference/` + `repair.py` are evaluator calibration only. +No third-party dependencies. Python >=3.11. + +```sh +python3 -m unittest discover -s tests/worker_consumer -v +python3 evals/worker_consumer/evaluate.py /absolute/candidate /tmp/new-report.json +``` + +Exit 0 = all criteria pass, 1 = observable defect; execution/setup errors raise separately. +Reports are created exclusively, not overwritten. Each scenario runs in a fresh isolated +Python subprocess; stdout/stderr are OS-level captured and metadata uses a separate file. +Never infer failure ownership from passing safety or vice versa. No weighted score. + +Frozen criteria before A/B: + +| Check | Observable boundary | +|---|---| +| business_contract | result values, original payloads, dependency calls and exact exceptions | +| retry_ack_contract | success ack, retry request, attempt limit DLQ, poison DLQ, unchanged unexpected propagation and runtime retry | +| cancellation_contract | CancelledError propagation; no disposition | +| whole_runtime_json | all captured runtime streams parse as strict JSON objects | +| payload_credential_exception_safety | synthetic payload/token/exception sentinels absent | +| concurrent_nested_context | overlapping dependency operations retain each message/correlation; nested operation restores parent | +| context_cleanup | post-success/failure/cancellation in same task; nested scope restoration | +| event_contracts | preserved four documented event names, count and originating IDs | +| single_failure_ownership | one warning/error or semantically named failure/retry/DLQ diagnosis per failed attempt | +| background_failure | pending tasks drained and audit failure owned/correlated once | +| cancellation_level | no false cancellation ERROR | +| outcome_fields_units | attempt/outcome, amount_cents, optional nonnegative duration_ms | +| bounded_events_noise | stable events; <=14 operational non-DEBUG events for 9 attempts + audit + lifecycle allowance | +| formatter_nonfinite/object/key/cycle | public facade does not raise, leak, emit raw fallback or invalid JSON; safe diagnostic and subsequent event both present | + +Calibration includes a known bad baseline, minimal repaired reference, observable mutations +(strict JSON, silent drop, propagation, runtime plaintext, credential leak, extra ack), and +acceptance of implementation-independent structured fallback and absent optional lifecycle. +No private logging helper names are inspected. Facade test events are excluded from noise. +Safe field omission/placeholder/fallback are all accepted; diagnostic spelling is unconstrained. +Fixed noise threshold is project-specific, not a universal skill rule. Foreign runtime logs +must satisfy the fixture's JSON contract; intentional CLI output is not part of this fixture. + +Limitations: synthetic finite batches and fake dispositions, no broker integration, crash +redelivery, real rebalance, process signals, queue-based logging, sink I/O outages, or performance +measurement. Unsupported value probes cover representative inputs, not an exhaustive serializer. +No requirement for arbitrary unlabelled string redaction outside documented sensitive fields. +A single cross-domain pair is exploratory, not statistical causal evidence. diff --git a/evals/worker_consumer/evaluate.py b/evals/worker_consumer/evaluate.py new file mode 100644 index 0000000..191af7f --- /dev/null +++ b/evals/worker_consumer/evaluate.py @@ -0,0 +1,170 @@ +#!/usr/bin/env python3 +"""Frozen observable worker evaluator. No private helper inspection or dependencies.""" +import argparse +import collections +import json +from pathlib import Path +import subprocess +import sys +import tempfile + +HERE = Path(__file__).resolve().parent +SECRETS = ['SYNTHETIC_DEPENDENCY_SECRET','SYNTHETIC_BARE_SECRET','SYNTHETIC_PAYLOAD_SECRET', + 'SYNTHETIC_AUDIT_SECRET','SYNTHETIC_TOKEN_SECRET'] + + +def parse(observation): + records, invalid = [], [] + def reject(value): + raise ValueError(value) + for line in (observation['stdout']+'\n'+observation['stderr']).splitlines(): + if not line.strip(): + continue + try: + value = json.loads(line, parse_constant=reject) + if not isinstance(value,dict) or not all(isinstance(value.get(k),str) for k in ('event','level')): + raise ValueError('envelope') + records.append(value) + except (ValueError,TypeError): + invalid.append(line) + return records, invalid + + +def grade(observations): + work = observations['workload']; meta = work['metadata']; records, invalid = parse(work) + criteria = [] + def check(name, passed, evidence): + criteria.append({'id':name,'passed':bool(passed),'evidence':evidence}) + expected_results = [{'message_id':'ok','amount_cents':123},'retry', + {'message_id':'redelivered','amount_cents':123},'dead_letter','dead_letter', + {'type':'RuntimeError','message':'SYNTHETIC_BARE_SECRET'}, + {'message_id':'audit','amount_cents':123}] + expected_dispositions = [['ok','ack',1],['retry','retry',1],['redelivered','ack',2], + ['poison','dead_letter',1],['exhausted','dead_letter',3], + ['unexpected','retry',1],['audit','ack',1]] + expected_exceptions = [{'type':'RetryableError','message':'upstream credential=SYNTHETIC_DEPENDENCY_SECRET'}, + {'type':'PoisonError','message':'invalid payload SYNTHETIC_PAYLOAD_SECRET'}, + {'type':'RuntimeError','message':'SYNTHETIC_BARE_SECRET'}] + check('business_contract',meta['results']==expected_results and meta['payloads_preserved'] and + meta['dependency_contracts']==expected_exceptions and + sorted(meta['calls'])==sorted([[x[0],x[2]] for x in expected_dispositions]),meta) + check('retry_ack_contract',sorted(meta['dispositions'])==sorted(expected_dispositions) and + meta['direct_error']==expected_exceptions[2] and meta['direct_dispositions']==[],meta['dispositions']) + check('cancellation_contract',meta['cancelled'] and meta['cancel_dispositions']==[], + {'cancelled':meta['cancelled'],'dispositions':meta['cancel_dispositions']}) + check('whole_runtime_json',bool(records) and not invalid,{'invalid_lines':invalid,'records':len(records)}) + raw=work['stdout']+work['stderr']; leaks=[s for s in SECRETS if s in raw] + check('payload_credential_exception_safety',not leaks,leaks) + probes=[r for r in records if r['event'] in ('probe.nested','probe.parent')] + wrong=[r for r in probes if r.get('message_id')!=r.get('probe_message') or + r.get('correlation_id')!='corr-'+r.get('probe_message','') or + (r['event']=='probe.parent' and r.get('operation') is not None) or + (r['event']=='probe.nested' and r.get('operation')!='nested')] + check('concurrent_nested_context',collections.Counter((r['event'],r.get('probe_message')) for r in probes)== + collections.Counter((event,name) for event in ('probe.nested','probe.parent') + for name in ('ok','retry','redelivered','poison','exhausted','unexpected','audit')) and not wrong,wrong) + cleanup=[r for r in records if r['event']=='probe.cleanup'] + wrong=[r for r in cleanup if any(r.get(k) is not None for k in ('message_id','correlation_id','operation'))] + scope={r['event']:r for r in records if r['event'].startswith('probe.scope_')} + check('context_cleanup',collections.Counter(r.get('probe_message') for r in cleanup)== + collections.Counter(('ok','retry','redelivered','poison','exhausted','unexpected','audit','direct','cancel')) and not wrong and + set(scope)=={'probe.scope_inner','probe.scope_outer','probe.scope_clear'} and + scope.get('probe.scope_inner',{}).get('message_id')=='inner' and + scope.get('probe.scope_outer',{}).get('message_id')=='outer' and + scope.get('probe.scope_inner',{}).get('correlation_id')=='corr-inner' and + scope.get('probe.scope_outer',{}).get('correlation_id')=='corr-outer' and + not any(scope.get('probe.scope_clear',{}).get(k) for k in ('message_id','correlation_id')),wrong or scope) + ops=[r for r in records if not r['event'].startswith('probe.')] + expected={'message.processed':{'ok','redelivered','audit'},'message.retry':{'retry'}, + 'message.dead_letter':{'poison','exhausted'},'audit.failed':{'audit'}} + wrong=[] + for event, ids in expected.items(): + found=[r for r in ops if r['event']==event] + if collections.Counter(r.get('message_id') for r in found)!=collections.Counter(ids): + wrong.append({'event':event,'records':found}) + for r in found: + if r.get('correlation_id')!='corr-'+r.get('message_id',''): + wrong.append(r) + check('event_contracts',not wrong,wrong) + failures={} + for name in ('retry','poison','exhausted','unexpected','audit'): + # Success access summaries are not duplicate diagnoses. Failure diagnoses + # include warning/error OR explicit retry/dead-letter/failure event semantics. + failures[name]=[r for r in ops if r.get('message_id')==name and + (r['level'].lower() in ('warning','error','critical') or + any(part in r['event'] for part in ('retry','dead_letter','failed')))] + unassigned=[r for r in ops if r['level'].lower() in ('warning','error','critical') and + r.get('message_id') not in {*failures,'direct'}] + direct_diagnostics=[r for r in ops if r.get('message_id')=='direct' and r['level'].lower() in ('warning','error','critical')] + check('single_failure_ownership',all(len(v)==1 for v in failures.values()) and + not unassigned and len(direct_diagnostics)<=1,{'by_message':failures,'unassigned':unassigned}) + check('background_failure',meta['background_remaining']==0 and + sorted(meta['audit_started'])==['audit','ok','redelivered'] and + sorted(meta['audit_completed'])==['audit','ok','redelivered'] and + len([r for r in ops if r['event']=='audit.failed' and r.get('message_id')=='audit' and + r.get('correlation_id')=='corr-audit'])==1,failures['audit']) + cancel_errors=[r for r in ops if r.get('message_id')=='cancel' and r['level'].lower() in ('error','critical')] + check('cancellation_level',not cancel_errors,cancel_errors) + wrong=[] + for r in ops: + if r['event'] in ('message.processed','message.retry','message.dead_letter'): + outcome={'message.processed':'ack','message.retry':'retry','message.dead_letter':'dead_letter'}[r['event']] + expected_attempt={'redelivered':2,'exhausted':3}.get(r.get('message_id'),1) + if r.get('attempt')!=expected_attempt or r.get('outcome')!=outcome: + wrong.append(r) + if r['event']=='message.processed' and r.get('amount_cents')!=123: + wrong.append(r) + if 'duration' in r or ('duration_ms' in r and (not isinstance(r['duration_ms'],(int,float)) or r['duration_ms']<0)): + wrong.append(r) + for name, found in failures.items(): + for r in found: + if r.get('correlation_id')!='corr-'+name or r.get('attempt')!=(3 if name=='exhausted' else 1): + wrong.append(r) + if name in ('unexpected','audit') and r.get('outcome')!='failed': + wrong.append(r) + if name=='retry' and r.get('retryable') is not True: + wrong.append(r) + if name in ('poison','exhausted') and r.get('retryable') is not False: + wrong.append(r) + check('outcome_fields_units',not wrong,wrong) + names=[r['event'] for r in ops] + dynamic=[n for n in names if any(x in n for x in ('processing_','corr-','SYNTHETIC_'))] + # Seven batch attempts + direct/cancel + one audit error, up to two lifecycle + # records, plus a small allowance for useful operational summaries. + info_ops=[r for r in ops if r['level'].lower()!='debug'] + check('bounded_events_noise',not dynamic and len(info_ops)<=14,{'dynamic':dynamic,'count':len(info_ops),'budget':14}) + for case in ('nonfinite','object','key','cycle'): + o=observations[case]; rs,bad=parse(o); text=o['stdout']+o['stderr'] + unsafe=[s for s in [*SECRETS,'--- Logging error ---','WORKER_SOURCE_SENTINEL'] if s in text] + recovery=[r for r in rs if r['event']=='probe.recovery'] + diagnostics, emission_invalid=parse(o['metadata']['emission']) + recovery_records, recovery_invalid=parse(o['metadata']['recovery']) + check('formatter_'+case,o['metadata']['raised'] is None and o['metadata']['recovery_raised'] is None + and len(recovery)==1 and any(r['event']=='probe.recovery' for r in recovery_records) + and bool(diagnostics) and not emission_invalid and not recovery_invalid and not bad and not unsafe, + {'metadata':o['metadata'],'unsafe':unsafe,'invalid':bad,'records':rs}) + return {'passed':all(c['passed'] for c in criteria),'criteria':criteria, + 'metrics':{'event_counts':dict(collections.Counter(names)), 'operational_records':len(ops), + 'json_records':len(records),'raw_lines':len(invalid)},'observations':observations} + + +def evaluate(project): + observations={} + with tempfile.TemporaryDirectory(prefix='consumer-eval-') as tmp: + for case in ('workload','nonfinite','object','key','cycle'): + metadata=Path(tmp)/f'{case}.json' + run=subprocess.run([sys.executable,'-I','-B',str(HERE/'probe.py'),str(project.resolve()),case,str(metadata)], + capture_output=True,text=True,timeout=25,cwd=project) + if run.returncode or not metadata.exists(): + raise RuntimeError(f'{case} probe setup/execution failed: {run.returncode}\n{run.stderr}') + observations[case]={'stdout':run.stdout,'stderr':run.stderr,'metadata':json.loads(metadata.read_text())} + return grade(observations) + + +if __name__=='__main__': + parser=argparse.ArgumentParser(); parser.add_argument('project',type=Path); parser.add_argument('report',type=Path) + args=parser.parse_args() + with args.report.open('x') as output: + result=evaluate(args.project); json.dump(result,output,indent=2); output.write('\n') + print(json.dumps({c['id']:c['passed'] for c in result['criteria']},indent=2)) + raise SystemExit(0 if result['passed'] else 1) diff --git a/evals/worker_consumer/probe.py b/evals/worker_consumer/probe.py new file mode 100644 index 0000000..e5a0e78 --- /dev/null +++ b/evals/worker_consumer/probe.py @@ -0,0 +1,174 @@ +"""Run in an isolated process; metadata never shares the logging output streams.""" +import asyncio +import copy +import json +import logging +import os +import tempfile +from contextlib import contextmanager +import sys +from pathlib import Path + +SECRETS = ['SYNTHETIC_DEPENDENCY_SECRET', 'SYNTHETIC_BARE_SECRET', + 'SYNTHETIC_PAYLOAD_SECRET', 'SYNTHETIC_AUDIT_SECRET', 'SYNTHETIC_TOKEN_SECRET'] + + +@contextmanager +def capture_streams(): + """Attribute synchronous emissions, including raw fd writes, to one call. + + Replay captured bytes to the original descriptors so the complete process + streams remain authoritative too. No candidate logger internals are used. + """ + observed = {} + sys.stdout.flush() + sys.stderr.flush() + with tempfile.TemporaryFile() as stdout, tempfile.TemporaryFile() as stderr: + saved = [os.dup(1), os.dup(2)] + try: + os.dup2(stdout.fileno(), 1) + os.dup2(stderr.fileno(), 2) + yield observed + finally: + sys.stdout.flush() + sys.stderr.flush() + for fd, original, stream, name in zip((1, 2), saved, (stdout, stderr), ('stdout', 'stderr')): + os.dup2(original, fd) + os.close(original) + stream.seek(0) + raw = stream.read() + observed[name] = raw.decode('utf-8', errors='replace') + while raw: + raw = raw[os.write(fd, raw):] + + +async def workload(): + from consumer import observability as log + from consumer.broker import Broker, Message + from consumer.dependency import Dependency + from consumer.worker import Consumer + from consumer.runtime import run + + class ObservedDependency(Dependency): + def __init__(self): + super().__init__() + self.audit_started = [] + self.audit_completed = [] + + async def audit(self, message): + self.audit_started.append(message.message_id) + try: + return await super().audit(message) + finally: + self.audit_completed.append(message.message_id) + + async def execute(self, message): + with log.scope(operation='nested'): + await asyncio.sleep(0) + log.info('probe.nested', probe_message=message.message_id) + log.info('probe.parent', probe_message=message.message_id) + return await super().execute(message) + + def msg(name, mode, attempt=1, audit=False): + return Message(name, 'corr-'+name, {'mode':mode, 'amount_cents':123, + 'body':'SYNTHETIC_PAYLOAD_SECRET', 'payment_token':'SYNTHETIC_TOKEN_SECRET', + 'audit_fail':audit}, attempt) + + messages = [msg('ok','success'), msg('retry','retry'), msg('redelivered','retry',2), + msg('poison','poison'), msg('exhausted','exhausted',3), + msg('unexpected','unexpected'), msg('audit','success',audit=True)] + payload_ids = [id(m.payload) for m in messages] + payloads = copy.deepcopy([m.payload for m in messages]) + broker, dep = Broker(), ObservedDependency() + consumer = Consumer(broker, dep) + original_handle = consumer.handle + + async def observed_handle(message): + try: + return await original_handle(message) + finally: + log.info('probe.cleanup', probe_message=message.message_id) + consumer.handle = observed_handle + results = await run(consumer, messages) + # Verify direct unexpected propagation separately, without runtime ack/retry. + direct_broker, direct_dep = Broker(), Dependency() + direct = Consumer(direct_broker, direct_dep) + try: + await direct.handle(msg('direct','unexpected')) + except Exception as error: + direct_error = {'type':type(error).__name__, 'message':str(error)} + else: + direct_error = None + log.info('probe.cleanup', probe_message='direct') + cancel_broker, cancel_dep = Broker(), Dependency() + cancel_consumer = Consumer(cancel_broker, cancel_dep) + async def cancel_job(): + try: + await cancel_consumer.handle(msg('cancel','cancel')) + finally: + log.info('probe.cleanup', probe_message='cancel') + task = asyncio.create_task(cancel_job()) + await cancel_dep.started.wait() + task.cancel() + cancelled = False + try: + await task + except asyncio.CancelledError: + cancelled = True + with log.scope(message_id='outer', correlation_id='corr-outer'): + with log.scope(message_id='inner', correlation_id='corr-inner'): + log.info('probe.scope_inner') + log.info('probe.scope_outer') + log.info('probe.scope_clear') + direct_contracts = [] + for mode in ('retry','poison','unexpected'): + try: + await Dependency().execute(msg('dependency',mode)) + except Exception as error: + direct_contracts.append({'type':type(error).__name__,'message':str(error)}) + return {'results':[{'type':type(r).__name__,'message':str(r)} if isinstance(r,BaseException) else r for r in results], + 'dispositions':broker.dispositions, 'calls':dep.calls, + 'payloads_preserved':payloads == [m.payload for m in messages] and payload_ids == [id(m.payload) for m in messages], + 'audit_started':dep.audit_started, 'audit_completed':dep.audit_completed, + 'direct_error':direct_error, 'direct_dispositions':direct_broker.dispositions, + 'cancelled':cancelled, 'cancel_dispositions':cancel_broker.dispositions, + 'background_remaining':len(consumer.background), 'dependency_contracts':direct_contracts} + + +def malformed(case): + from consumer import observability as log + class Unknown: + def __str__(self): + raise ValueError('SYNTHETIC_BARE_SECRET') + __repr__ = __str__ + cycle = {}; cycle['self'] = cycle + values = {'nonfinite':[float('nan'),float('inf'),float('-inf')], + 'object':object(), 'key':{Unknown():'safe'}, 'cycle':cycle} + raised = None + with capture_streams() as emission: + try: + raise RuntimeError('SYNTHETIC_BARE_SECRET') + except RuntimeError: + try: + log.exception('probe.malformed', value=values[case]) # WORKER_SOURCE_SENTINEL + except Exception as error: + raised = type(error).__name__ + recovery_raised = None + with capture_streams() as recovery: + try: + log.info('probe.recovery') + except Exception as error: + recovery_raised = type(error).__name__ + return {'raised':raised, 'recovery_raised':recovery_raised, + 'emission':emission, 'recovery':recovery} + + + +if __name__ == '__main__': + sys.path.insert(0, str(Path(sys.argv[1]).resolve())) + logging.basicConfig(level=logging.INFO) # Adapter bootstrap, before facade configuration. + from consumer import observability as log + log.configure() + logging.raiseExceptions = True + result = asyncio.run(asyncio.wait_for(workload(), 15)) if sys.argv[2]=='workload' else malformed(sys.argv[2]) + Path(sys.argv[3]).write_text(json.dumps(result)) diff --git a/evals/worker_consumer/reference/observability.py b/evals/worker_consumer/reference/observability.py new file mode 100644 index 0000000..54b4e2f --- /dev/null +++ b/evals/worker_consumer/reference/observability.py @@ -0,0 +1,65 @@ +"""Small calibration repair; never supplied to A/B workers.""" +import json +import logging +import math +import sys +from contextlib import contextmanager +from contextvars import ContextVar + +_context = ContextVar('context', default={}) +logger = logging.getLogger('consumer') + + +def safe(value, depth=0): + if depth > 8: + return '[bounded]' + if type(value) is dict: + return {k:safe(v,depth+1) for k,v in list(value.items())[:50] + if type(k) is str and k not in ('payload','body','payment_token','password','authorization')} + if type(value) in (list,tuple): + return [safe(v,depth+1) for v in value[:50]] + if type(value) is float and not math.isfinite(value): + return None + if type(value) in (str,int,float,bool) or value is None: + return value + return '[unsupported]' + + +class Formatter(logging.Formatter): + def format(self, record): + try: + result = {**safe(getattr(record,'fields',{})), + 'event':record.msg if record.name=='consumer' else 'runtime.lifecycle', + 'level':record.levelname.lower()} + if record.exc_info: + result['error_type']=record.exc_info[0].__name__ + return json.dumps(result,allow_nan=False) + except Exception: + return '{"event":"logging.fallback","level":"error"}' + + +def configure(): + handler=logging.StreamHandler(sys.stderr); handler.setFormatter(Formatter()) + root=logging.getLogger(); root.handlers=[handler]; root.setLevel(logging.INFO) + logger.handlers=[]; logger.propagate=True; logger.setLevel(logging.INFO) + + +@contextmanager +def scope(**fields): + token=_context.set({**_context.get(),**fields}) + try: + yield + finally: + _context.reset(token) + + +def info(event,**fields): + logger.info(event,extra={'fields':{**fields,**_context.get()}}) + + +def warning(event,**fields): + logger.warning(event,extra={'fields':{**fields,**_context.get()}}) + + +def exception(event,**fields): + logger.exception(event,extra={'fields':{**fields,**_context.get()}}) diff --git a/evals/worker_consumer/repair.py b/evals/worker_consumer/repair.py new file mode 100644 index 0000000..0697aa3 --- /dev/null +++ b/evals/worker_consumer/repair.py @@ -0,0 +1,22 @@ +"""Deterministic calibration repair, not an experiment candidate.""" +from pathlib import Path +import shutil + +HERE=Path(__file__).resolve().parent + + +def repair(project): + shutil.copyfile(HERE/'reference/observability.py',project/'consumer/observability.py') + (project/'consumer/service.py').write_text('async def process(message, dependency):\n return await dependency.execute(message)\n') + p=project/'consumer/worker.py'; s=p.read_text() + s=s.replace(" log.info('message.received', payload=message.payload, attempt=message.attempt)\n",'') + s=s.replace("log.exception('message.retry', attempt=message.attempt, retryable=True)","log.warning('message.retry', attempt=message.attempt, retryable=True, outcome='retry')") + s=s.replace("attempt=message.attempt, retryable=False)","attempt=message.attempt, retryable=False, outcome='dead_letter')") + s=s.replace(" log.exception('message.cancelled')\n",'') + s=s.replace(" log.exception('message.failed')\n",'') + s=s.replace("outcome='ack')","outcome='ack', attempt=message.attempt)") + s=s.replace(" log.exception('audit.failed', message_id=message.message_id)"," with log.scope(message_id=message.message_id, correlation_id=message.correlation_id):\n log.exception('audit.failed', attempt=message.attempt, outcome='failed')") + p.write_text(s) + p=project/'consumer/runtime.py'; s=p.read_text() + s=s.replace(" runtime_log.error('consumer failed: %s', result,\n exc_info=(type(result), result, result.__traceback__))", " with log.scope(message_id=message.message_id, correlation_id=message.correlation_id):\n log.warning('message.failed', attempt=message.attempt, outcome='failed', error_type=type(result).__name__)") + p.write_text(s) diff --git a/evals/worker_consumer/template/README.md b/evals/worker_consumer/template/README.md new file mode 100644 index 0000000..94cc52a --- /dev/null +++ b/evals/worker_consumer/template/README.md @@ -0,0 +1,40 @@ +# Async payment message consumer + +Python 3.11+, stdlib only. Run `python3 -m unittest discover -s tests -v`. +Architecture: fake Broker -> Consumer.handle -> service.process -> Dependency.execute. +Runtime concurrently dispatches a batch and drains audit tasks at shutdown. No HTTP. + +Public contracts: +- Message(message_id, correlation_id, payload, attempt=1). IDs are approved opaque identifiers. + Payload includes amount_cents, mode, optional audit_fail, and sensitive payment_token/body. + Preserve the payload object and content; no new required fields or validation semantics. +- Success returns {message_id, amount_cents}, acknowledges once, starts one audit task. +- RetryableError before attempt 3 retries once and returns 'retry'; attempt >=3 dead-letters once. + The fake broker records a retry request; it does not automatically redeliver. +- PoisonError dead-letters once and returns 'dead_letter'. +- Unexpected exceptions propagate unchanged from handle (no ack there); runtime.run requeues once. +- Cancellation propagates, leaves message unacked, and is normal shutdown, not an error. +- Audit tasks are drained even when they fail; audit failure must not change an existing ack. +- Dependency results, call counts, exception types and messages are business contracts. +- Public logging facade entrypoints stay available; nested scope must restore parent bindings. + +Logging contracts: +- Keep stdlib and architecture. Configure output in the composition/facade setup. +- Complete runtime stdout/stderr must contain JSON log objects with string event and level. + Every operational failure needs one safe diagnostic owner, including audit failures. +- Events consumed by operations: message.processed, message.retry, message.dead_letter, audit.failed. + Keep their meanings. Include message_id, correlation_id, attempt on message outcomes and + outcome ('ack', 'retry', 'dead_letter', 'failed') where relevant. Money uses amount_cents. +- Diagnostics must not reveal raw payload, credentials, exception messages or source secrets. + Arbitrary structured values must not make logging raise or fall through to raw diagnostics. +- Stable bounded event names; put IDs in fields. Optional duration must use explicit units. +- Aim for one operational outcome per attempt; DEBUG diagnostics are welcome. No requirement + for an INFO arrival/service event. Startup/shutdown summaries are optional and useful once/batch. +- Concurrent messages must stay isolated. Restore context after success, failure, cancellation, + and nested scopes. Background audit records must retain their originating IDs. + +All secrets in this fixture are synthetic. Improve logging only; no broker/server dependency needed. + +`python3 -m consumer` runs the normal bootstrap: adapter stdlib logging configuration, +then facade configure(), then runtime.run(). The evaluator uses the same order. +The fake adapter represents a finite assigned batch; no real broker rebalance protocol is claimed. diff --git a/evals/worker_consumer/template/consumer/__init__.py b/evals/worker_consumer/template/consumer/__init__.py new file mode 100644 index 0000000..e69de29 diff --git a/evals/worker_consumer/template/consumer/__main__.py b/evals/worker_consumer/template/consumer/__main__.py new file mode 100644 index 0000000..bddee7f --- /dev/null +++ b/evals/worker_consumer/template/consumer/__main__.py @@ -0,0 +1,12 @@ +import asyncio +import logging +from . import observability as log +from .broker import Broker, Message +from .dependency import Dependency +from .worker import Consumer +from .runtime import run + +logging.basicConfig(level=logging.INFO) +log.configure() +asyncio.run(run(Consumer(Broker(), Dependency()), [ + Message('demo', 'corr-demo', {'amount_cents':100,'mode':'success'})])) diff --git a/evals/worker_consumer/template/consumer/broker.py b/evals/worker_consumer/template/consumer/broker.py new file mode 100644 index 0000000..fc4b0b4 --- /dev/null +++ b/evals/worker_consumer/template/consumer/broker.py @@ -0,0 +1,24 @@ +from dataclasses import dataclass + + +@dataclass(frozen=True) +class Message: + message_id: str + correlation_id: str + payload: dict + attempt: int = 1 + + +class Broker: + """Fake adapter: dispositions are observable; payloads are never rewritten.""" + def __init__(self): + self.dispositions = [] + + def ack(self, message): + self.dispositions.append((message.message_id, 'ack', message.attempt)) + + def retry(self, message): + self.dispositions.append((message.message_id, 'retry', message.attempt)) + + def dead_letter(self, message): + self.dispositions.append((message.message_id, 'dead_letter', message.attempt)) diff --git a/evals/worker_consumer/template/consumer/dependency.py b/evals/worker_consumer/template/consumer/dependency.py new file mode 100644 index 0000000..6916cfb --- /dev/null +++ b/evals/worker_consumer/template/consumer/dependency.py @@ -0,0 +1,38 @@ +import asyncio + + +class RetryableError(Exception): + pass + + +class PoisonError(Exception): + pass + + +class Dependency: + def __init__(self): + self.calls = [] + self.started = asyncio.Event() + + async def execute(self, message): + self.calls.append((message.message_id, message.attempt)) + self.started.set() + await asyncio.sleep(0) + mode = message.payload.get('mode', 'success') + if mode == 'cancel': + await asyncio.Event().wait() + if mode == 'retry' and message.attempt < 2: + raise RetryableError('upstream credential=SYNTHETIC_DEPENDENCY_SECRET') + if mode == 'exhausted': + raise RetryableError('SYNTHETIC_BARE_SECRET') + if mode == 'poison': + raise PoisonError('invalid payload SYNTHETIC_PAYLOAD_SECRET') + if mode == 'unexpected': + raise RuntimeError('SYNTHETIC_BARE_SECRET') + return {'message_id': message.message_id, 'amount_cents': message.payload['amount_cents']} + + async def audit(self, message): + await asyncio.sleep(0) + if message.payload.get('audit_fail'): + raise RuntimeError('SYNTHETIC_AUDIT_SECRET') + return message.message_id diff --git a/evals/worker_consumer/template/consumer/observability.py b/evals/worker_consumer/template/consumer/observability.py new file mode 100644 index 0000000..ea3dda7 --- /dev/null +++ b/evals/worker_consumer/template/consumer/observability.py @@ -0,0 +1,43 @@ +"""Public facade: configure(), scope(**fields), info/warning/exception(event, **fields).""" +import json +import logging +import sys +from contextlib import contextmanager + +_context = {} +logger = logging.getLogger('consumer') + + +class Formatter(logging.Formatter): + def format(self, record): + result = {'event': record.getMessage(), 'level': record.levelname.lower()} + result.update(getattr(record, 'fields', {})) + if record.exc_info: + result['exception'] = self.formatException(record.exc_info) + return json.dumps(result) + + +def configure(): + handler = logging.StreamHandler(sys.stderr) + handler.setFormatter(Formatter()) + logger.handlers = [handler] + logger.propagate = False + logger.setLevel(logging.INFO) + + +@contextmanager +def scope(**fields): + _context.update(fields) + yield + + +def info(event, **fields): + logger.info(event, extra={'fields': {**_context, **fields}}) + + +def warning(event, **fields): + logger.warning(event, extra={'fields': {**_context, **fields}}) + + +def exception(event, **fields): + logger.exception(event, extra={'fields': {**_context, **fields}}) diff --git a/evals/worker_consumer/template/consumer/runtime.py b/evals/worker_consumer/template/consumer/runtime.py new file mode 100644 index 0000000..84f20de --- /dev/null +++ b/evals/worker_consumer/template/consumer/runtime.py @@ -0,0 +1,19 @@ +import asyncio +import logging +from . import observability as log + +runtime_log = logging.getLogger('broker.runtime') + + +async def run(consumer, messages): + """Unexpected errors reach runtime; it requeues. Cancellation stays unacked.""" + runtime_log.info('consumer started') + results = await asyncio.gather(*(consumer.handle(m) for m in messages), return_exceptions=True) + for message, result in zip(messages, results): + if isinstance(result, Exception): + consumer.broker.retry(message) + runtime_log.error('consumer failed: %s', result, + exc_info=(type(result), result, result.__traceback__)) + await consumer.drain() + runtime_log.info('consumer stopped') + return results diff --git a/evals/worker_consumer/template/consumer/service.py b/evals/worker_consumer/template/consumer/service.py new file mode 100644 index 0000000..945b577 --- /dev/null +++ b/evals/worker_consumer/template/consumer/service.py @@ -0,0 +1,12 @@ +from . import observability as log + + +async def process(message, dependency): + log.info(f'processing_{message.message_id}', payload=message.payload) + try: + result = await dependency.execute(message) + except Exception: + log.exception('service.failed') + raise + log.info('service.done') + return result diff --git a/evals/worker_consumer/template/consumer/worker.py b/evals/worker_consumer/template/consumer/worker.py new file mode 100644 index 0000000..ca1390e --- /dev/null +++ b/evals/worker_consumer/template/consumer/worker.py @@ -0,0 +1,47 @@ +import asyncio +from . import observability as log +from .dependency import RetryableError, PoisonError +from .service import process + + +class Consumer: + def __init__(self, broker, dependency): + self.broker = broker + self.dependency = dependency + self.background = [] + + async def handle(self, message): + with log.scope(message_id=message.message_id, correlation_id=message.correlation_id): + log.info('message.received', payload=message.payload, attempt=message.attempt) + try: + result = await process(message, self.dependency) + except RetryableError: + if message.attempt < 3: + self.broker.retry(message) + log.exception('message.retry', attempt=message.attempt, retryable=True) + return 'retry' + self.broker.dead_letter(message) + log.exception('message.dead_letter', attempt=message.attempt, retryable=False) + return 'dead_letter' + except PoisonError: + self.broker.dead_letter(message) + log.exception('message.dead_letter', attempt=message.attempt, retryable=False) + return 'dead_letter' + except asyncio.CancelledError: + log.exception('message.cancelled') + raise + except Exception: + log.exception('message.failed') + raise + self.broker.ack(message) + log.info('message.processed', amount_cents=result['amount_cents'], outcome='ack') + self.background.append((message, asyncio.create_task(self.dependency.audit(message)))) + return result + + async def drain(self): + pending, self.background = self.background, [] + for message, task in pending: + try: + await task + except Exception: + log.exception('audit.failed', message_id=message.message_id) diff --git a/evals/worker_consumer/template/tests/test_contract.py b/evals/worker_consumer/template/tests/test_contract.py new file mode 100644 index 0000000..baec0a5 --- /dev/null +++ b/evals/worker_consumer/template/tests/test_contract.py @@ -0,0 +1,37 @@ +import asyncio +import unittest +from consumer.broker import Broker, Message +from consumer.dependency import Dependency +from consumer.worker import Consumer +from consumer.runtime import run + + +class Contracts(unittest.IsolatedAsyncioTestCase): + async def test_dispositions(self): + broker, dep = Broker(), Dependency() + consumer = Consumer(broker, dep) + messages = [Message(mode, 'c-'+mode, {'mode': mode, 'amount_cents': 100}, attempt) + for mode, attempt in [('success', 1), ('retry', 1), ('exhausted', 3), + ('poison', 1), ('unexpected', 1)]] + results = await run(consumer, messages) + self.assertEqual(results[:4], [{'message_id': 'success', 'amount_cents': 100}, + 'retry', 'dead_letter', 'dead_letter']) + self.assertIsInstance(results[4], RuntimeError) + self.assertEqual(sorted(broker.dispositions), sorted([ + ('success', 'ack', 1), ('retry', 'retry', 1), ('exhausted', 'dead_letter', 3), + ('poison', 'dead_letter', 1), ('unexpected', 'retry', 1)])) + self.assertEqual(len(dep.calls), 5) + + async def test_cancel_and_redelivery(self): + broker, dep = Broker(), Dependency() + consumer = Consumer(broker, dep) + task = asyncio.create_task(consumer.handle(Message('cancel', 'c', {'mode':'cancel','amount_cents':1}))) + await dep.started.wait() + task.cancel() + with self.assertRaises(asyncio.CancelledError): + await task + self.assertEqual(broker.dispositions, []) + result = await consumer.handle(Message('retry', 'c', {'mode':'retry','amount_cents':1}, 2)) + self.assertEqual(result, {'message_id':'retry','amount_cents':1}) + await consumer.drain() + self.assertEqual(broker.dispositions, [('retry','ack',2)]) diff --git a/tests/worker_consumer/test_evaluator.py b/tests/worker_consumer/test_evaluator.py new file mode 100644 index 0000000..21106f9 --- /dev/null +++ b/tests/worker_consumer/test_evaluator.py @@ -0,0 +1,79 @@ +import copy +import importlib.util +from pathlib import Path +import shutil +import sys +import tempfile +import unittest + +ROOT=Path(__file__).resolve().parents[2] +HERE=ROOT/'evals/worker_consumer' +sys.path.insert(0,str(HERE)) +from evaluate import evaluate, grade +from repair import repair + + +class EvaluatorTests(unittest.TestCase): + @classmethod + def setUpClass(cls): + cls.temp=tempfile.TemporaryDirectory() + cls.project=Path(cls.temp.name)/'fixed' + shutil.copytree(HERE/'template',cls.project) + cls.bad=evaluate(HERE/'template') + repair(cls.project) + cls.good=evaluate(cls.project) + + @classmethod + def tearDownClass(cls): + cls.temp.cleanup() + + def test_baseline_contracts_and_logging_defects(self): + results={c['id']:c['passed'] for c in self.bad['criteria']} + self.assertTrue(results['business_contract']) + self.assertTrue(results['retry_ack_contract']) + self.assertTrue(results['cancellation_contract']) + for name in ('whole_runtime_json','payload_credential_exception_safety','context_cleanup', + 'single_failure_ownership','formatter_cycle','formatter_object'): + self.assertFalse(results[name],name) + + def test_minimal_repair(self): + self.assertTrue(self.good['passed'],self.good['criteria']) + + def test_observable_mutations(self): + def failure(name, mutate): + observed=copy.deepcopy(self.good['observations']); mutate(observed) + result={c['id']:c for c in grade(observed)['criteria']} + self.assertFalse(result[name]['passed'],result[name]) + failure('formatter_cycle',lambda o:o['cycle']['metadata'].update(emission={'stdout':'','stderr':''})) + failure('formatter_object',lambda o:o['object']['metadata'].update(raised='TypeError')) + failure('formatter_nonfinite',lambda o:o['nonfinite'].update(stderr=o['nonfinite']['stderr']+'{"event":"x","level":"info","n":NaN}\n')) + failure('whole_runtime_json',lambda o:o['workload'].update(stdout='raw runtime error\n')) + failure('retry_ack_contract',lambda o:o['workload']['metadata']['dispositions'].append(['retry','ack',1])) + failure('payload_credential_exception_safety',lambda o:o['workload'].update(stdout='SYNTHETIC_TOKEN_SECRET\n')) + + def test_pre_freeze_review_regressions(self): + def remove_records(observed, predicate): + import json + for stream in ('stdout','stderr'): + observed['workload'][stream]='\n'.join(line for line in observed['workload'][stream].splitlines() + if not predicate(json.loads(line))) + for name, mutate in [ + ('context_cleanup', lambda o:remove_records(o,lambda r:r['event']=='probe.scope_clear')), + ('concurrent_nested_context',lambda o:remove_records(o,lambda r:r['event']=='probe.nested')), + ('background_failure',lambda o:o['workload']['metadata'].update(audit_completed=['audit'])), + ('single_failure_ownership',lambda o:o['workload'].update(stdout='{"event":"runtime.failed","level":"error"}\n')), + ('formatter_cycle',lambda o:o['cycle']['metadata'].update(emission={'stdout':'','stderr':''})), + ]: + with self.subTest(name=name): + observed=copy.deepcopy(self.good['observations']); mutate(observed) + self.assertFalse(next(c for c in grade(observed)['criteria'] if c['id']==name)['passed']) + + def test_safe_fallback_and_optional_lifecycle(self): + observed=copy.deepcopy(self.good['observations']) + for case in ('nonfinite','cycle','object','key'): + observed[case]['stderr']='{"event":"serialization.fallback","level":"warning"}\n{"event":"probe.recovery","level":"info"}\n' + observed[case]['stdout']='' + observed[case]['metadata']['emission']={'stdout':'','stderr':'{"event":"serialization.fallback","level":"warning"}\n'} + for stream in ('stdout','stderr'): + observed['workload'][stream]='\n'.join(line for line in observed['workload'][stream].splitlines() if 'runtime.lifecycle' not in line) + self.assertTrue(grade(observed)['passed'])