Skip to content

Cut no-op reconcile chatter from miren's journal#878

Merged
phinze merged 1 commit into
mainfrom
phinze/mir-1282-cut-miren-log-noise-80-of-gardens-journal-is-no-op-reconcile
Jul 1, 2026
Merged

Cut no-op reconcile chatter from miren's journal#878
phinze merged 1 commit into
mainfrom
phinze/mir-1282-cut-miren-log-noise-80-of-gardens-journal-is-no-op-reconcile

Conversation

@phinze

@phinze phinze commented Jul 1, 2026

Copy link
Copy Markdown
Contributor

Digging through journalctl -u miren on garden, the signal-to-noise ratio was rough: a clean ~1.9h steady-state window held about 80k lines (~700 lines/min, call it 1M lines/day), and roughly 80% of that was reconcile loops heartbeating on every tick even when nothing changed. That's the same theme that bit us in MIR-1279, where garden sat wedged for 14h before a human noticed. A journal that noisy is exactly where a real signal goes to hide.

Three loops drove most of the volume. The sandboxpool sandbox counts debug line was the single highest-volume line in the whole journal, firing per-pool every tick even when actual == ready == desired. The deployment launcher narrated its entire reconcile story at INFO on every pass (reconciling appreconciling app versionfound pools to check and onward), seven lines per app per minute regardless of whether anything happened. And the sandbox controller logged considering sandbox create or update at the top of every reconcile, plus a handful of debug siblings.

The tempting fix is to just demote everything to debug, but garden already runs at debug, so that buys nothing (the highest-volume line was already debug). So instead of demoting, we took a critical eye to whether these lines earn their place at all and cut the pure heartbeats outright. What's left is gated on actual work: the pool status line already only logs on a count change, so we folded desired into it and dropped the redundant counts line. Pool reuse only logs when reuse actually mutates the pool. The deployment loop now emits a single summary line only when it did real work, instead of seven lines of narration. The auto-mount-without-disk-config warning, which was firing for six apps on every tick forever, now warns once per app.

The sandbox considering line lives in both the classic and the saga controller, so we removed it from both to keep things quiet regardless of the labs.Sagas() flag. That meant touching the frozen legacy sandbox.go, which is guarded by a hash test during the saga migration. Per the guard's own instructions I audited the saga path for the parallel change (it was just the twin log line) and bumped the recorded hash.

The two smaller items the issue mentions, the tempo trace-export timeouts and the inbound TLS-handshake scanner noise, are left for separate passes. Those are a different kind of problem than our own loops talking to themselves, and the TLS one in particular wants its own think about http.Server.ErrorLog filtering.

Closes MIR-1282

@phinze phinze requested a review from a team as a code owner July 1, 2026 15:41
@coderabbitai

coderabbitai Bot commented Jul 1, 2026

Copy link
Copy Markdown

Review Change Stack

📝 Walkthrough

Walkthrough

This change reduces log verbosity across several controllers and adjusts pool cleanup accounting. In the deployment launcher, reconcile-start logs are removed, a sync.Map tracks apps already warned about missing disk configuration to warn once per app, and cleanupOldVersionPools now returns a count of cleaned pools used in a conditional summary log. In sandbox, saga controller, and sandboxpool manager, various debug/info logs are removed, a status log gains a desired-instance field, and a frozen-file test hash is updated accordingly.

Changes

Cohort / File(s) Change Summary
Launcher reconcile & cleanup (controllers/deployment/launcher.go) Removes unconditional reconcile logs; adds warnedNoDisk sync.Map for once-per-app warning; changes cleanupOldVersionPools to return (int, error); adds conditional summary log with created/cleaned counts.
Sandbox/saga/sandboxpool logging (controllers/sandbox/sandbox.go, controllers/sandbox/saga_controller.go, controllers/sandboxpool/manager.go) Removes several debug/info logs without altering control flow; adds desired field to a status debug log; updates frozen-hash test expectation.

Sequence Diagram(s)

Included above within the hidden review-stack layer for cleanup summary logging.

Related issues: None mentioned in the provided context.

Related PRs: None mentioned in the provided context.

Suggested labels: logging, refactor

Suggested reviewers: None specified.

Poem:
A rabbit hopped through logs so loud,
Trimming chatter from the crowd,
One warn per app, no more, no less,
Pools now counted, cleaned with success,
Quiet code, a tidier den — thump, thump, again.


