spa: rotate every Skillberry log from inside the service that writes it

[aviweit]

spa: rotate every Skillberry log from inside the service that writes it

Base: main ← Head: fix/spa-env-log-rotation

Problem

Logs produced by the SPA arm were unbounded. spa_env captured make's stdout with open("ab") into vendor/<repo>/{store.log,proxy-agent.log} — append, never truncated, never rotated. proxy-agent.log was measured past 100MB, and 14.4MB inside a single 10-minute run. Within a single run the agent's captured stdout grew at 1.10 MB/min ≈ 660MB per 10 hours. Local example runs are affected the same way as CI, since spa_env is what the arms' run.sh uses.

Approach: each service rotates its own log

The only safe place to rotate a live log is inside the process that owns it. spa_env clones both services at pinned refs, so it patches each clone at provision time, between clone and install.

skillberry-agent already had a RotatingFileHandler (5MB × 10) and needed no rotation added. Its problem was the second handler in the same basicConfig call, duplicating every record onto stdout. Dropping console_handler cut /tmp/skillberry-agent.log from 1.10 MB/min to ~16 KB/min (68×) while losing nothing — the records were already in /tmp/tools-agent.log. What remains in the stdout file is output that never passes through the root logger: LiteLLM's own logger (~1900 lines/run), rich's console renderer (~480), and uvicorn's access log (~270). That file is kept, and rotated at start, so those stay available.

The patch also sets the handler's size and count from the same env vars as everything else. Upstream hardcodes maxBytes=5MB, backupCount=10 at main.py:82 with no config key for either, so tools-agent.log was otherwise the one log the knobs could not reach — CAPEVOLVE_SKILLBERRY_LOG_MAX_BYTES=1048576 rotated the store every 1 MB while the agent kept rolling at 5 MB. Wiring these through config/config_structure.py as advanced__log_max_bytes / advanced__log_backup_count is the proper upstream fix and belongs in a PR against skillberry-agent.

skillberry-store shipped no logging configuration at all — only logging.getLogger(__name__) in ~20 modules — so its captured stdout was its only log and nothing could bound it. The patch installs a RotatingFileHandler on the root logger at import time in main.py, ahead of the first store import so SBS()-time records are covered, writing /tmp/tools-store.log (5MB × 10).

Uvicorn's own loggers are deliberately left alone, in both services. An earlier revision rerouted uvicorn / uvicorn.error / uvicorn.access into the rotating handlers. It does not hold, and it loses the access log: every vMCP server constructs uvicorn.Config(...), whose __init__ calls configure_logging() → dictConfig, re-applying uvicorn's defaults process-wide — which, combined with handlers=[], left uvicorn.access with no handler and no propagation. Observed live: a GET returning 200 whose access line appeared in neither log. With uvicorn untouched those lines stay on stdout, where SERVICE_LOG captures them and our start-time rotation bounds them. server.py is therefore not patched at all — a test asserts it comes out byte-identical.

This patch is a deliberate stopgap

Changing the store repository was considered and rejected as too risky for this change. Doing it properly would mean opening a PR against skillberry-store, waiting for it to be reviewed and released, and then moving STORE_REF off 0.2.1 — the tag this arm is pinned to, which the SPA stack has been tested against extensively and which is proven stable in practice. Swapping the store version in order to obtain log rotation would trade a bounded, well-understood problem (disk growth, with a known rate and a known ceiling) for an unbounded one: an unproven store revision sitting underneath every benchmark run, where any regression shows up as reward noise that is expensive and slow to attribute. Log rotation is not worth putting the arm's measurement baseline at risk.

Patching the clone keeps that proven store at 0.2.1 and changes nothing about its behaviour except where its log records are written. It is confined to spa_env, applies at provision time, and is reversible by deleting two functions — no coordination with another repository, no release to wait for, and no new store version under the benchmark.

That said, the long-term direction is the opposite one: rotation belongs in the store itself, and this patch should be retired once it lands there — ideally alongside the next store version bump, when the stack is being re-validated anyway and the risk is being taken deliberately rather than as a side effect of a logging fix.

Until then the patch is built to fail loudly rather than drift. Each one matches an exact snippet of its pinned source and requires exactly one occurrence, so a vanished snippet (0) and an ambiguous one (2+) both stop provisioning — before install, with the file, the anchor name, the occurrence count and the pinned ref in the message. It is idempotent via a marker comment, so re-provisioning is a no-op. Bumping STORE_REF / AGENT_REF (or SKILLBERRY_STORE_REF / SKILLBERRY_AGENT_REF) means owning the patch, rather than silently getting a service whose log grows without limit.

