Skip to content

fix(embed): bound daemon log growth - #3165

Open
koriyoshi2041 wants to merge 4 commits into
vectorize-io:mainfrom
koriyoshi2041:rios/fix-embed-log-rotation
Open

fix(embed): bound daemon log growth#3165
koriyoshi2041 wants to merge 4 commits into
vectorize-io:mainfrom
koriyoshi2041:rios/fix-embed-log-rotation

Conversation

@koriyoshi2041

Copy link
Copy Markdown
Contributor

Summary

  • rotate a full embedded-daemon log before starting a replacement daemon
  • keep three 10 MiB backups by default
  • allow operators to tune or disable the limit with HINDSIGHT_EMBED_DAEMON_LOG_MAX_BYTES and HINDSIGHT_EMBED_DAEMON_LOG_BACKUP_COUNT

Why

The embedded daemon currently reopens the same profile log in append mode across restarts. Long-running profiles can therefore accumulate multi-gigabyte logs. Rotation happens inside the existing per-profile startup lock, after stale-port cleanup and before the new child opens the file, so no live daemon keeps writing to a renamed inode.

Tests

  • uv run pytest tests/test_daemon_client.py -q (21 passed)
  • uv run ruff check hindsight_embed/daemon_embed_manager.py
  • uv run ruff format --check hindsight_embed/daemon_embed_manager.py tests/test_daemon_client.py
  • uv run ty check hindsight_embed
  • git diff --check

The full embed suite reached 148 passed with three pre-existing environment-sensitive command-selection failures: this slim checkout does not install sentence-transformers, while those tests expect the sibling binary path. The focused daemon suite and type/style gates are green.

Closes #3164

@nicoloboschi nicoloboschi left a comment

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks for this — the approach is right and the call-site placement is the part that matters most: rotating after _clear_port() and after the is_running() re-check, inside the profile lock, before the child opens the file. I verified the rotation loop for backup_count 1/2/3, ran the three new tests, and ruff check/format --check are clean.

A few things to address before this can merge; inline comments have the details.

Blocking

  1. A rotation failure can crash daemon startup — _rotate_daemon_log() is called outside any try, so an OSError escapes start(), which is documented to return False on failure. See the inline comment on the call site.
  2. The embed test jobs never ran on this PR. test-embed and test-embed-windows are gated on needs.detect-changes.outputs.has_secrets == 'true', and fork PRs get no secrets — both show as skipping. The four green checks are docs/generated-file jobs only. A maintainer needs to re-run the full suite via workflow_dispatch on this branch before merge, Windows especially given (1).

Should fix (cheap, same PR)

  1. New config flags need docs — per CLAUDE.md. Add rows to the env tables in hindsight-docs/docs/sdks/embed.md (~L121) and hindsight-embed/README.md (~L159), and spell out what isn't guessable: peak retention is max_bytes × (backup_count + 1) = 40 MiB by default; MAX_BYTES=0 disables rotation, while BACKUP_COUNT=0 deletes the log.
  2. ProfileManager.delete_profile() (hindsight_embed/profile_manager.py:341, outside this diff) unlinks only {name}.log, so {name}.log.1..N — up to 30 MiB per deleted profile — is orphaned. Globbing {name}.log* there closes the loop.

Scope note (not blocking)

Rotation only runs at daemon start, past the is_running() early return. The scenario in #3164 (--idle-timeout 0, months of uptime) never restarts, so that log still grows without bound — this caps the starting size, not growth. That's a legitimate reading of the issue (it lists restart-boundary rotation as an option), but the title "bound daemon log growth" overstates it and I'd keep #3164 open for a live-rotation follow-up rather than auto-closing. Live rotation is feasible later: every writer holds an O_APPEND fd, so copy-then-truncate(0) on the same inode is safe (appends always seek to EOF, no sparse hole).

Separately, the same unbounded-append pattern still exists in hindsight_api/daemon.py (daemonize()~/.hindsight/daemon.log) and for the control-center ui_log — worth a follow-up issue, not this PR.