Comment @coderabbitai help to get the list of available commands.

@coderabbitai coderabbitai Bot left a comment

Copy link
Copy Markdown

Choose a reason for hiding this comment

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

Actionable comments posted: 1

Caution

Some comments are outside the diff and can’t be posted inline due to platform limitations.

⚠️ Outside diff range comments (1)
controllers/deployment/launcher.go (1)

268-270: 🎯 Functional Correctness | 🟡 Minor | ⚡ Quick win

pools_created count also includes revived pools, not just newly-created ones.

newPoolIDs (populated at Lines 268-270) receives IDs both when ensurePoolForService creates a brand-new pool (Line 530) and when it revives an existing drained pool for deploy verification (Line 473, bootForVerification). The new summary log at Lines 334-338 reports len(newPoolIDs) as pools_created, which will overstate actual pool creation whenever a scaled-to-zero pool is simply revived on redeploy — undermining the goal of this PR to make summary logs accurately reflect real work.

🐛 Proposed fix: track creations and revivals separately
-	var newPoolIDs []entity.Id
+	var newPoolIDs []entity.Id
+	poolsCreated := 0
 	for _, svc := range spec.Services {
 		...
 		poolID, err := l.ensurePoolForService(ctx, app, &ver, spec, svc.Name)
+		created, err := l.ensurePoolForService(ctx, app, &ver, spec, svc.Name) // adjust signature to also report creation
 		...
 		if poolID != "" {
 			newPoolIDs = append(newPoolIDs, poolID)
+			if created {
+				poolsCreated++
+			}
 		}
 	}

Then use poolsCreated (instead of len(newPoolIDs)) in the pools_created log field, and keep len(newPoolIDs) (or a new pools_revived field) separately for readiness-wait bookkeeping.

Also applies to: 330-339

🤖 Prompt for AI Agents
Verify each finding against current code. Fix only still-valid issues, skip the
rest with a brief reason, keep changes minimal, and validate.

In `@controllers/deployment/launcher.go` around lines 268 - 270, The deployment
summary is using newPoolIDs for both newly created pools and revived drained
pools, so pools_created is inflated. Update launcher.go to track actual
creations separately from revivals by using ensurePoolForService and
bootForVerification results to distinguish them, then log pools_created from the
creation counter (poolsCreated) instead of len(newPoolIDs). Keep len(newPoolIDs)
only for readiness-wait bookkeeping or expose a separate pools_revived field if
needed.
🧹 Nitpick comments (1)
controllers/deployment/launcher.go (1)

49-54: 📐 Maintainability & Code Quality | 🔵 Trivial | 💤 Low value

Unbounded growth of warnedNoDisk.

Entries are never evicted (e.g., on app deletion), so this map grows for the lifetime of the process across all apps ever seen. Likely low-impact given expected churn, but worth a TTL/cleanup hook if app churn is high in practice.

🤖 Prompt for AI Agents
Verify each finding against current code. Fix only still-valid issues, skip the
rest with a brief reason, keep changes minimal, and validate.

In `@controllers/deployment/launcher.go` around lines 49 - 54, The warnedNoDisk
sync.Map can grow without bound because entries are never removed after an app
is deleted or no longer needs the warning. Add cleanup/eviction in the launcher
flow that manages app lifecycle, using the relevant app ID path in
controllers/deployment/launcher.go, so warnedNoDisk entries are deleted when an
app is torn down or after an expiry/TTL. Keep the one-time warning behavior in
the reconcile logic intact while ensuring stale keys do not accumulate.
🤖 Prompt for all review comments with AI agents
Verify each finding against current code. Fix only still-valid issues, skip the
rest with a brief reason, keep changes minimal, and validate.

Inline comments:
In `@controllers/sandboxpool/manager.go`:
- Around line 507-511: The "updated pool status" debug log in SandboxPoolManager
should report the same capped desired count used by reconciliation, not the raw
pool.DesiredInstances value. Update the log call in the pool status update path
to use the already-computed desired variable (the capped value) alongside
current and ready so the summary matches the enforced scaling state.

---

Outside diff comments:
In `@controllers/deployment/launcher.go`:
- Around line 268-270: The deployment summary is using newPoolIDs for both newly
created pools and revived drained pools, so pools_created is inflated. Update
launcher.go to track actual creations separately from revivals by using
ensurePoolForService and bootForVerification results to distinguish them, then
log pools_created from the creation counter (poolsCreated) instead of
len(newPoolIDs). Keep len(newPoolIDs) only for readiness-wait bookkeeping or
expose a separate pools_revived field if needed.