Requirements this satisfies

• Every log under /tmp and only there — nothing under vendor/<repo>, nothing at the repo root, no new directory. env_manager.log moves from the repo root to /tmp and is rotated by the same helper. tau2's environment manager is benchmark-specific and spa_env does not launch it, so the call lives in the benchmark's own examples/skillberry_benchmarks_tau2_airline/spa/run.sh — generic rotation logic in the skill, benchmark-specific invocation in the benchmark. It rotates in the else branch only, never on the "already up" reuse path, since rotating a log a live process holds open is exactly the failure this design avoids.
• SERVICE_LOG pinned explicitly on the make run command line rather than inherited from the vendored default, so rotation cannot silently act on a file nothing writes. A command-line assignment is required: make lets makefile assignments beat the environment unless -e is given. SERVICE_SENTINEL is deliberately left at its default, since SPA_PID_FILE / STORE_PID_FILE hardcode those paths.
• Initialization failures leave their trace on disk. Service crashes reach the service's own log because the shell establishes the redirect before exec. A failure before that — a missing .stamps/srv.env, a Makefile error — is visible only on make's stdout, so it is captured to a transient /tmp/<svc>.start.log, deleted on health-check success and retained with its tail in the raised error on failure.
• setup.sh / run.sh keep their reuse semantics — an existing clone is reused, a healthy service is reused rather than restarted. This is also what makes rotation safe: every rotation call sits below a health short-circuit, so a reused service returns before any log is touched, and its rotation was already done by the call that started it.
• start_spa gains the health short-circuit start_store already had, which rotating its log made mandatory. Because SPA binds ONE skill at start and status() does not report which, reuse verifies SKILL_NAME on the live process and refuses on mismatch rather than silently evaluating the previously bound skill. Unreadable is treated as reusable, so platforms without /proc are not broken.
• Tunable via CAPEVOLVE_SKILLBERRY_LOG_MAX_BYTES and CAPEVOLVE_SKILLBERRY_LOG_BACKUPS, plus CAPEVOLVE_SKILLBERRY_STORE_TOOLS_LOG_FILE and CAPEVOLVE_SKILLBERRY_STORE_LOG_LEVEL. Defaults are 5MB × 10 on both sides — ours and the patched store's — so one variable means the same thing wherever it is read. Readable from the repo-root .env, with a shell export taking precedence.

Test results

Unit tests pass. 1289 passed, 12 skipped — main's 1247 plus the 42 added here, skips unchanged. The tests drive the real rotation and the real launch path rather than inspecting source, because the failure modes are a mis-ordered generation shuffle and a mis-placed call. Coverage includes 12 consecutive rotations leaving exactly the configured number of backups, rotation ordered before launch, OSError degrading instead of blocking a start, and a healthy service being neither restarted nor rotated.

The provision-time patches are covered directly too: they apply to synthetic clones mirroring the pinned sources, are byte-for-byte idempotent across repeated provisions, two patches in one file do not shadow each other, a moved anchor names the file, the anchor and the pinned ref, an ambiguous anchor refuses rather than guessing, and server.py is verified untouched. Three further tests pin the knob contract: a ceiling set only in .env reaches rotation, a shell export beats the file, and run.sh's rotate call is $REPO-anchored and reports failure — that last one runs its subprocess from a foreign cwd, since using the repo root as cwd is what previously let a relative-path defect through.

End-to-end on the full optimisation loop — task 9, 10 trials, 2 iterations on the tau2-airline SPA arm: the store refreshed the skill with each new candidate, and the logs rotated correctly throughout. This is the case where the two halves of this change could have interfered and did not: every candidate goes through reset_store_to_skill + restart_spa, which stops SPA before starting it, so start_spa finds no healthy agent, launches fresh, rotates, and re-reads the new candidate from the store. The reuse short-circuit added here never suppresses that rebinding.

Manual verification:

what	observed
candidate refresh + rotation across a 2-iteration run	task 9, 10 trials, 2 iterations — store picked up each new candidate, logs rotated throughout
store rotation mid-run, default ceiling	process started 13:25, rolled its log at 14:06 with no restart — tools-store.log.1 at 5,242,825 bytes (55 bytes under the 5MB ceiling)
store rotation with CAPEVOLVE_SKILLBERRY_LOG_MAX_BYTES=1048576	rotation every 1 MB, confirming the knob is honoured end to end by the patched handler inside the store process; observed accumulating tools-store.log.1 … .8, each within ~500 bytes of 1 MB
agent's own rotation, mid-run	tools-agent.log.1 … .4 created inside a single run, each ~4.9MB
agent stdout volume	1.10 MB/min → ~16 KB/min after the patch (68× reduction)
log placement	all logs in /tmp; nothing under vendor/, nothing at the repo root
start-captures	no *.start.log left behind after healthy starts

Follow-ups (not in this PR)

• env_manager.log is rotated at start like the others but has no within-run rotation, since tau2's environment manager has no internal rotator and is not ours to patch. At 0.02 MB/min (~12MB per 10 hours) that is two orders of magnitude below the services this PR addresses; bounding it within a run would be a separate, benchmark-side change.
• A malformed value in the env knobs (5MB, lowercase info) raises ValueError rather than falling back to the default. It now surfaces inside rotate_if_large rather than at import spa_env, so a bad value no longer takes down the whole arm, but it is still not a graceful degrade.
• The idempotence marker is unversioned, so editing a patch body does not re-apply it to an already-provisioned clone — that currently needs clean + re-provision.

🤖 Generated with Claude Code

[OsherElhadad]

Reviewed the diff in a separate clone (fix/spa-env-log-rotation vs main). Overall the design is solid (patch-the-clone approach, health short-circuit before rotation, truncate-not-append for the start-capture) and the test suite in test_spa_env_log_rotation.py is genuinely good — it drives real rotation/launch behavior instead of grepping source. A few issues worth a look before merge:

Bug: LOG_MAX_BYTES / LOG_BACKUPS are computed before .env is loaded

LOG_MAX_BYTES = int(os.environ.get("CAPEVOLVE_SKILLBERRY_LOG_MAX_BYTES") or 5 * 1024 * 1024)
LOG_BACKUPS = int(os.environ.get("CAPEVOLVE_SKILLBERRY_LOG_BACKUPS") or 10)

These are evaluated at module import time, but load_env() (which reads the repo-root .env into os.environ) is only called inside provision(), start_store(), start_spa(), etc. — after the module has already finished executing top-level code. So if CAPEVOLVE_SKILLBERRY_LOG_MAX_BYTES / CAPEVOLVE_SKILLBERRY_LOG_BACKUPS are set only in .env (not already exported in the calling shell), rotate_if_large's defaults silently fall back to 5MB/10, contradicting the PR description's claim that these knobs are "readable from the repo-root .env."

