mkdir log dump on login after new instance creation deep dive.

Cordy commented

2026-09-14 01:35:34 +00:00

Owner

— every login creates a log dump of mkdirs which all already say they exist. Maybe those are not login specific but every time we tagged a new version and bumped it on the homelab

Cordy added this to the v0.7 — Closed beta (dogfood + hardening) milestone

2026-09-14 01:35:34 +00:00

Cordy commented

2026-09-14 02:42:49 +00:00

Author

Owner

Dug through both the live pods and the code — partial result, and one thing I need from you.

What I can rule out: cairnd itself has no mkdir logging anywhere. The login-time directory work is: (1) the home-ensure hook (#146) — on first authentication per username it silently runs Mkdir("/home") + Mkdir("/home/<user>"), errors discarded, once per username per process; (2) scope's lazy ensure — same silent best-effort pattern per prefix, memory-only once-map. The s3 driver's Mkdir even Stats first and returns ErrAlreadyExists without touching the backend. None of these can print a line, let alone a dump.

What matches your observation anyway: both once-maps are memory-only, so every version bump/pod restart resets them — the first login after each deploy re-runs all the ensures. That fits "maybe not login specific but every time we tagged a new version and bumped it" exactly. So the activity is real and expected; the log lines must come from something other than cairnd's own logger.

Verified live: on the current v0.6.191 pods, boot (02:25Z) and your 02:31Z login on files-bao produced zero mkdir lines — the earlier evidence rotated away with the pod replacement.

To pin it down I need: a paste of a few of the actual lines (or a screenshot), and which log you saw them in — cairn-enc, cairn-openbao, openbao-0, the converter, or Garage/TrueNAS. Candidates by shape: Garage logs S3 requests server-side (dir-marker PUTs would show there, not in cairnd); the audit log, if you had the runtime toggle on, records actions and could read like a dump; or a WebDAV client (Finder mount, rclone) issuing MKCOLs would appear as msg=request method=MKCOL ... status=405 lines in cairnd — that's the only way "already exists" text can reach cairnd's request log.

If it turns out to be expected-but-noisy behaviour from a neighbour system, the fix is probably a docs note rather than code; if those lines are cairnd msg=request MKCOL 405s, we should find which client fires them on login.

Dug through both the live pods and the code — partial result, and one thing I need from you. **What I can rule out:** cairnd itself has no mkdir logging anywhere. The login-time directory work is: (1) the home-ensure hook (#146) — on first authentication per username it silently runs `Mkdir("/home")` + `Mkdir("/home/<user>")`, errors discarded, once per username **per process**; (2) scope's lazy ensure — same silent best-effort pattern per prefix, memory-only once-map. The s3 driver's `Mkdir` even Stats first and returns `ErrAlreadyExists` without touching the backend. None of these can print a line, let alone a dump. **What matches your observation anyway:** both once-maps are memory-only, so **every version bump/pod restart resets them** — the first login after each deploy re-runs all the ensures. That fits "maybe not login specific but every time we tagged a new version and bumped it" exactly. So the *activity* is real and expected; the *log lines* must come from something other than cairnd's own logger. **Verified live:** on the current v0.6.191 pods, boot (02:25Z) and your 02:31Z login on files-bao produced zero mkdir lines — the earlier evidence rotated away with the pod replacement. **To pin it down I need:** a paste of a few of the actual lines (or a screenshot), and which log you saw them in — cairn-enc, cairn-openbao, openbao-0, the converter, or Garage/TrueNAS. Candidates by shape: Garage logs S3 requests server-side (dir-marker PUTs would show there, not in cairnd); the audit log, if you had the runtime toggle on, records actions and could read like a dump; or a WebDAV client (Finder mount, rclone) issuing MKCOLs would appear as `msg=request method=MKCOL ... status=405` lines in cairnd — that's the only way "already exists" text can reach cairnd's request log. If it turns out to be expected-but-noisy behaviour from a neighbour system, the fix is probably a docs note rather than code; if those lines are cairnd `msg=request` MKCOL 405s, we should find which client fires them on login.

Cordy referenced this issue from a commit

2026-09-14 13:26:05 +00:00

one-shot: #535 red - already-exists mkdir floods the audit log

forgejo-actions referenced this issue from a commit

2026-09-14 13:26:12 +00:00

test(#535): already-exists mkdir must not be audited (red)

Cordy referenced this issue from a commit

2026-09-14 13:27:54 +00:00

one-shot: #535 green - skip already-exists mkdir events (v0.6.193)

forgejo-actions referenced this issue from a commit

2026-09-14 13:28:36 +00:00

fix(#535): stop auditing ensure-mkdirs that hit already-exists

Cordy referenced this issue

2026-09-14 13:32:41 +00:00

#535: stop auditing ensure-mkdirs that hit already-exists (v0.6.193) #544

Cordy referenced this issue from a commit

2026-09-14 13:33:55 +00:00

Merge pull request '#535: stop auditing ensure-mkdirs that hit already-exists (v0.6.193)' (#544) from fix-535 into main

Cordy commented

2026-09-14 13:42:17 +00:00

Author

Owner

Root-caused and fixed — v0.6.193 shipped (PR #544), live on both dogfoods. Closing.

Your paste was the missing piece: it's the audit log, and the pattern is exact. On the first sign-in after every restart (your 00:44 / 02:31 / 13:12 bursts each follow a version bump), two once-per-process ensures re-run: the home-directory ensure (#146 — the two actor-less "—" rows, since it runs on a background context) and scope's lazy per-prefix ensure (the alternating /spaces + /spaces/<name> pairs, one per space). Both are deliberately best-effort and discard ErrAlreadyExists — but audit.Driver.Mkdir recorded every attempt, so each landed as mkdir — denied · already exists.

Fix: the audit driver no longer records a Mkdir that failed with ErrAlreadyExists. A directory that was already there is neither an action nor a denial — the same reasoning that keeps List/Stat unaudited. Real failures (read-only, holds, backend errors) and successful directory creations still land. TDD: witnessed red (flooded events), full suite green.

Verify: your next login after this deploy (and every one after) should add zero mkdir rows to the audit query.

**Root-caused and fixed — v0.6.193 shipped (PR #544), live on both dogfoods. Closing.** Your paste was the missing piece: it's the **audit log**, and the pattern is exact. On the first sign-in after every restart (your 00:44 / 02:31 / 13:12 bursts each follow a version bump), two once-per-process ensures re-run: the home-directory ensure (#146 — the two actor-less "—" rows, since it runs on a background context) and scope's lazy per-prefix ensure (the alternating `/spaces` + `/spaces/<name>` pairs, one per space). Both are deliberately best-effort and discard `ErrAlreadyExists` — but `audit.Driver.Mkdir` recorded every attempt, so each landed as `mkdir — denied · already exists`. Fix: the audit driver no longer records a Mkdir that failed with `ErrAlreadyExists`. A directory that was already there is neither an action nor a denial — the same reasoning that keeps List/Stat unaudited. Real failures (read-only, holds, backend errors) and successful directory creations still land. TDD: witnessed red (flooded events), full suite green. Verify: your next login after this deploy (and every one after) should add zero mkdir rows to the audit query.

Cordy closed this issue

2026-09-14 13:42:21 +00:00

Rows
Columns

mkdir log dump on login after new instance creation deep dive. #535