---

Nitpick comments:
In `@controllers/deployment/launcher.go`:
- Around line 49-54: The warnedNoDisk sync.Map can grow without bound because
entries are never removed after an app is deleted or no longer needs the
warning. Add cleanup/eviction in the launcher flow that manages app lifecycle,
using the relevant app ID path in controllers/deployment/launcher.go, so
warnedNoDisk entries are deleted when an app is torn down or after an
expiry/TTL. Keep the one-time warning behavior in the reconcile logic intact
while ensuring stale keys do not accumulate.
🪄 Autofix (Beta)

Fix all unresolved CodeRabbit comments on this PR:

  • Push a commit to this branch (recommended)
  • Create a new PR with the fixes

ℹ️ Review info
⚙️ Run configuration

Configuration used: Organization UI

Review profile: CHILL

Plan: Pro

Run ID: 7733d82b-5039-4f27-8359-df63840d7519

📥 Commits

Reviewing files that changed from the base of the PR and between a5ae843 and 357aad9.

📒 Files selected for processing (5)
  • controllers/deployment/launcher.go
  • controllers/sandbox/saga_controller.go
  • controllers/sandbox/sandbox.go
  • controllers/sandbox/sandbox_frozen_test.go
  • controllers/sandboxpool/manager.go
💤 Files with no reviewable changes (2)
  • controllers/sandbox/saga_controller.go
  • controllers/sandbox/sandbox.go

Comment thread controllers/sandboxpool/manager.go Outdated
Garden's journal was running ~1M lines/day, and about 80% of it was
reconcile loops logging on every tick whether or not anything changed.
A journal that noisy is where a real signal hides, which is how MIR-1279
wedged garden for 14h before anyone noticed.

Three loops drove most of the volume: the sandboxpool "sandbox counts"
debug line, the deployment launcher's seven-line reconcile narration,
and the sandbox controller's per-tick "considering sandbox create or
update" and its debug siblings. Garden already runs at debug, so
demoting these would buy nothing; instead we cut the pure heartbeats and
kept only what carries signal.

What survives is gated on real work: the pool status line still only
logs on a count change (now carrying desired too), pool reuse only logs
when it mutates the pool, and the deployment loop emits one summary line
when it actually creates or cleans up pools. The auto-mount-without-disk
warning now fires once per app. The "considering" line is removed from
both the classic and saga controllers so it stays quiet regardless of
the labs flag.
@phinze phinze force-pushed the phinze/mir-1282-cut-miren-log-noise-80-of-gardens-journal-is-no-op-reconcile branch from 357aad9 to 8efe92e Compare July 1, 2026 16:00
@phinze

phinze commented Jul 1, 2026

Copy link
Copy Markdown
Contributor Author

Thanks for the careful read. Two fixes in the latest push: renamed the summary field pools_createdpools_started since that count also includes drained pools revived for deploy verification (booting them is real work, so the honest fix is the accurate label), and the updated pool status log now caps desired at MaxPoolSize to match what reconciliation enforces.

On the warnedNoDisk unbounded-growth note: leaving it as-is for now. The appMu map right above it has the same never-evicted lifetime keyed by every app ID we reconcile, so this stays consistent with the existing pattern, and it's a small transitional set of apps. Happy to add lifecycle eviction for both maps in a follow-up if churn ever becomes a concern.

@evanphx evanphx left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

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

I have any idea for a slog Handler that captures and holds related logs to see if the operation errors out, and if so, it emits all of the logs. We can look at a mechanism like that as well.

@phinze

phinze commented Jul 1, 2026

Copy link
Copy Markdown
Contributor Author

I have any idea for a slog Handler that captures and holds related logs to see if the operation errors out, and if so, it emits all of the logs. We can look at a mechanism like that as well.

Ooo fun idea. Would have to keep an eye on allocs but I like the shape.

@phinze phinze merged commit af5d3cb into main Jul 1, 2026
16 checks passed
@phinze phinze deleted the phinze/mir-1282-cut-miren-log-noise-80-of-gardens-journal-is-no-op-reconcile branch July 1, 2026 20:05
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.

2 participants