Note this doesn't affect the store's own rotating handler (the code string in _patch_store_logging re-reads os.environ.get(...) inside the store process at its own startup, after that process's env is set), only spa_env's own module-level constants used by rotate_if_large() defaults for the captured-stdout logs and env_manager.log.

Fix: read these lazily (e.g. inside rotate_if_large via load_env() first, or as a function instead of a module constant) rather than at import time.

Bug: run.sh's env-manager rotation call uses a cwd-relative import path, silently swallowed

"$PY" -c "import sys; sys.path.insert(0,'skills/interventions/llm-proxies/spa/scripts')
import spa_env; spa_env.rotate_if_large('$ENV_LOG')" || true

skills/interventions/llm-proxies/spa/scripts is relative to the shell's cwd at the time run.sh is invoked, not to $REPO (which the rest of the script computes explicitly and uses, e.g. the ( cd "$REPO" && ... ) subshell right below for the actual env-manager launch). If bash run.sh is invoked from anywhere other than the repo root, import spa_env fails, and the trailing || true swallows the ImportError entirely — rotation for env_manager.log silently never happens, with no diagnostic. Suggest anchoring it: sys.path.insert(0, '$REPO/skills/interventions/llm-proxies/spa/scripts').

(The unit test test_it_is_callable_exactly_the_way_run_sh_calls_it masks this because it explicitly passes cwd=SPA_ENV.parents[5] — i.e. it tests the happy-path cwd rather than the actual invocation contract.)

Risk: store's uvicorn log_config patch assumes keys exist

for _name in ("uvicorn", "uvicorn.error", "uvicorn.access"):
    log_config["loggers"][_name]["handlers"] = []
    log_config["loggers"][_name]["propagate"] = True

This is injected into skillberry-store's server.py and assumes log_config["loggers"] already has all three keys for the pinned STORE_REF. If any is missing (only uvicorn.access was referenced by the pre-existing anchor line), this raises a KeyError at server startup — a runtime failure in the patched file, not something the _apply_patch anchor-count guard would catch at provision time. Worth a defensive .setdefault(_name, {}) or log_config["loggers"].get(_name) guard, or at least a note that this was verified against the actual uvicorn LOGGING_CONFIG shape for that store version.

Minor / already disclosed

• The PR description itself flags that the agent's uvicorn re-routing doesn't work (uvicorn's dictConfig at server start overwrites the import-time handler reassignment) — consistent with what I see in the patch, no action needed beyond what's already noted.
• The ValueError-on-bad-knob and unversioned-idempotence-marker follow-ups are already called out in the PR body as known, deferred — agree these are fine to leave for later.

Nice work on the failure-mode coverage (start-capture tail, reuse short-circuits, OSError degradation) — that part is thorough.

[skillberry-bot]

❌ Automatic Labeling Failed

An error occurred while trying to automatically label this pull request. Please check the workflow logs for details and add labels manually.

[aviweit]

Changes since review #5195267078

Thanks — all three findings were correct and are addressed.

Review findings

• LOG_MAX_BYTES / LOG_BACKUPS read before .env loads — fixed. They are plain defaults now,
  and a new _log_setting() calls load_env() before reading the environment. Your scoping was
  exactly right: the store's own handler was never affected, only spa_env's module constants. The
  PR description's .env claim is now true of the code rather than aspirational.

• run.sh cwd-relative import, silently swallowed — fixed. The sys.path insert is
  $REPO-anchored, and the || true is replaced by a warning on stderr (a rotation failure should
  not abort a benchmark run, but it must not be invisible). Confirmed the old form fails from a
  foreign cwd with ModuleNotFoundError while the new one rotates.

• Store's uvicorn log_config key assumption — removed entirely rather than guarded. Your
  question prompted a closer look, and the block was doing something worse than risking a
  KeyError: it was losing the store's access log. Every vMCP server constructs
  uvicorn.Config(...), whose __init__ calls configure_logging() → dictConfig, re-applying
  uvicorn's defaults process-wide; combined with our handlers=[] that left uvicorn.access with
  no handler and no propagation. Observed live: a GET returning 200 whose access line appeared
  in neither log file. server.py is no longer patched at all, and the seam carries a comment
  explaining why it must stay that way.

• Agent's uvicorn re-routing — you flagged this as already-disclosed and needing no action. It is
  now removed too, for the same reason: dead code that claims to work is worse than none. Uvicorn's
  access lines stay on stdout, land in skillberry-*.log, and remain bounded by our start-time
  rotation.

Also in this update

• The agent's rotation size and count are now under the same knobs as everything else. Upstream
  hardcodes maxBytes=5MB, backupCount=10 at main.py:82 with no config key, so
  tools-agent.log was the one log our variables could not reach —
  CAPEVOLVE_SKILLBERRY_LOG_MAX_BYTES=1048576 rotated the store every 1 MB while the agent kept
  rolling at 5 MB. One variable now means one thing across all four logs. (Wiring these through
  config/config_structure.py as advanced__log_max_bytes / advanced__log_backup_count is the
  proper upstream fix and belongs in a PR against skillberry-agent, noted in the code.)

• Fixed an idempotence bug in the patch layer. _apply_patch used one shared marker, but a file
  can carry more than one patch and a replacement that keeps its own anchor would be re-applied on
  every provision, stacking duplicates. Markers are now per-patch, with an assert that each appears
  in its own replacement.

• Fixed an implicit-Optional annotation. rotate_if_large(logfile, max_bytes: int = None)
  declared int while defaulting to None, so type checkers narrowed it to int, concluded
  max_bytes is None could never be true, and greyed the branch out as unreachable.

• Renamed the parameter log → logfile — it is a path, in a module that also talks about log
  records and log levels.

Tests

Eleven new tests, 1289 passed / 12 skipped (from 1247 on main). Each of the three fixes has a
test that was confirmed to fail without it:

• a ceiling set only in .env reaches rotation; a shell export still beats the file
• run.sh's insert is $REPO-anchored and reports failure — and the subprocess test now runs from a
  foreign cwd, since as you noted it previously passed cwd=<repo root> and so masked the defect
• server.py comes out byte-identical, and the agent patch writes no uvicorn reference
• the patch layer is covered directly now: applies, byte-for-byte idempotent across repeated
  provisions, two patches in one file do not shadow each other, a moved anchor names the file/ref/
  occurrence count, an ambiguous anchor refuses rather than guessing