The second commit (generated docs sync) is legitimate — skills/hindsight-docs/references/** on main is genuinely stale versus the hindsight-docs/ sources and the pre-commit hook regenerates it. Fine to keep as its own commit.


# Create log directory
daemon_log.parent.mkdir(parents=True, exist_ok=True)
self._rotate_daemon_log(daemon_log)

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Blocking: this call is outside any try. The try: below only starts at open(daemon_log, "ab"), and start_daemon() wraps _start_daemon_locked() in try/finally with no except — so any OSError here propagates all the way out of start(), which is documented to return False on failure, and surfaces as a CLI traceback instead.

The realistic trigger is Windows: os.replace()/unlink() on a file another process still holds open raises PermissionError [WinError 32], and _clear_port() killing a stale daemon doesn't guarantee its stdout/stderr handle has been released yet. This module supports Windows explicitly (_detach_popen_kwargs, msvcrt locking), and test-embed-windows was skipped on this PR, so nothing would have caught it.

Log housekeeping must never be able to prevent the daemon from starting:

try:
    self._rotate_daemon_log(daemon_log)
except OSError as exc:
    logger.warning(f"Could not rotate daemon log {daemon_log}: {exc}")

That also covers the exists()stat() TOCTOU on the first line of the method.

DEFAULT_DAEMON_IDLE_TIMEOUT = 0 # 0 = disabled (no auto-exit)
DEFAULT_DAEMON_LOG_MAX_BYTES = 10 * 1024 * 1024
DEFAULT_DAEMON_LOG_BACKUP_COUNT = 3
DAEMON_LOG_MAX_BYTES = _parse_non_negative_int_env("HINDSIGHT_EMBED_DAEMON_LOG_MAX_BYTES", DEFAULT_DAEMON_LOG_MAX_BYTES)

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

These are read at import time and bound as default args at def time, so a value set in a profile .env is silently ignored — only a process-level export before launching the CLI takes effect. That's likely to surprise operators, since profiles are the documented way to configure an embedded daemon, and the PR description says the limit is tunable without that caveat.

HINDSIGHT_EMBED_DAEMON_IDLE_TIMEOUT handles this correctly: it's read off the merged profile config via env.get(...). Rotation runs ~60 lines after load_profile_config(), so the same treatment is a one-liner at the call site:

max_bytes = _safe_non_negative_int(env.get("HINDSIGHT_EMBED_DAEMON_LOG_MAX_BYTES"), DEFAULT_DAEMON_LOG_MAX_BYTES)

Keeping the module constants as the fallback is fine — it's the profile layer that's missing.

Nit while you're here: L73 is 119 chars, right on the 120 limit, while its sibling on L74 is wrapped. Wrap it for symmetry.

return value if math.isfinite(value) and value > 0 else fallback


def _parse_non_negative_int_env(name: str, default: int) -> int:

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Nit: this swallows a malformed value silently — HINDSIGHT_EMBED_DAEMON_LOG_MAX_BYTES=10MB or 1e6 both fall back to the default with no signal, and the operator's next clue is a log that didn't shrink. A logger.warning on the fallback path would save real debugging time.

Also a small asymmetry with the neighbours: _parse_float_env parses and _safe_non_negative_float validates, as two composable steps, while this one does both. Not worth a refactor, but _parse_non_negative_int_env returning the default for a negative value (rather than clamping to 0) is worth a line of docstring.

any stale daemon has been stopped. That keeps child processes from
writing to a renamed inode during rotation.
"""
if max_bytes == 0 or not log_path.exists() or log_path.stat().st_size < max_bytes:

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Two different "zero" semantics meet here and neither is documented anywhere a user will find:

  • max_bytes == 0 → rotation disabled (log grows forever)
  • backup_count == 0 → the full log is deleted (L145-147)

Both are defensible, but the asymmetry — one zero means "do nothing", the other means "destroy the evidence" — will bite someone who sets BACKUP_COUNT=0 expecting "don't keep backups, just start fresh" and instead loses the log that was about to explain a crash. Please state both in the env-var docs, and consider truncate(0) instead of unlink() for the backup_count == 0 path: it keeps the inode, so any fd still held by a dying daemon keeps working instead of writing into an unlinked file.

) -> None:
"""Rotate a full daemon log before a new daemon opens it.

Startup is serialized by the profile lock, and this runs only after

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This docstring states the invariant the whole design rests on — and it's correct today — but nothing in the test suite pins it. A future refactor that hoists _rotate_daemon_log() above _clear_port() (say, to "prepare the log directory earlier") would silently start renaming an inode a live daemon is writing to, and every test would still pass. See my comment on the test file for a cheap way to lock the ordering down.

Worth adding one sentence here too: rotation happens only at start, and only past the is_running() early return — so a daemon running with --idle-timeout 0 (the scenario in #3164) never rotates while it's up.

mock_popen.assert_not_called()


class TestDaemonLogRotation:

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

These three tests exercise the static method directly, which covers the rotation arithmetic well. What's missing is the part the safety argument actually depends on: that rotation is called after _clear_port() / is_running() and before Popen. Nothing currently fails if that ordering is broken.

test_start_daemon_locked_skips_spawn_when_port_already_healthy just above already has the mock-Popen scaffolding — patching _rotate_daemon_log and asserting it isn't called on the already-healthy path, plus asserting it is called before Popen on the spawn path, is a few lines and closes the gap.

Also worth covering:

  • max_bytes=0 leaves an oversized log untouched (the disable switch is completely untested)
  • _parse_non_negative_int_env with a non-numeric and a negative value

assert (tmp_path / "daemon.log.1").read_bytes() == b"current"
assert (tmp_path / "daemon.log.2").read_bytes() == b"previous"

def test_zero_backups_truncates_full_log(self, tmp_path):

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Naming: this doesn't truncate, it deletes — the assertion is not log_path.exists(). Either rename to test_zero_backups_deletes_full_log, or switch the implementation to an actual truncate(0) (which I'd prefer, see my comment on the backup_count == 0 branch) and keep the name.

@koriyoshi2041

Copy link
Copy Markdown
Contributor Author

Addressed the review in faa6888d7:

  • rotation failures now warn and allow startup to continue;
  • limits are read from the merged profile/process environment, with warnings for invalid values;
  • zero backups truncates the existing inode, and profile deletion removes retained backups;
  • added startup-order, zero-limit, invalid-config, and profile-cleanup regressions;
  • documented zero semantics, peak retention, and restart-only scope in both embed docs.

Local validation: full embed suite 154 passed; ty, Ruff check/format, and diff check passed. The fork cannot run the secrets-gated Linux/Windows embed jobs, so maintainer-side workflow_dispatch remains the final platform gate.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

hindsight-embed daemon log is append-only and unbounded (1.2 GB / 13.7M lines)

2 participants