From f4afa76caf61bd14909ef2dbbf8f51a104017668 Mon Sep 17 00:00:00 2001 From: Kwang Moo Yi Date: Tue, 25 Aug 2026 18:41:41 -0700 Subject: [PATCH 1/3] Consolidate the main app's diagnostic logs into one file MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The main app wrote fifteen persistent log files — background_sync, error, chat_error, bg_app_refresh, bg_processing, ai_processing, push, backfill_ai, backfill, inbox, boot, body_render and stuck_messages (BackgroundSyncLogger), plus device_sync (DeviceSyncLogger) and auth_diagnostics (AuthDiagnostics) — each with its own retention policy and its own reader — thirteen byte-capped, a 300-line device_sync ring and a 50-entry auth ring, neither of which bounds a single large message. Diagnosing anything that crossed two subsystems meant exporting several files and re-interleaving them by hand from their timestamps, and a file the reporter forgot was silently absent rather than visibly empty. There are now two persistent log files, one per process: tabmail.log for the main app (new AppLogStore) and nse.log for the notification service extension, whose behaviour is unchanged. Every entry is `[ISO8601] [TAG] message`, and because every writer goes through one serial queue onto one file, a single export carries every subsystem interleaved in append order — the one thing a per-channel file cannot express. Append order, not call order: the timestamp is captured on the caller's thread, so a writer preempted before it reaches the queue lands after one that stamped later and the timestamps can even read as decreasing. Line order is the oracle, not the timestamp. AppLogStore.read(channel:) filters back to one subsystem and clear(channel:) drops one channel's entries while preserving the rest, which is what StuckMessageDiagnostics needs when it clears its own channel before a scan. The Debug menu's Logs section is App Logs plus NSE Logs instead of thirteen per-subsystem buttons plus NSE; the Stuck Message Report button keeps its own section and is not one of the thirteen, though its read/clear closures are repointed at the shared store. Consolidation orphans the fifteen files it replaces. Left in place they are unreadable, unclearable, and counted: StorageEstimator.totalSizeMB() measures Application Support recursively, and SyncEngine.runPruneIfOverBudget answers isOverBudget() by deleting MessageBody and header rows — so orphaned log bytes can buy their own size in pruned mail. That is conditional, not categorical: isOverBudget() is `budgetMB != Int.max && totalSizeMB() >= budgetMB` and defaultBudgetMB is Int.max, so it bites only once a user has configured a finite budget and usage reaches it. Five of the fifteen are written in production builds, where the Debug menu is behind a debug unlock and no user gesture could reach them. StartupMigrations.deleteLegacyLogFiles removes them once, keyed on didDeleteLegacyLogFiles_v1. It names the fifteen explicitly and never enumerates the directory, since a widened pattern would eat tabmail.log itself. It uses unlink(2) rather than FileManager.removeItem: one syscall with no check/use window between deciding and acting, and one that can never recurse, so a directory bearing a legacy name cannot be deleted with its contents. When unlink fails it classifies the entry with lstat(2), so only a real directory entry counts as the deliberate permanent skip and a symlink whose unlink failed is a failure that is retried. That classification is spelled with lstat rather than URL.resourceValues as a behaviour-preserving simplification, not a fix: Foundation's isDirectoryKey does not follow symlinks either, which the code comment records because it is not plainly documented and had to be established empirically. Each name's failure is isolated so one undeletable file cannot strand the other fourteen, and an error that cannot be classified counts as a failure rather than a clean skip. The one-shot flag is armed only after a fully clean pass, which makes a transient obstruction self-heal on the next launch; it is not a promise about a permanently undeletable file, which keeps the pass unarmed at a cost of fifteen unlink syscalls, fourteen returning ENOENT. The flag is deliberately absent from resetFlagKeys, which arms the "Updating…" splash. One shared file means one entry can cost every channel's history, so size is bounded at the store: AppLogStore.append truncates a message at maxEntryScalars, and trimTail refuses to replace a non-empty log with an empty file. Both matter. trimTail keeps the last keepBytes and then advances past the first newline in that tail, so an entry whose only newline is its own terminal byte previously left nothing and the rewrite erased the file — a routine size trim destroying every channel at once. The bound is over unicode scalars rather than Characters because prefix(n) counts extended grapheme clusters, so one "a" carrying thousands of combining marks defeats a Character cap. The two guards are deliberately redundant with each other and with logChatError's own caps. Reads and clears now run inside the serial queue rather than after a drain barrier. A barrier only proves the writes queued before it have landed; an append queued after it ran concurrently with the decode, so an export could observe a half-written entry or a split UTF-8 scalar. Doing the decode inside the queue removes that window and removes the separate flush helper. logChatError additionally bounds and escapes both of its spans inside the façade rather than at each call site, because it is always-on and is the one writer that takes literal user-typed text. Order matters in both directions: capping after escaping slices a generated escape sequence in half and renders as text the user never typed, while escaping without a bound collapses a multi-line message onto one physical line. Its prefix(100) on the user span is a privacy bound, not a size bound, and the two do not substitute for each other. Invariant impact: the always-on versus debug-gated split registered by IOS-LOG-002 is unchanged. BackgroundSyncLogger.log/logError/logChatError, DeviceSyncLogger.log and AuthDiagnostics.log still persist in production; every other channel keeps its `guard DebugModeManager.isLoggingEnabled()`, which gates the print as well as the disk write. AppLogStore itself never gates; the caller owns that decision. No BackgroundSyncLogger log-emission call site was added, removed or re-worded — all 437 `BackgroundSyncLogger.log*(` sites are byte-identical to main. The 40-site drop against main is entirely the per-file `read*Log(`/`clear*Log(` surface this change removes. No pre-existing stdout print site was changed, and IOS-LOG-001/IOS-LOG-003 still own that corpus; two new console sites were added, both in the migration and both debug-gated per rule 12, taking it from eleven to thirteen. The NSE keeps its synchronous append and in-place truncate clear, which are correct for a process that can be hard-killed at any instant; its one modified line is a doc-comment cross-reference following trimTail's move. Four behaviour changes are deliberate. Retention is no longer isolated per channel: one 32 MB cap trimmed back to 16 MB replaces thirteen independent 16 MB budgets, a 300-line device_sync ring and a 50-entry auth ring, so a noisy channel can now evict another's entries, including always-on ERROR and AUTH ones. That is accepted for diagnostics rather than fixed with per-channel floors. AuthDiagnostics gained a UI route it never had — it already had a readLog(), but nothing called it and its doc comment named a Settings > Maintenance row absent from the tree, so its entries were written and unreachable rather than unreadable. Correspondingly they are now destroyed by "Clear All Logs", which previously could not touch them. AuthDiagnostics also writes asynchronously now instead of completing a synchronous atomic write on the caller's thread, including from TabMailApp.init on MainActor; unblocking launch is the better trade and the cost, a tail entry lost to termination, is documented on its own declaration. Verification: TEST BUILD SUCCEEDED from a clean derived-data tree with zero errors and zero compiler warnings; the only diagnostic emitted is the documented benign ExtractAppIntentsMetadata one. The full suite passes. New tests pin that every façade's entries land in the one file, per-channel filtering and clearing over every AppLogChannel case including a leading orphan continuation left by a trim, the always-on versus debug-gated classification derived from allCases so a new channel cannot slip in unclassified, that every debug-gated writer gates its console output as well as its file write, that concurrent writers across channels leave every line parseable, that consecutive appends leave no blank line between entries, that one oversized newline-free entry leaves the log untrimmed instead of erasing it, that the store bounds an entry from a writer which bounds nothing itself, logChatError's privacy cap on ordinary text and its cap-before-escape ordering, ISO8601 timestamps, empty- and missing-file placeholders, and the legacy cleanup's one-shot, never-recursing, failure-isolating behaviour including a symlink-to-directory whose unlink fails. Every test guarding changed behaviour was confirmed to fail against that behaviour's pre-change form, by inverting the change and re-running it. The symlink test is the one exception and deliberately so: it pins the invariant that an entry whose unlink failed counts as a failure, and both the old and new spellings of that classification satisfy it, so it stays green under inversion. The trim tests drive the boundary through test-only overrides; a separate test pins the production 32/16 MB constants themselves. Accepted limitations: entryTag validates the tag against AppLogChannel and requires a delimiter after it but does not validate the timestamp, so "[junk] [SYNC] forged" parses as SYNC — date-parsing every physical line of a 32 MB file is not worth it. Cross-channel line forgery is closed for logChatError only; the other fourteen façades and AppLogStore.append pass their message through unescaped, so a raw newline still yields a line another channel's filtered read will claim and that channel's clear will not remove. The raw-newline caveat is inherited, but consolidation is what made its consequence cross-channel. Reading or clearing from the Debug menu still runs on the calling thread, as it did before. Running a pre-consolidation build after the cleanup has run recreates a legacy file that the armed flag will not remove again, and "Clear All Logs" does not cover it. Some added tests are deliberately weaker than their titles suggest and are recorded rather than hardened here: the dual-write test cannot observe a facade that also writes an absolute legacy path outside the redirected directory, the console-gating test is a lexical scan rather than an injected sink, and the concurrency test is probabilistic. Two further costs are registered rather than fixed, both pre-existing rather than introduced here. trimTail can discard one whole entry more than necessary when size - keepBytes lands exactly on an entry boundary; the unconditional advance past the first newline is byte-identical to v1.7.14 and is kept because it can never leave half a line behind. And unlink resolves symlinks in the parent path, so the lstat classification guards the fifteen names rather than the directory holding them; nothing in the app creates such a symlink, and v1.7.14 extended the same trust from all fifteen loggers on every write. Consolidation also falsifies references in eight routed Companion files that this change does not otherwise touch, which name the per-subsystem log files, the removed share buttons, or BackgroundSyncLogger.trimTail as current. Five of those eight are hash-pinned bodies; the only sanctioned edit to one is a prepended COMPANION-CURRENT-NOTE wrapper, which exact_body strips before hashing, and amending such a body WITHOUT that wrapper is the operation MIS-IOS-009 records. They are therefore corrected in one place — a closed list in topic 122, naming every dead artifact literally so a search for one returns the stale sentence and its correction together — rather than patched at eight sites. The two routed files that register this change, topic 122 and ios-log-002.md, name the same artifacts deliberately and carry their corrections inline here. The known-issues verifier exits 0. The companion-docs verifier reconstructs PROJECT_MEMORY.md and DECISIONS.md byte-identically and passes its ADR-census, ported-decision, memory-routing and ported-topic checks. Its two link checks exit non-zero on pre-existing references to the monorepo-root tree above this checkout — untouched here, and satisfied when the checkout's parent is that root. Signed-off-by: Kwang Moo Yi --- .../Current/122-one-log-file-per-process.md | 405 +++++ Companion/Memory/amendments-manifest.tsv | 1 + .../Current/KnownIssues/ios-log-002.md | 105 ++ PROJECT_MEMORY.md | 1 + Shared/Notifications/NSELogStore.swift | 2 +- .../Account/AccountManagerQueue.swift | 4 +- TabMail/Services/AppLogStore.swift | 527 ++++++ TabMail/Services/AuthDiagnostics.swift | 87 +- TabMail/Services/BackgroundSyncLogger.swift | 514 ++---- TabMail/Services/BootProfiler.swift | 13 +- TabMail/Services/DebugModeManager.swift | 19 + TabMail/Services/DeviceSyncLogger.swift | 57 +- TabMail/Services/StartupMigrations.swift | 197 ++- .../Services/StuckMessageDiagnostics.swift | 7 +- .../Services/Sync/BodyFetchProcessor.swift | 4 +- TabMail/Views/Settings/DebugLogView.swift | 35 +- TabMailTests/Services/AppLogStoreTests.swift | 1567 +++++++++++++++++ .../Services/AuthDiagnosticsTests.swift | 108 +- .../Services/BackgroundSyncLoggerTests.swift | 137 +- .../Services/StartupMigrationsTests.swift | 506 +++++- 20 files changed, 3725 insertions(+), 571 deletions(-) create mode 100644 Companion/Memory/Current/122-one-log-file-per-process.md create mode 100644 TabMail/Services/AppLogStore.swift create mode 100644 TabMailTests/Services/AppLogStoreTests.swift diff --git a/Companion/Memory/Current/122-one-log-file-per-process.md b/Companion/Memory/Current/122-one-log-file-per-process.md new file mode 100644 index 00000000..3ff495cd --- /dev/null +++ b/Companion/Memory/Current/122-one-log-file-per-process.md @@ -0,0 +1,405 @@ +## The main app writes ONE persistent log file, and the NSE writes ONE — never a new file per subsystem (issue #83, 2026-08-25) + +**The rule.** A new persistent diagnostic channel is a new `AppLogChannel` case and a tag. It is +**not** a new file, a new `fileURL` computed property, a new `read*Log()` / `clear*Log()` pair, or a +new share button. There are exactly two persistent log files in this codebase and adding a third is +the defect this topic exists to prevent: + +| process | file | owner | +|---|---|---| +| main app | `tabmail.log` (Application Support / TabMail) | `AppLogStore` | +| notification service extension | `nse.log` (App Group container) | `NSELogStore` | + +**What it replaced.** The main app wrote **fifteen** separate files — +`background_sync.log`, `error.log`, `chat_error.log`, `bg_app_refresh.log`, `bg_processing.log`, +`ai_processing.log`, `push.log`, `backfill_ai.log`, `backfill.log`, `inbox.log`, `boot.log`, +`body_render.log`, `stuck_messages.log` (all `BackgroundSyncLogger`), plus `device_sync.log` +(`DeviceSyncLogger`) and `auth_diagnostics.log` (`AuthDiagnostics`) — each with its own retention +policy and its own reader. ⚠️ NOT "each with its own BYTE cap": thirteen were byte-capped, but +`device_sync.log` used a 300-LINE ring and `auth_diagnostics.log` a 50-ENTRY ring, neither of which +bounds a single large message. ⚠️ **NOT "each with its own share button"** — `auth_diagnostics.log` had none; the +correction is stated in full below and this opening paragraph is where earlier drafts kept +re-introducing the claim, because this is the paragraph other files copy from. The count grew by one +every time a subsystem +wanted a channel, because adding a file was the path of least resistance and nothing said not to. + +**Why one file is not a cosmetic change.** The failures worth diagnosing cross subsystems: a stalled +backfill that surfaces as an inbox reload storm, a push that lands while a BG refresh holds the +database, an AI queue that starves behind a sync error. With per-subsystem files the reporter had to +export several and re-interleave them **by hand** from their timestamps, and any file they forgot +was silently absent rather than visibly empty. **A single file recovers APPEND ordering, which is +the one thing a per-channel file physically cannot express.** That ordering is pinned by a test +(`AppLogStoreTests`, "Entries from different channels interleave in append order"). ⚠️ APPEND +order, not CALL order: a caller preempted between stamping its timestamp and reaching `ioQueue` +lands after one that stamped later, so the timestamps can read as decreasing. Line order is the +oracle. That test is sequential and therefore does not — and is not claimed to — pin a concurrent +call-order guarantee. + +**Entry format and separability.** `[] [] `. `AppLogStore.read()` returns +everything; `read(channel:)` filters back to one subsystem, and `clear(channel:)` drops one +channel's entries while preserving every other — which is what `StuckMessageDiagnostics.run` needs, +since it clears its own channel before each scan and must not take the rest of the file with it. +A physical line with no `[timestamp] [TAG] ` prefix is a **continuation** of the entry above it and +is kept or dropped with that entry; `BackgroundSyncLogger.logChatError` deliberately emits a second +` User message: …` line, and attributing it to nothing would leak it out of a filtered export. + +**⚠️ The gating split is a registered decision and consolidation did NOT change it** (`IOS-LOG-002`). +`AppLogStore.append` does **not** gate — the caller owns that decision, exactly as before: + +- **Always-on** (persist in production): `BackgroundSyncLogger.log`, `.logError`, `.logChatError`, + `DeviceSyncLogger.log`, `AuthDiagnostics.log`. A failure that only reproduces in the field has to + leave a trace, and `IOS-LOG-002` chose this side of a genuinely two-sided trade. +- **Debug-gated** (`guard DebugModeManager.isLoggingEnabled() else { return }`, global rule 12): + every other channel. **The guard gates the `print` too**, not just the disk write — a debug-gated + channel must be a no-op in production on BOTH channels. + +Both directions are pinned by tests, and the pair is deliberately two-sided: "gated channels write +NOTHING while disabled" alone would also pass for a writer that had been accidentally hard-disabled, +so "gated channels DO write once enabled" is its required counterpart. The unlocked half is only +reachable because `DebugModeManager.loggingEnabledOverrideForTesting` exists — in the test host the +real gate is always false (no unlock flag, no session), and its seam default is `nil`, meaning +"derive it exactly as production does" (`MIS-IOS-017`). + +**Retention: what actually changed, stated in the direction that does NOT flatter the change.** +The cap is **32 MB, trimmed back to 16 MB** (raised from 16/8 by owner decision, 2026-08-25). The +trim advances past the first partial line so no PARTIAL PHYSICAL LINE is retained — a line, not +a logical entry: a cut inside `logChatError`'s two-line entry leaves its continuation orphaned. + +⚠️ **An earlier version of this paragraph said `device_sync` and `auth_diagnostics` "retain far +more" and stopped there. That is true of TOTAL BYTES and FALSE of the per-channel floor, and it was +wrong in the direction that hid a regression** — caught by the cross-model review of `8b5e517c4`, +not by the author. The honest statement is two-sided: + +- **Lost: retention ISOLATION.** Before, each of the 13 `BackgroundSyncLogger` files had its **own** + 16 MB budget, `device_sync.log` an unconditional 300-line ring and `auth_diagnostics.log` an + unconditional 50-entry ring. **No channel could evict another.** Now all fifteen share one tail, + so `.sync` — always-on, 137 call sites — can evict the `[ERROR]` and `[AUTH]` entries that a field + report actually needs. The thirteen formerly byte-capped channels (ten debug-gated plus the + always-on `.sync`, `.error` and `.chatError`) therefore have a **narrower guarantee** than before, + and the two ring-retained files have **no floor at all** rather than a larger one. ⚠️ "13 debug + channels" was wrong: the gating split is FIVE always-on to TEN debug-gated, which does not line up + with the thirteen-byte-capped grouping. +- **Gained: a much larger shared budget**, which for any single channel in ordinary use is more + headroom than its old per-file cap gave it. + +**This is an accepted trade, not an oversight** (owner, 2026-08-25: *"increase max to 32, and then +okay if other logs drown things. it's just diagnostics. don't overcomplicate it"*). Per-channel +floors and reserved quotas were considered and **declined**. Do not re-introduce them without +re-opening that decision, and do not restate the retention change as a pure widening. + +**`AuthDiagnostics` gained a UI ROUTE it never had — NOT a reader.** ⚠️ An earlier draft of this +topic, of the `IOS-LOG-002` amendment, and of the commit body all said "gained a reader it never +had." **That is false and it survived two reviews before being caught**: `v1.7.14`'s +`AuthDiagnostics` has a `readLog()` (`git show v1.7.14:TabMail/Services/AuthDiagnostics.swift`, and +`DeviceSyncLogger` had one too). What it lacked was any surface that CALLED it — the Logs section +carried thirteen `LogShareButton`s plus NSE, and **auth was not among them**, so "fifteen files each +with its own share button" is wrong as well. ⚠️ **It is `fourteen` of fifteen, not thirteen, and the +first correction of this sentence got THAT wrong too.** `stuck_messages.log` does have a button — +`LogShareButton(title: "Stuck Message Report", … readLog: BackgroundSyncLogger.readStuckDiagLog)` +at `v1.7.14` — it just lives in the `Stuck Message Diagnostics` section rather than in `Logs`, and +it is still there today. ⚠️ **NOT "untouched":** that symbol has ZERO occurrences in the tree now. +The button keeps its title and its section, but this change REPOINTS both closures at +`AppLogStore.read(channel: .stuckDiag)` / `clear(channel: .stuckDiag)`. Same button, rewritten line. **`auth_diagnostics.log` is the only one of the fifteen with +no share button anywhere.** The transferable error is the one this file already names twice: a +census was scoped to one SECTION and its answer was stated about the whole MENU +(`feedback_census_inherits_its_search_shape`). The predicate that settles it is +`grep -c 'LogShareButton(' TabMail/Views/Settings/DebugLogView.swift` over the WHOLE file — fifteen +at `v1.7.14`, three now — never a reading of the `Logs` section alone. Its own +doc comment named a "Settings > Maintenance > Auth Diagnostics" row that does not exist in the tree, +which is what made the reader unreachable rather than absent. Those entries are now part of the +single App Logs export, so the consolidation *fixed* a reachability gap rather than merely tidying +one. **The generalisable error: "no UI reads it" was restated as "it has no reader," and nobody +checked the type until a second model did.** + +**🚨 Consolidating orphans the OLD files, and orphaned log bytes buy their size in PRUNED MAIL.** +This is the non-obvious consequence and the reason `StartupMigrations.deleteLegacyLogFiles` exists. +The fifteen replaced files survive an upgrade: nothing writes them, nothing reads them, and "Clear +All Logs" no longer knows they exist. That is not merely untidy — `StorageEstimator.totalSizeMB()` +measures Application Support **recursively**, `isOverBudget()` compares it to the user's configured +`globalStorageBudgetMB`, and `SyncEngine.runPruneIfOverBudget` responds by deleting `MessageBody` +and header rows. ⚠️ **State that CONDITIONALLY or it is false** — an earlier draft of this topic, and +of the commit body, asserted it flatly. `StorageEstimator.defaultBudgetMB` is `Int.max` and +`isOverBudget()` short-circuits on `budgetMB != Int.max`, so the pruning consequence exists only for +users who have SET a budget. That is still a real population rather than a theoretical one — the +budget is an ordinary `SettingsView` row, not a debug surface — and for them dead diagnostics +displace real mail. **Five of the fifteen are written in +production** (`background_sync`, `error`, `chat_error`, `device_sync`, `auth_diagnostics` — the +always-on set), where the Debug menu that could once clear them sits behind `debugMode.isUnlocked` +and is unreachable. Hence a **one-shot unlink at launch**, keyed on `didDeleteLegacyLogFiles_v1`, +naming the fifteen files **explicitly** and never enumerating the directory — a widened pattern +would eat `tabmail.log` itself. It is deliberately **not** in `resetFlagKeys`, because that list +arms the "Updating…" splash via `allResetsComplete` and unlinking fifteen small files is not +splash-worthy. + +**The generalisation worth carrying: consolidation is not complete until the predecessors are +gone.** Merging N artifacts into one leaves N orphans that no surface can reach, and "nothing reads +them" is not the same as "they cost nothing" — here the cost was routed through a storage budget +nobody was thinking about. Ask what still measures, sums, or enumerates the container. + +**What this topic does NOT cover, stated negatively (`MIS-019`).** It does not touch the `stdout` +`print` corpus — `IOS-LOG-001` (Views + Services) and `IOS-LOG-003` (calendar family) still own that. +⚠️ **It DID add two `print` sites, and an earlier draft of this topic — and of the commit body — +claimed the opposite.** `StartupMigrations` went from 11 to 13, both new ones in the legacy-log +cleanup, and `TabMail/Services/` is inside `IOS-LOG-001`'s corpus (scope extended 2026-08-05), whose +own range-not-corpus rule says a NEW ungated diagnostic inside a range is still a defect and is still +swept. Both are therefore wrapped in `if DebugModeManager.isLoggingEnabled()` per global rule 12. No +`BackgroundSyncLogger` call site was added, removed or re-worded. It does +not license adding new user-content interpolations to any channel; `IOS-LOG-002`'s negative bound +still binds, and a value that could carry a SECRET is the PRIME DIRECTIVE, not this topic. It does +not change the NSE, whose single file, synchronous-append rationale and in-place-truncate `clear` +are unchanged — `NSELogStore` writes inline precisely because the NSE process can be hard-killed at +any instant, and `AppLogStore`'s async `ioQueue` is correct only for the main app. + +**⚠️ One serial queue for one file is load-bearing, not tidiness.** `DeviceSyncLogger` used to own a +second queue and `AuthDiagnostics` wrote **synchronously on the caller's thread** — including from +`TabMailApp.init` on MainActor. Sharing a file without sharing a serial queue would interleave +partial writes; all three now go through `AppLogStore.ioQueue`. + + +### Four hazards the SHARED file creates that fifteen separate files did not + +Each was found by cross-model review of the first implementation, and each is a consequence of the +same structural change: fifteen private, independently-written artifacts became one shared, +line-oriented, in-place-appended artifact. **This is the transferable list — a future consolidation +of anything line-oriented should expect all four.** + +1. **A torn write now corrupts the NEXT writer's entry, not just its own.** At `v1.7.14` + `AuthDiagnostics` and `DeviceSyncLogger` rewrote their whole file with + `write(to:atomically:true)` — an atomic replace can never leave a partial line — and every other + channel appended to a file only IT wrote. Now all fifteen append in place to one file, so a + process death mid-`write` leaves a partial line onto which the next entry is concatenated: two + entries become one physical line, `entryTag` reads it as the FIRST one's channel, the second is + unfilterable, and `clear(channel:)` on the first channel deletes the survivor with it. + `AppLogStore.appendRaw` therefore opens `forUpdating` (`O_RDWR`, not `O_WRONLY`) and repairs a + missing terminal newline before appending. ⚠️ **Two honest qualifications an earlier draft + omitted.** The repair stops the NEXT entry from merging onto the torn one; it does **not** + reconstruct the torn entry's lost suffix — that evidence is gone, and at `v1.7.14` the two atomic + writers could lose a whole entry but never hold a torn one. And "one 1-byte read is the whole + cost" understates it: requiring `O_RDWR` means a `tabmail.log` that is writable but NOT readable + (mode `0200`) now fails to open at all and every append is silently dropped, where the old + `O_WRONLY` append succeeded. Not reachable for a file the sandboxed app creates and owns, but it + is a real narrowing and it is the cost of the repair, not a free improvement. +2. **One bad byte could destroy the WHOLE artifact, and make it unclearable.** If a torn write + splits a multibyte UTF-8 scalar, `String(contentsOf:encoding:)` throws — which made `read()` + report `(no log)` for the entire file and turned `clear(channel:)` into a silent no-op. A single + byte thus destroyed every channel's history AND removed the means to recover. `decodedFileText` + now decodes lossily (`String(decoding:as:)`, U+FFFD for the invalid sequence). ⚠️ **`nil` is NOT + reserved for the genuinely-missing file, and three places said it was** — `decodedFileText`'s own + doc, `read()`'s doc, and an earlier draft of this paragraph. It is returned for ANY + `Data(contentsOf:)` failure: missing, unreadable (mode `000`), or a directory at the path. So an + existing-but-unopenable log still reports `(no log)` and still makes `clear(channel:)` a silent + no-op — the same "unreadable ⇒ unclearable" pair, surviving for a different cause. Not reachable + inside the app's own sandbox, where it owns and can open its own Application Support files, which + is why this is a documentation-accuracy point first and a robustness note second. +3. **User-authored text can forge ANOTHER channel's entry.** `logChatError` is always-on and + `AIChat` passes literal user-typed `userText`. A typed newline followed by `[x] [AUTH] …` yields + a second physical line that parses as a real AUTH entry: it surfaces in `read(channel: .auth)`, + truncates the real entry in `read(channel: .chatError)`, and survives + `clear(channel: .chatError)`. Confined to `chat_error.log` this was harmless; the shared file is + what makes it cross-channel. The user span is now escaped **inside the façade** (cap first with + `prefix(100)`, escape second, so the cap can never slice an escape sequence), which is the one + deviation from the otherwise call-site-owned escaping rule. +4. **A one-shot deletion of the predecessors must never be able to recurse.** `removeItem(at:)` is + documented recursive, and guarding it with an `isRegularFile` query does not help — the query and + the removal are two syscalls with a window between them, so a directory appearing at a legacy + name in that window is deleted with its contents, at launch, before any UI exists to report it. + The cleanup uses `unlink(2)`: one syscall, no check/use window, refuses a directory outright, and + removes a symlink's LINK rather than reaching through to its target. Darwin returns `EPERM` for + BOTH a directory and an immutable file, so the ambiguity is resolved by an `lstat(2)` call that + only CLASSIFIES (no removal follows it), and an unresolvable answer counts as a **failure**, + never a clean skip — erasing it would arm the one-shot flag and strand that name's bytes + forever. That last point is the general one: **`try?` on a metadata query, feeding a one-shot + completion flag, converts "I could not tell" into "nothing to do, done forever."** + + ⚠️ **`URL.resourceValues(forKeys: [.isDirectoryKey])` does NOT follow symlinks.** A review round + asserted the opposite — that the original `.isDirectoryKey` spelling would resolve a + symlink-to-directory as a directory and silently convert a failed `unlink` into the deliberate + permanent skip. It does not. Measured directly against Foundation on a symlink pointing at a + directory: `.isDirectoryKey` is `false`, `.isSymbolicLinkKey` is `true`, `lstat` reports + not-a-directory and only `stat` (which does follow) reports one. Corroborated a second way, by + inverting the line in the simulator and re-running `StartupMigrationsTests`, which stays green + precisely because both spellings agree. The `lstat` spelling shipped anyway — it states the + no-follow requirement in the call itself instead of relying on an undocumented Foundation + behaviour — but it is a **behaviour-preserving simplification, not a defect fix**, and the + symlink test therefore cannot be red-proofed against it. The transferable lesson is about + reviews, not about files: **a reviewer's MECHANISM can be sound while its CLASSIFICATION is + wrong.** "`resourceValues` resolves the URL" is true in general and false for this specific key; + the finding read as correct because the mechanism was plausible. Verify the classification + against the actual API before recording a fix as a fix, or the changelog inherits a defect that + never existed. + +### Accepted costs, registered rather than fixed + +- **`clear(channel:)` went from O(1) to O(whole file).** At `v1.7.14` + `BackgroundSyncLogger.clearStuckDiagLog()` was one `"".write(to:atomically:)`. It is now a full + read → filter → atomic rewrite of a file capped at 32 MB, and `StuckMessageDiagnostics.run()` + calls it at the top of every scan from a nonisolated `async` context, blocking a cooperative-pool + thread. Transient peak memory is roughly 4× the file. Reachable only with debug logging unlocked + (`DebugMenuView` is behind `debugMode.isUnlocked`; `StuckMessageDiagnostics.run` guards on + `isLoggingEnabled()`), so no production user reaches it — but the five always-on channels can + genuinely grow the file to the cap, so the size input is real. +- **Ordering is carried by LINE ORDER, not by the timestamp.** `append` stamps with + `iso8601String()` — `withInternetDateTime`, **second** precision — and captures it on the caller's + thread before `ioQueue.async`. Two threads can therefore enqueue in the opposite order to their + capture. ⚠️ An earlier draft said this is unobservable because both render the same second. That + is FALSE: a capture at `…:00.999` preempted past a capture at `…:01.001` that enqueues first puts + a VISIBLY DECREASING pair of timestamps on disk. The + serial queue still writes in submission order, so the file reads correctly; but do not describe + the timestamps as the ordering oracle. Sub-second interleaving is read from line order. +- ~~**`read()` is not serialized against writers after its drain barrier.**~~ **RETRACTED — closed + in this same change, and this bullet is kept only so the retraction is searchable.** An earlier + draft shipped a `flushPendingWrites()` barrier and decoded OUTSIDE `ioQueue`. A barrier only + proves the writes queued BEFORE it have landed; an append queued after it ran concurrently with + the decode, so a share could observe a half-written entry or a split UTF-8 scalar. Both readers + now decode INSIDE `ioQueue.sync` and `flushPendingWrites` no longer exists — it has zero + occurrences in Swift. **The general form: a drain barrier is not mutual exclusion.** It orders + the past and says nothing about the future, so it is the wrong tool whenever the reader must not + overlap a concurrent writer. +- **The trim is physical-line-safe, not entry-safe.** It advances past the first newline in the + retained tail, which is correct for the fourteen single-line channels. A cut inside the first line + of `logChatError`'s deliberate two-line entry leaves the `User message:` continuation as a leading + orphan: filtered reads drop it (both `filter` and `clear(channel:)` treat a leading orphan the same + way, which is what makes "unreadable but unclearable" impossible), while the unfiltered export + shows it without its channel. ⚠️ **This paragraph has now been wrong TWICE, in OPPOSITE + directions, and both retractions are kept because the pair is the lesson.** Draft one said "no + writer can produce an entry larger than the cap" — false: `logChatError` bounded its user span + with `prefix(100)`, which counts extended grapheme CLUSTERS, so one pasted grapheme carrying an + unbounded run of combining marks passed that cap intact (`MIS-IOS-013` — **a SIZE question asked + with a grapheme-level `String` API, and the answer believed**). Draft two then said "a single + entry larger than the cap is not trimmed, it ERASES the file" — true of the code at the time, and + false of the code this topic now describes. Both holes are closed at the STORE: `append` bounds + every channel at `maxEntryScalars` (unicode scalars, which one grapheme cannot defeat), and + `trimTail` refuses to write an empty file. **Current behaviour: such a trim is ABANDONED — the + log is left untrimmed and above its cap, neither erased nor trimmed** — which is deliberate, + because keeping an oversized file beats deleting a non-empty one, and the next bounded append + puts a newline inside the tail so the following trim succeeds. Do not restate the erase claim; it + describes a superseded draft. +- **A permanently undeletable legacy file re-runs the fifteen-name scan every launch, forever.** The + flag arms only on a clean pass, which is what makes a TRANSIENT obstruction self-heal; it is not a + strict-progress guarantee. Arming after a partial pass would be strictly worse. The cost is + fifteen `unlink` calls, fourteen returning `ENOENT` immediately. +- **The trim is entry-lossy at an aligned boundary, and that is PRE-EXISTING, not new.** When + `offset = size - keepBytes` happens to land immediately after a newline, the retained tail already + begins at a line boundary — and the unconditional "advance past the first newline" discards that + first PHYSICAL LINE anyway. Note the unit: a physical line, not an entry. For the fourteen + single-line channels the two coincide, but if the retained tail opens on `logChatError`'s + deliberate two-line entry, what is dropped is its tagged HEAD, leaving the `User message:` + continuation as a leading orphan — the same orphan class the bullet above describes. `v1.7.14`'s + `BackgroundSyncLogger.trimTail` is byte-identical on this point, so consolidation neither + introduced nor widened it. **Deliberately not fixed:** the unconditional form can never leave half + a line behind, and losing one extra line from a 16 MiB retained tail of diagnostics is exactly the + redundant work this repo prefers over conditional cleverness. No remedy is prescribed here on + purpose — an earlier draft stated one and stated its predicate BACKWARDS. +- **The cleanup trusts the CONTAINER DIRECTORY, only its final path components.** `unlink` resolves + symlinks in the PARENT path, so if `Application Support/TabMail` were itself a symlink, the + fifteen unlinks would follow it; the `lstat` classification guards the final component only. + **Deliberately not fixed.** Pinning the directory with `O_DIRECTORY | O_NOFOLLOW` + `unlinkat` is + the mechanical fix, but the premise is unreachable in the iOS sandbox: nothing in the app creates + that symlink, and anyone who could plant it already has arbitrary write access to the container. + `v1.7.14` extended the identical trust — all fifteen loggers resolved the same parent path on every + write — so this is the app's standing container assumption, not something consolidation introduced. + Worth stating because the finding LOOKS like a directory-traversal defect and will be re-raised. + + +### Three more guarantees the shared file gives up, none of them obvious + +Recorded because each was missed by at least one reviewer and none is visible from the diff alone. + +- **Filesystem failure isolation is gone.** At `v1.7.14`, making `push.log` unreadable broke PUSH and + nothing else. One unreadable `tabmail.log` now hides and disables **all fifteen** channels at once. + Consolidation converts fifteen independent single points of failure into one shared one — the + ordinary cost of consolidation, worth stating rather than discovering. +- **`DeviceSyncLogger` lost its queue independence.** It owned a second serial queue; it now shares + `AppLogStore.ioQueue` with fourteen other channels including the 137-site always-on `.sync`. A + device-sync entry enqueued behind a flood of large entries can be lost to termination in a way it + could not before. This is the same trade already recorded for `AuthDiagnostics`' synchronous write, + reached by a different route, and the commit body originally recorded only the Auth half. +- **`logBoot` entries gained a timestamp they never had.** At `v1.7.14` the façade wrote + `line + "\n"` with no timestamp at all — `BootProfiler.mark` supplies its own + `[BootProfile +Nms (ΔNms)]`. Boot lines are now `[ISO8601] [BOOT] [BootProfile …]`. Additive and + unavoidable given the shared envelope, nothing parses the old format, but it is the ONE writer + whose on-disk text changed beyond the mandated tag insertion, so "no call site was re-worded" — + true about call sites — does not cover it. + +Also worth knowing, though a cost rather than a lost guarantee: **`read()` runs on MainActor from the +share button.** `LogShareButton`'s action calls its injected `readLog()` — now `AppLogStore.read`, +which decodes INSIDE `ioQueue.sync` — and then writes a temp file, roughly 2× the file, +synchronously, before the share sheet appears. (An earlier draft called the now-deleted +`flushPendingWrites()`; the main-actor cost is unchanged by that swap, and is now additionally a +wait on any queued write or trim.) `v1.7.14`'s largest BYTE-CAPPED button was a 16 MB +`background_sync.log` — not an overall maximum, since `device_sync.log`'s 300-LINE ring bounded no +line's length and could exceed it; the cap +is now 32 MB. Debug-only, and the counterpart to the `clear(channel:)` entry above. + +## Routed files this change falsified, and why they were not edited in place + +Consolidation makes references in eight routed files factually wrong — eight files this change +does **not** otherwise touch. Two further routed files name the same dead artifacts deliberately, +because they are what registers this change: this topic, and +`Companion/Process/Current/KnownIssues/ios-log-002.md`. Both carry their corrections inline in this +same commit, so neither is listed below and neither is a counterexample to the closure claim at the +end. The eight are listed here, with their corrections, **rather than patched at each site**, and +the reason is mechanical: five of the eight are hash-pinned bodies in +`Companion/Memory/manifest.tsv` / `Companion/Decisions/manifest.tsv`. The only sanctioned edit to +such a body is a prepended `COMPANION-CURRENT-NOTE` wrapper, which `exact_body` in +`Scripts/compact_companion_docs.rb` strips before hashing — ⚠️ the wrapper is the SAFE operation, +and amending one of these bodies *without* it is the one `MIS-IOS-009` records, repeatedly aborting +the verifier on its first check. This repo's routing +protocol makes the **`rg` result set** the reachable surface, not the individual file, so a search +for any dead artifact below returns the stale sentence and this correction together. That is the +whole requirement, and it costs one edit instead of eight. + +The dead artifacts, spelled out so they match a literal search: `background_sync.log`, `error.log`, +`chat_error.log`, `bg_app_refresh.log`, `bg_processing.log`, `ai_processing.log`, `push.log`, +`backfill_ai.log`, `backfill.log`, `inbox.log`, `boot.log`, `body_render.log`, `stuck_messages.log`, +`device_sync.log`, `auth_diagnostics.log`, `BackgroundSyncLogger.trimTail`, and the share buttons +"Error Logs", "Backfill Logs" and "Boot Profile Logs". + +Every per-file destination below is now `tabmail.log`, read with `AppLogStore.read(channel:)` and +exported by the single **"App Logs"** button. **The `BackgroundSyncLogger.log*` façades all survive** +— `logError`, `logBackfill`, `logInbox` and `logBoot` are unchanged as call sites; only their +destination and their reader moved. Citations are by quoted phrase, not line number +(`feedback_line_citations_go_stale`). + +- **`Companion/Memory/Current/105-a-print-is-not-production-observability-on-ios.md`** — "appended to + `error.log`, exported by `DebugLogView`'s *"Error Logs"* share button". Both halves are now wrong: + the destination is `tabmail.log` under the `[ERROR]` tag, exported by "App Logs". The point the + sentence is making — that `logError` is ungated at the write — is **unaffected and still true**. +- **`Companion/Process/Current/KnownIssues/ios-scroll-003.md`** — the same phrase, "(`error.log`, + exported by `DebugLogView`'s "Error Logs")", with the same correction. Its argument, that this is + a developer channel rather than a user-visible surface, is unaffected. +- **`Companion/Memory/Current/027-backfill-diagnostics-backfill-log-channel-2026-07-02.md`** — its + title and its "`BackgroundSyncLogger.logBackfill` → `backfill.log` (debug-gated, exported as + "Backfill Logs" in the Debug menu)". The façade and the debug gate are both unchanged; the + destination is the `[BACKFILL]` tag in `tabmail.log`, exported by "App Logs". This file also + names the dead EXPORT filename `backfill_ai_logs.txt`, and is the only routed file citing a dead + export name. (Deliberately not restated here: how many exports the app has NOW. This + section's job is to make DEAD names reachable; a live count is a new falsifiable claim that + serves no part of that job and would need re-verifying on every UI change.) +- **`Companion/Memory/Current/029-bodycomplete-fts-indexed-truth-display-cache-has-no-flag-adr-ios-050-202.md`** + — two hits. "`backfill.log` showed pending…" is **historical narration of a 2026-07 investigation + and was true when written**; leave it read as history. "Asset evictions now log to `backfill.log`" + is present-tense and now means the `[BACKFILL]` tag in `tabmail.log`. +- **`Companion/Decisions/Active/adr-ios-050.md`** — the same two shapes. Its **Context** paragraph + ("`backfill.log` showed the body-pending population climbing") is historical; its consequence 3 + ("logs victims + MB reclaimed + duration to `backfill.log`") is present-tense and now the + `[BACKFILL]` tag in `tabmail.log`. The consequence itself — that eviction is observable — holds. +- **`Companion/Memory/Current/033-optimistic-ui-rollback.md`** — `inbox.log`, now the `[INBOX]` tag + in `tabmail.log`. +- **`Companion/Memory/Current/072-persistent-nse-log-file-watchdog-partial-result-delivery-2026-07-09.md`** + and + **`Companion/Memory/Current/099-persistent-nse-log-file-watchdog-partial-delivery-audit-rounds.md`** + — both carry the same sentence twice over. `BackgroundSyncLogger.trimTail` is a **dead symbol** + (zero Swift occurrences); the function moved to `AppLogStore.trimTail`, and the point being made + about it — that an atomic external replace would orphan a cached `FileHandle` onto a deleted + inode, which is why `NSELogStore` truncates in place instead — is **still exactly true of + `AppLogStore.trimTail`**, so only the name is stale. Both also say the "NSE Logs" button "mirrors + the "Boot Profile Logs" pattern"; that button is gone, and "NSE Logs" now sits beside "App Logs" + as one of the two buttons the **Logs section** now has. `DebugLogView` declares three + `LogShareButton`s in all — the third, "Stuck Message Report", sits in its own section and was + never one of the thirteen, so a whole-file count and a Logs-section count differ by one here. + +⚠️ **This list is closed under the nineteen artifacts named above — the fifteen log files, `BackgroundSyncLogger.trimTail`, and the three share-button titles — and nothing else.** It is wrong the moment a +further routed file cites a per-subsystem log file, or a future change moves `tabmail.log` itself. +It does **not** cover `Companion/Memory/History/` or `Companion/Process/History/`, which are +snapshots and are supposed to read as of their date. diff --git a/Companion/Memory/amendments-manifest.tsv b/Companion/Memory/amendments-manifest.tsv index e577b65c..2d281134 100644 --- a/Companion/Memory/amendments-manifest.tsv +++ b/Companion/Memory/amendments-manifest.tsv @@ -9,3 +9,4 @@ order source_rev status source_lines sha256 path title 7 working-tree current 115-149 9948edda6c42dd06af636641449013e2709cfffd7bf0101c61e3e4e2ed7c3b89 Companion/Memory/Current/111-the-address-problem-root-cause-behind-most-action-queue-complexity.md THE ADDRESS PROBLEM — the root cause behind most action-queue complexity 8 working-tree current - 1dc732841320d067f5dbab758af972a4e9c3c68b27e258b45fdb0e45dc92fa3c Companion/Memory/Current/120-an-affordance-is-bounded-by-the-durable-state.md An affordance's lifetime is bounded by the DURABLE state that backs it, never by when the UI happened to appear (issue #76, 2026-08-20) 9 744977a6d historical 9-17 e03524a3af3f5095f2ab3d82f4b06b7f72dc7fa3ed80e4a4d3c5ed79f88b4aab Companion/Memory/History/121-project-memory-index-usage-preamble-before-pass-6.md PROJECT_MEMORY.md index-usage preamble before companion-compact pass 6 +10 working-tree current - 1c7fea224c1f94a40f2daf269b6c18f53646fb49e9443c0ec20ef057fd9e780f Companion/Memory/Current/122-one-log-file-per-process.md The main app writes ONE persistent log file, and the NSE writes ONE — never a new file per subsystem (issue #83, 2026-08-25) diff --git a/Companion/Process/Current/KnownIssues/ios-log-002.md b/Companion/Process/Current/KnownIssues/ios-log-002.md index cf167c28..593b8ae5 100644 --- a/Companion/Process/Current/KnownIssues/ios-log-002.md +++ b/Companion/Process/Current/KnownIssues/ios-log-002.md @@ -1,3 +1,108 @@ + +> **⚠️ AMENDMENT (2026-08-25, GitHub #83) — THIS ROW'S CHANNEL 2 MOVED FILES. THE DISPOSITION IS +> UNCHANGED (still CLOSED AS A DECISION), and the body is preserved unedited because it is +> regenerated from the hash-pinned archive and byte-compared.** +> +> Channel 2 below is described as `BackgroundSyncLogger` "appended to a file in the app container, +> and **exported by `DebugLogView`'s share buttons**". Both halves are still true of the CHANNEL and +> now name the wrong artifacts. The main app's **fifteen** persistent log files were consolidated +> into **one** — `tabmail.log`, owned by the new `AppLogStore` — and the Logs section's thirteen +> per-subsystem share buttons became a single "App Logs" button (its "NSE Logs" button is genuinely +> unchanged, and the separate "Stuck Message Report" button keeps its title and its `Stuck Message +> Diagnostics` section — but ⚠️ NOT "untouched": both of its closures are repointed at +> `AppLogStore.read/clear(channel: .stuckDiag)`, so only the NSE button is byte-identical). `error.log` no longer exists as a +> file; the same entries are now `[ERROR]`-tagged lines in the shared file, recoverable with +> `AppLogStore.read(channel: .error)`. +> +> **Nothing this row dispositions has changed, which is why this is an amendment and not a +> re-opening:** +> - **The always-on set is identical.** `BackgroundSyncLogger.log` / `.logError` / `.logChatError`, +> `DeviceSyncLogger.log` and `AuthDiagnostics.log` still persist in production; every other channel +> still carries its `guard DebugModeManager.isLoggingEnabled() else { return }`. Consolidation +> deliberately moved neither side of the trade this row decided, and both directions are now pinned +> by tests in `AppLogStoreTests` ("Always-on channels persist while debug logging is DISABLED", +> "Debug-gated channels write NOTHING while debug logging is DISABLED", and its required +> counterpart "Debug-gated channels DO write once debug logging is enabled"). +> - **Class B and Class C are untouched.** No `BackgroundSyncLogger` CALL SITE was added, removed or +> re-worded, so the interpolations this row defers — the account holder's own address, and +> user-authored folder names — are the same sites with the same text. ⚠️ **The `412` / `51` / `12` +> figures below were NOT re-derived here**; they are rev-pinned leads, not bounds (`MIS-044`), and +> the predicate to re-run is the LINE-oriented one the body states. +> - **Exposure (d) is unchanged in kind, but its PER-ACTION PAYLOAD is BROADER.** ⚠️ An earlier +> draft called it "marginally narrower … one button rather than thirteen"; that conflated fewer +> BUTTONS with less EXPOSURE and contradicted this row's own AUTH-widening note below. Sharing is +> still an explicit user action, but one App Logs share now exports all fifteen main-app channels +> — including AUTH and CHAT — where sharing PUSH once exported `push.log` alone. +> - **Channel 1 (`NSELog` / unified log) is not touched at all.** The NSE keeps its own separate +> `nse.log` and its own `os_log` behaviour. +> +> **One thing genuinely CHANGED and is recorded here rather than left to be re-discovered:** +> `AuthDiagnostics` wrote `auth_diagnostics.log`, which **no** Debug-menu surface ever read — its own +> doc comment named a "Settings > Maintenance" row that does not exist in the tree. ⚠️ **It DID have a +> `readLog()`** (`v1.7.14:TabMail/Services/AuthDiagnostics.swift`); an earlier draft of this amendment +> said it "gained a reader it never had," which is false — it gained a UI ROUTE. `v1.7.14`'s Logs +> section had thirteen share buttons plus NSE, with auth absent. ⚠️ An earlier wording of this +> sentence added "and stuck-messages", which is FALSE: `stuck_messages.log` has its own "Stuck +> Message Report" button in the `Stuck Message Diagnostics` section. Counting the whole file, +> `v1.7.14` had FIFTEEN `LogShareButton`s and `auth_diagnostics.log` is the only one of the fifteen +> log files with none. Those entries +> were therefore written and UNREACHABLE, not unreadable. They are now inside the single App Logs export, so this row's Class B +> "`BackgroundSyncLogger` corpus … exported by share buttons" reasoning now reaches the auth channel +> too. That is a WIDENING of what a shared export can contain, it is stated here rather than +> silently absorbed, and it does not change the disposition: the content is the account holder's own +> address on their own device, which is exactly the exposure (d) already accepts. +> +> **⚠️ THE ABOVE RECORDED ONLY HALF OF THAT WIDENING, AND THE MISSING HALF POINTS THE OTHER WAY** +> (added 2026-08-25 after the review of `8b5e517c4`; the author recorded the reader and +> not the destroyer — `feedback_fix_produces_mirror_image_bug`). Auth entries gained a **UI ROUTE** +> — the wording corrected two paragraphs above, restated correctly here so this sentence cannot be +> read on its own as the retracted "reader" claim — and they also gained a **DESTROYER**. At `v1.7.14` `AuthDiagnostics` had **no clear function at all** +> and was absent from `DebugLogView` entirely, so its entries were immune to every clear surface in +> the app. They are now inside `tabmail.log`, which "Clear All Logs" wipes. The support flow "clear +> the logs, reproduce, share" therefore now destroys the auth history that predates the repro — +> precisely the history the channel's own doc comment says must "survive an unexpected logout". +> **Owner decision, 2026-08-25: keep it** (*"Clear all should clear all. never used excluded auth +> logs anyway"*). Excluding auth from Clear All was considered and declined; do not re-add an +> exclusion without re-opening this. +> +> **Also recorded rather than left to be re-discovered: retention ISOLATION was lost.** Each of the +> 13 `BackgroundSyncLogger` files had its own 16 MB budget, `device_sync.log` a 300-line ring and +> `auth_diagnostics.log` a 50-entry ring, and **no channel could evict another**. One shared tail +> (now 32 MB / 16 MB) means `.sync` — always-on, 137 call sites — can evict the `[ERROR]` and +> `[AUTH]` entries this row's (c) rationale calls the primary field-debug artifact. Accepted by the +> owner as "just diagnostics"; per-channel floors were declined. This does not change the +> disposition, but it does narrow what (c) can promise: the channel still exists, its retention is +> no longer independent of unrelated traffic. +> +> **And the fifteen replaced files are now unlinked once at launch** +> (`StartupMigrations.deleteLegacyLogFiles`, flag `didDeleteLegacyLogFiles_v1`). Left in place they +> were unreadable, unclearable, and — via `StorageEstimator.totalSizeMB()` → `isOverBudget()` → +> `SyncEngine.runPruneIfOverBudget` — would have displaced real mail rows. Five of the fifteen are +> written in production, where `DebugMenuView` is behind `debugMode.isUnlocked` and unreachable, so +> no user gesture could ever have removed them. +> +> **One thing this change NARROWS, recorded for symmetry with the widening above.** `logChatError` +> is always-on and `AIChat` passes literal user-typed `userText` into it. Unescaped, a user who typed +> a newline followed by `[x] [AUTH] …` produced a second physical line that parses as a genuine AUTH +> entry — surfacing in `read(channel: .auth)`, truncating the real entry in +> `read(channel: .chatError)`, and surviving `clear(channel: .chatError)`. Confined to +> `chat_error.log` that forgery was harmless; the shared file is what made it cross-channel. The user +> span is now passed through `DebugModeManager.escapedForLogLine` **inside the façade** rather than at +> each call site. ⚠️ **An earlier wording of this sentence ended "so no user-authored text can forge a +> channel." That is an UNQUALIFIED ABSOLUTE and it is FALSE** — both reviewers caught it +> independently. `logChatError` escapes only ITS OWN two spans. The other fourteen façades, and +> `AppLogStore.append` itself, still pass their message through unchanged, so +> `BackgroundSyncLogger.log("head\n[] [AUTH] forged")` still forges an AUTH entry, still +> truncates the SYNC filtered read at it, and still survives `clear(channel: .sync)`. What is closed +> is the `logChatError` path; the general case is REGISTERED here, not fixed, and this row's own +> class C (user-authored folder names on other channels) is a live instance of it. State it as +> "closed for `logChatError`", never as "no user-authored text can forge a channel". +> This does not disturb classes B and C +> below, which are about the account holder's own address and folder names, not about line forgery. +> +> Architecture, the full channel table, and the rule that a new channel is an `AppLogChannel` case +> rather than a sixteenth file: [`Companion/Memory/Current/122-one-log-file-per-process.md`](../../../Memory/Current/122-one-log-file-per-process.md). + # IOS-LOG-002 > Routed from `KNOWN_ISSUES.md` line 1000 during the 2026-08-09 hierarchy split. The exact pre-split source is hash-pinned in [`known-issues-pre-hierarchy-2026-08-09.txt`](../../History/KnownIssues/known-issues-pre-hierarchy-2026-08-09.txt) (`SHA-256 513497704ad37e977e2fb86e4623e956e6f1ca99844122948ff74995dfa9a309`). diff --git a/PROJECT_MEMORY.md b/PROJECT_MEMORY.md index 5c7177a5..c051a5a8 100644 --- a/PROJECT_MEMORY.md +++ b/PROJECT_MEMORY.md @@ -161,3 +161,4 @@ Authored after `v1.6.38`, so deliberately **not** rows in [`manifest.tsv`](Compa | Current | 🚨 **"TRIAL ENDED" IS DERIVED, NEVER A NEW `/whoami` FLAG** — `has_subscription:false` + the `trial` KEY present; `.active` REQUIRES `plan_tier == "Trial"` (a legacy **CARD trial** stays a plain subscriber); `AccountInfo.trialState(now:)`, `AISubscriptionGate.trialHasEnded`; intro-offer DELETED (#55) | [read in full](Companion/Memory/Current/118-trial-ended-is-derived-never-a-new-whoami-flag.md) | | Current | 🚨 **POST-LOGIN ROUTING WAITS FOR AN AUTHORITATIVE `/whoami`** (issue #56) — `PendingPlanNavigationLatch` / `pending_plan_navigation`, `AISubscriptionGate.lastAuthoritativeApplyAt`, `Account.existing(forEmail:provider:in:)` CASE-FOLDED, `signInGeneration`/`applyIfCurrentEpoch` | [read in full](Companion/Memory/Current/119-post-login-routing-waits-for-an-authoritative-whoami.md) | | Current | 🚨 **AFFORDANCE LIFETIME COMES FROM THE DURABLE HOLD, NEVER FROM WHEN THE UI APPEARED** — undo-send anchor drift = presentation latency Δ; same-name-different-instant `queuedAt` (#76) | [read in full](Companion/Memory/Current/120-an-affordance-is-bounded-by-the-durable-state.md) | +| Current | 🚨 **ONE LOG FILE PER PROCESS** (#83) — `AppLogStore`/`tabmail.log`, `NSELogStore`/`nse.log` | [read in full](Companion/Memory/Current/122-one-log-file-per-process.md) | diff --git a/Shared/Notifications/NSELogStore.swift b/Shared/Notifications/NSELogStore.swift index 067641dc..dcfcf361 100644 --- a/Shared/Notifications/NSELogStore.swift +++ b/Shared/Notifications/NSELogStore.swift @@ -138,7 +138,7 @@ enum NSELogStore { /// first newline, if it has grown past `effectiveMaxBytes`. Runs at most /// once per NSE process (gated by `trimmedThisProcess`) on the SAME /// `FileHandle` used for subsequent appends — never an atomic external - /// replace (`BackgroundSyncLogger.trimTail`'s approach), which would + /// replace (`AppLogStore.trimTail`'s approach), which would /// orphan the cached handle onto a since-deleted inode. Caller must hold /// `state`'s lock. private static func trimIfNeeded(handle: FileHandle) { diff --git a/TabMail/Services/Account/AccountManagerQueue.swift b/TabMail/Services/Account/AccountManagerQueue.swift index 509e2cd8..596e17c3 100644 --- a/TabMail/Services/Account/AccountManagerQueue.swift +++ b/TabMail/Services/Account/AccountManagerQueue.swift @@ -68,7 +68,9 @@ struct ExecutedOperation: Sendable { /// /// ⚠️ BUT A `print` COULD NEVER HAVE DELIVERED THAT EXCEPTION, so each site now /// also writes `BackgroundSyncLogger.logError` — ungated at the write, -/// file-backed (`error.log`), exported by `DebugLogView`. There is no +/// file-backed (the single `tabmail.log` via `AppLogStore`, on the `.error` +/// channel; recoverable with `AppLogStore.read(channel: .error)`), and exported +/// by `DebugLogView`'s "App Logs" share. There is no /// `freopen`/`dup2` anywhere in this tree (`rg -g '*.swift' 'freopen|dup2'` /// returns nothing), so on a device `stdout` goes nowhere and the /// "production observability" the exception buys from a bare `print` is zero. diff --git a/TabMail/Services/AppLogStore.swift b/TabMail/Services/AppLogStore.swift new file mode 100644 index 00000000..a10cbaa1 --- /dev/null +++ b/TabMail/Services/AppLogStore.swift @@ -0,0 +1,527 @@ +/* This Source Code Form is subject to the terms of the Mozilla Public + * License, v. 2.0. If a copy of the MPL was not distributed with this + * file, You can obtain one at https://mozilla.org/MPL/2.0/. */ + +import Foundation +import Synchronization + +/// The main app's SINGLE persistent diagnostic log file (`tabmail.log`) in +/// Application Support, and the counterpart to `NSELogStore`'s single `nse.log` +/// in the App Group container. Two processes, two files, and no more than that. +/// +/// Before this existed the main app wrote **fifteen** separate files +/// (`background_sync.log`, `error.log`, `chat_error.log`, `bg_app_refresh.log`, +/// `bg_processing.log`, `ai_processing.log`, `push.log`, `backfill_ai.log`, +/// `backfill.log`, `inbox.log`, `boot.log`, `body_render.log`, +/// `stuck_messages.log`, `device_sync.log`, `auth_diagnostics.log`), each with +/// its own retention policy and its own reader. ⚠️ NOT "each with its own BYTE +/// cap" — thirteen were byte-capped, `device_sync.log` used a 300-LINE ring and +/// `auth_diagnostics.log` a 50-ENTRY ring — and NOT "each with its own share +/// button": `auth_diagnostics.log` had none, which is precisely why its entries +/// were unreachable rather than unreadable. Diagnosing anything that crossed two +/// subsystems — a stalled backfill that shows up as an inbox reload storm, a +/// push that arrives while a BG refresh is running — meant exporting several +/// files and re-interleaving them by hand from their timestamps. One file +/// interleaved in append order is the whole point. Those fifteen files are +/// unlinked once, on the first launch after upgrade, by +/// `StartupMigrations.deleteLegacyLogFiles(in:)` — stranded, they would still +/// count toward `StorageEstimator`'s budget and could buy their size in pruned +/// mail. CONDITIONALLY: `isOverBudget()` is +/// `budgetMB != Int.max && totalSizeMB() >= budgetMB` and `defaultBudgetMB` is +/// `Int.max`, so that consequence exists only for a user who has configured a +/// finite budget. Stating it categorically is wrong. +/// +/// Each entry is `[] [] `, where `` is an +/// `AppLogChannel`. The tag is what replaces the old per-file separation: +/// `read(channel:)` filters back to a single subsystem when that is what you +/// want, and `read()` gives you everything in order when it is not. +/// +/// **This type does NOT gate.** Whether a channel writes in production is the +/// caller's decision and is unchanged by consolidation: `BackgroundSyncLogger`, +/// `DeviceSyncLogger` and `AuthDiagnostics` keep the exact +/// `DebugModeManager.isLoggingEnabled()` guards they had per channel, so the +/// always-on set (sync, error, chat error, device sync, auth) and the +/// debug-gated set are the same sets as before. That split is a deliberate, +/// registered decision (`IOS-LOG-002`) — a consolidation must not quietly widen +/// either side of it. +/// +/// ⚠️ Line-forgery caveat, inherited and NOT introduced here: a message that +/// itself contains a newline produces additional physical lines. Continuation +/// lines are attributed to the entry above them (see `read(channel:)`), which is +/// what `BackgroundSyncLogger.logChatError`'s deliberate two-line entry needs. +/// Sender-authored values interpolated into a log line must still be passed +/// through `DebugModeManager.escapedForLogLine`; that is the pre-existing rule +/// and this file neither strengthens nor weakens it. +/// +/// One channel does NOT leave that to its call sites. `logChatError` bounds and +/// escapes BOTH of its spans inside the façade — the literal user-typed +/// `userMessage`, AND the `message` line, which carries the backend's own error +/// string at most of its production call sites — because that writer is always-on: +/// unescaped, a newline followed by `[x] [AUTH] …` in EITHER span forges an entry +/// on ANOTHER channel in this shared file. Every other channel's interpolations +/// remain a call-site duty. +/// +/// SIZE, unlike escaping, is bounded HERE for every channel: `append` truncates +/// at `maxEntryScalars`, so no façade can hand the file an entry longer than a +/// trim's retained tail. `logChatError`'s own caps stay where they are and are +/// deliberately redundant with it. +enum AppLogStore { + /// Filename in Application Support / TabMail. + private static let fileName = "tabmail.log" + + /// Hard cap on log file size before tail-trim kicks in. + /// + /// Doubled from the 16 MB the per-subsystem `background_sync.log` used, + /// because that cap now has to hold FIFTEEN channels instead of one. The + /// trim is a whole-file tail-trim with no per-channel reservation, so a + /// chatty channel can evict a quiet one's history — accepted deliberately + /// (owner, 2026-08-25: "just diagnostics, don't overcomplicate"). Raising + /// the ceiling is the mitigation; per-channel floors or quotas are NOT. + /// Still far below the old worst case of fifteen independently-capped files. + static let maxBytes = 32 * 1024 * 1024 + /// Bytes to retain after a tail-trim. Trim happens at most once per + /// (maxBytes - keepBytes) of growth, so the 2:1 ratio is what bounds how + /// often the (whole-file, atomic) rewrite runs — keep it when changing + /// either constant. + static let keepBytes = 16 * 1024 * 1024 + + /// Hard ceiling on how many unicode scalars ONE entry's message may + /// contribute, applied at the STORE boundary so it covers all fifteen + /// façades rather than only the one that bounds its own spans. + /// + /// This is a SIZE bound and only a size bound. + /// `BackgroundSyncLogger.logChatError` keeps its own, far tighter + /// `prefix(100)` on `userMessage`; that one is a PRIVACY bound — it decides + /// how much of what the user actually typed is persisted — and neither + /// substitutes for the other. + /// + /// Deliberately redundant with both that bound and with `trimTail`'s refusal + /// to write an empty file: three independent things have to fail before one + /// oversized entry can cost the log. Scalars, never `Character`s — + /// `prefix(n)` counts extended grapheme clusters and one cluster can carry an + /// unbounded run of combining marks (`MIS-IOS-013`), so a grapheme-level cap + /// bounds neither scalars nor bytes. + /// + /// 64 Ki scalars is a ceiling, not a budget: the longest line any channel + /// writes is one of `StuckMessageDiagnostics`' per-folder histograms, and + /// even at four UTF-8 bytes per scalar the worst case is 256 KB — 1/64th of + /// `keepBytes`, so a bounded entry can never be the tail a trim retains. + static let maxEntryScalars = 64 * 1024 + + /// Shared serial queue for ALL persistent log file I/O. + /// + /// Appends are O(entry size) (`FileHandle.seekToEnd` + write), but disk I/O + /// on MainActor during rapid SwiftUI renders (e.g. `InboxViewModel.init` + /// during fast nav) can still produce visible stalls, and Device Sync's + /// WebSocket handlers log from the main thread. Serializing on a background + /// `utility`-QoS queue keeps log I/O off MainActor. Timestamps are captured + /// at call time. ⚠️ On-disk ordering is APPEND ORDER — the order work reached + /// `ioQueue` — NOT call order: a caller preempted between stamping and + /// enqueueing lands after one that stamped later, so timestamps can even read + /// as decreasing. Line order is the oracle, not the timestamp. This holds + /// though writes are async. `print()` stays on the caller's thread for + /// immediate Xcode-console visibility. + /// + /// One queue for one file is now load-bearing rather than merely tidy: + /// `DeviceSyncLogger` and `AuthDiagnostics` used to own their own file, and + /// `AuthDiagnostics` wrote synchronously on the caller's thread (including + /// from `TabMailApp.init` on MainActor). Sharing a file without sharing a + /// serial queue would interleave partial writes. + private static let ioQueue = DispatchQueue(label: "tabmail.logger.io", qos: .utility) + + // MARK: - Test seams + // + // `nil` = use the real Application Support container / real byte caps, + // which is exactly what production starts with. Mirrors `NSELogStore`'s + // seams so both log stores are overridden the same way. + + /// Test-only override for the log file location. + static let fileURLOverride = Mutex(nil) + /// Test-only override for `maxBytes` — lets trim tests use small caps + /// instead of writing multi-megabyte payloads. + static let maxBytesOverride = Mutex(nil) + /// Test-only override for `keepBytes`. + static let keepBytesOverride = Mutex(nil) + + private static var effectiveMaxBytes: Int { maxBytesOverride.withLock { $0 } ?? maxBytes } + private static var effectiveKeepBytes: Int { keepBytesOverride.withLock { $0 } ?? keepBytes } + + static var fileURL: URL { + if let override = fileURLOverride.withLock({ $0 }) { return override } + let dir = FileManager.default.urls(for: .applicationSupportDirectory, in: .userDomainMask)[0] + .appendingPathComponent("TabMail", isDirectory: true) + try? FileManager.default.createDirectory(at: dir, withIntermediateDirectories: true) + return dir.appendingPathComponent(fileName) + } + + // MARK: - Write + + /// Append one timestamped, channel-tagged entry. Never gates — the caller + /// owns the `DebugModeManager.isLoggingEnabled()` decision for its channel. + /// + /// `message` may span multiple lines; only the first carries the tag, and + /// `read(channel:)` attributes the rest to it. + static func append(_ message: String, channel: AppLogChannel) { + // SIZE bound, applied to EVERY channel — see `maxEntryScalars`. The + // PRIVACY bound on the one span of literal user text lives in + // `BackgroundSyncLogger.logChatError` and is a different, tighter thing. + let bounded = String(String.UnicodeScalarView(message.unicodeScalars.prefix(maxEntryScalars))) + let entry = "[\(Date().iso8601String())] [\(channel.tag)] \(bounded)\n" + appendRaw(entry) + } + + /// Shared write helper — appends via `FileHandle.seekToEnd`, repairs a torn + /// tail first, periodic byte-cap trim, all on `ioQueue`. + /// + /// Opened `forUpdating` (`O_RDWR`) rather than `forWritingTo` (`O_WRONLY`) + /// for one reason: the torn-tail repair below has to READ the file's last + /// byte, and a write-only handle cannot. + private static func appendRaw(_ entry: String) { + let url = fileURL + ioQueue.async { + guard let data = entry.data(using: .utf8) else { return } + if !FileManager.default.fileExists(atPath: url.path) { + try? Data().write(to: url) + } + if let handle = try? FileHandle(forUpdating: url) { + do { + let size = try handle.seekToEnd() + // TORN-TAIL REPAIR. Every entry ends with `\n`, so a file that + // does not is a file whose last write was cut short — the + // process died between `write` starting and the bytes landing. + // Without this, the next entry is concatenated onto that + // partial line: two entries become one physical line that + // `entryTag` reads as the FIRST one's channel, so the second is + // misattributed, cannot be filtered back out, and + // `clear(channel:)` on the first channel deletes the survivor + // along with it. + // + // This is NEW exposure, not a pre-existing bug being papered + // over. At v1.7.14 `AuthDiagnostics` and `DeviceSyncLogger` + // rewrote their whole file with `write(to:atomically:true)` — + // an atomic replace can never leave a partial line — and every + // other channel appended to a file only IT wrote. Now all + // fifteen append in place to one shared file, so one channel's + // torn write corrupts the NEXT channel's entry. + // + // One extra 1-byte read per append is the whole cost. + if size > 0 { + try handle.seek(toOffset: size - 1) + let lastByte = try handle.read(upToCount: 1) + try handle.seekToEnd() + if lastByte != Data([0x0A]) { + try handle.write(contentsOf: Data([0x0A])) + } + } + try handle.write(contentsOf: data) + } catch { + // Drop on write error; next append will retry. + } + try? handle.close() + } + if let size = (try? FileManager.default.attributesOfItem(atPath: url.path))?[.size] as? Int, + size > effectiveMaxBytes { + trimTail(url: url) + } + } + } + + /// Atomically replace `url` with its last `effectiveKeepBytes`, advanced past + /// the first partial line so we never retain a PARTIAL PHYSICAL LINE. Note + /// the unit: a physical line, not a logical entry. `logChatError` writes a + /// deliberate two-line entry, and a cut inside its tagged head leaves the + /// `User message:` continuation as a leading orphan. Caller must run this + /// on `ioQueue`. + private static func trimTail(url: URL) { + guard let handle = try? FileHandle(forReadingFrom: url) else { return } + defer { try? handle.close() } + guard let size = try? handle.seekToEnd(), size > UInt64(effectiveKeepBytes) else { return } + let offset = size - UInt64(effectiveKeepBytes) + do { try handle.seek(toOffset: offset) } catch { return } + guard var data = try? handle.readToEnd() else { return } + if let newline = data.firstIndex(of: 0x0A) { + data = data.subdata(in: (newline + 1).. String? { + guard let data = try? Data(contentsOf: url) else { return nil } + return String(decoding: data, as: UTF8.self) + } + + /// The whole log, every channel, in append order. This is what the Debug + /// menu's single "App Logs" share button exports. + static func read() -> String { + guard let text = ioQueue.sync(execute: { decodedFileText(at: fileURL) }), + !text.isEmpty else { + return "(no log)" + } + return text + } + + /// Only the entries written on `channel`, in append order. + /// + /// A physical line that does not begin a new entry (no `[timestamp] [TAG] ` + /// prefix) is a continuation of the entry above it and is kept or dropped + /// with that entry — `BackgroundSyncLogger.logChatError` deliberately emits a + /// second ` User message: …` line, and splitting it off would attribute it + /// to nothing. + static func read(channel: AppLogChannel) -> String { + guard let text = ioQueue.sync(execute: { decodedFileText(at: fileURL) }), + !text.isEmpty else { + return channel.emptyPlaceholder + } + let kept = filter(text, keepingChannel: channel) + return kept.isEmpty ? channel.emptyPlaceholder : kept + } + + /// Pure line filter behind `read(channel:)` — separated so it is testable + /// without touching the filesystem. + static func filter(_ text: String, keepingChannel channel: AppLogChannel) -> String { + var kept: [Substring] = [] + var including = false + for line in bodyLines(of: text) { + if let tag = entryTag(of: line) { + including = (tag == channel.tag) + } + if including { kept.append(line) } + } + return rejoin(kept) + } + + /// Split into lines with the file's single trailing newline removed, so the + /// empty tail element `split` would otherwise produce is not mistaken for a + /// continuation line. + /// + /// That mistake is not cosmetic. The tail element carries no `[ts] [TAG] ` + /// prefix, so `entryTag` reports `nil` and the line is attributed to the + /// entry above it. When that entry is the one being DROPPED, the newline + /// goes with it, `clear(channel:)` writes a file with no trailing newline, + /// and the next `append` lands on the same physical line — merging two + /// entries into one that no longer parses. Pinned by "Appending after + /// clear(channel:) starts a new line". + private static func bodyLines(of text: String) -> [Substring] { + var body = Substring(text) + if body.last == "\n" { body = body.dropLast() } + return body.split(separator: "\n", omittingEmptySubsequences: false) + } + + /// Rejoin lines into a file body that ends with exactly one newline, or is + /// empty. The inverse of `bodyLines`. + private static func rejoin(_ lines: [Substring]) -> String { + guard !lines.isEmpty else { return "" } + return lines.joined(separator: "\n") + "\n" + } + + /// Every tag `entryTag` will accept. Derived from `AppLogChannel.allCases` + /// so a new channel is admitted by adding the case and nothing else, and so + /// arbitrary bracketed text can never be mistaken for a channel. + static let knownTags: Set = Set(AppLogChannel.allCases.map(\.tag)) + + /// The channel tag of a line that STARTS an entry, or `nil` for a + /// continuation line. Parsed over `unicodeScalars` rather than with + /// `hasPrefix`/`split`, per `MIS-IOS-013` — the delimiters are ASCII but the + /// timestamp and message around them need not be. + /// + /// Two checks beyond "there is a second bracketed field", because + /// `read(channel:)` and `clear(channel:)` both key off this and a line that + /// merely LOOKS like an entry start would be attributed to — or cleared + /// from — the wrong channel: + /// + /// * the tag's closing `]` must be followed by a space or end the line, so + /// `[…] [SYNC]forged` is a continuation line rather than a SYNC entry; and + /// * the tag must be a real `AppLogChannel` tag, so `[…] [junk] …` is a + /// continuation line rather than an entry on a channel that cannot be + /// read back or cleared. + /// + /// Both failures return `nil` — i.e. the line is treated as a continuation + /// of the entry above it, exactly as an unparseable line always was. The + /// timestamp field is deliberately NOT validated: this runs once per + /// physical line of a file capped at `maxBytes`, and date parsing per line + /// is not a cost a debug reader should pay. + static func entryTag(of line: Substring) -> String? { + let scalars = Array(line.unicodeScalars) + guard scalars.first == "[" else { return nil } + guard let timestampEnd = scalars.firstIndex(of: "]") else { return nil } + var index = timestampEnd + 1 + guard index < scalars.count, scalars[index] == " " else { return nil } + index += 1 + guard index < scalars.count, scalars[index] == "[" else { return nil } + index += 1 + var tag = String.UnicodeScalarView() + while index < scalars.count, scalars[index] != "]" { + tag.append(scalars[index]) + index += 1 + } + guard index < scalars.count else { return nil } + // Past the tag's closing `]`: a real entry has `] ` (the separator + // `append` writes) or nothing at all (an entry whose message is empty + // still ends with that space, so end-of-line only happens for a + // hand-written line — accepted, it is unambiguous). + index += 1 + guard index == scalars.count || scalars[index] == " " else { return nil } + let parsed = String(tag) + guard knownTags.contains(parsed) else { return nil } + return parsed + } + + // MARK: - Clear + + /// Clear the entire log — every channel. The Debug menu's "Clear All Logs". + static func clear() { + ioQueue.sync { + try? Data().write(to: fileURL, options: .atomic) + } + } + + /// Drop just one channel's entries, preserving every other channel. + /// + /// `StuckMessageDiagnostics.run` clears its own channel before each scan so + /// the shared report is that run's output rather than an accumulation. With + /// one file, clearing the file to achieve that would destroy every other + /// subsystem's history along with it. + /// + /// A LEADING orphan — a continuation line with no entry above it, which a + /// tail-trim leaves behind whenever it cuts between a multi-line entry's + /// first and second lines (`logChatError`'s ` User message: …`) — belongs + /// to no channel and is dropped whichever channel is being cleared. That + /// matches `filter(_:keepingChannel:)`, which seeds `including = false` and + /// so already drops it on every filtered read. Seeding `dropping = false` + /// here instead made the orphan unreadable but unclearable: no channel's + /// export showed it, and no channel's clear removed it, so a fragment of + /// user text could survive every clear the UI offers short of "Clear All". + static func clear(channel: AppLogChannel) { + ioQueue.sync { + let url = fileURL + guard let text = decodedFileText(at: url), !text.isEmpty else { return } + var kept: [Substring] = [] + var dropping = true + for line in bodyLines(of: text) { + if let tag = entryTag(of: line) { + dropping = (tag == channel.tag) + } + if !dropping { kept.append(line) } + } + try? Data(rejoin(kept).utf8).write(to: url, options: .atomic) + } + } + + /// Test-only: reset every override to its default. It does NOT empty the + /// log — each caller owns the temp file it pointed the store at and deletes + /// it. The overrides are process-lifetime state, so without this a test + /// sharing the test-host process would leak a prior test's temp file URL or + /// byte cap into the next one. + static func _resetForTesting() { + fileURLOverride.withLock { $0 = nil } + maxBytesOverride.withLock { $0 = nil } + keepBytesOverride.withLock { $0 = nil } + } +} + +/// The subsystem an `AppLogStore` entry came from. One case per file that the +/// main app used to write separately; the raw tag is what makes a single file +/// separable again. +enum AppLogChannel: String, CaseIterable, Sendable { + /// Background sync events (BGAppRefreshTask, BGProcessingTask, silent push). + case sync + /// Errors with source context — sync, NIO, API. Always-on (`IOS-LOG-002`). + case error + /// Chat / AI errors: tool failures, empty responses, connection errors. + case chatError + /// Device Sync connection, probes and responses. + case deviceSync + /// Auth events, retained so they survive an unexpected logout. + case auth + /// `BGAppRefreshTask` lifecycle. + case bgAppRefresh + /// `BGProcessingTask` lifecycle. + case bgProcessing + /// AI processing queue: enqueue, dispatch, dequeue, complete, retry. + case aiProcessing + /// Push registration, subscription and silent-push processing. + case push + /// `BackfillAIQueue`: enqueue, claim, success, skip, retry, drop, repopulate. + case backfillAI + /// Backfill header walk and body queue. + case backfill + /// `InboxViewModel` lifecycle and reloads. + case inbox + /// `BootProfiler` cold-launch timeline. + case boot + /// Body-render / HTML double-escape diagnostics. + case bodyRender + /// `StuckMessageDiagnostics` scan output. + case stuckDiag + + /// The literal written between brackets on every entry. Stable — a reader + /// looking at an exported log from an older build matches on these, so + /// renaming one silently orphans that build's history. + var tag: String { + switch self { + case .sync: return "SYNC" + case .error: return "ERROR" + case .chatError: return "CHAT" + case .deviceSync: return "DEVICESYNC" + case .auth: return "AUTH" + case .bgAppRefresh: return "BGREFRESH" + case .bgProcessing: return "BGPROC" + case .aiProcessing: return "AI" + case .push: return "PUSH" + case .backfillAI: return "BACKFILL-AI" + case .backfill: return "BACKFILL" + case .inbox: return "INBOX" + case .boot: return "BOOT" + case .bodyRender: return "RENDER" + case .stuckDiag: return "STUCK" + } + } + + /// Shown by `AppLogStore.read(channel:)` when this channel has no entries. + var emptyPlaceholder: String { + switch self { + case .stuckDiag: + return "(no stuck-message diagnostics — run the scan from the Debug menu)" + default: + return "(no \(tag) log)" + } + } +} diff --git a/TabMail/Services/AuthDiagnostics.swift b/TabMail/Services/AuthDiagnostics.swift index effbb77e..d3a9287b 100644 --- a/TabMail/Services/AuthDiagnostics.swift +++ b/TabMail/Services/AuthDiagnostics.swift @@ -4,43 +4,60 @@ import Foundation -/// Persistent diagnostic log for auth-related events. -/// Writes timestamped entries to a file in Application Support so they survive -/// app restarts and can be retrieved after an unexpected logout. -/// Surface via Settings > Maintenance > "Auth Diagnostics" row. +/// Diagnostic log writer for auth-related events (launch session state, token +/// refresh outcomes, Keychain save failures). +/// +/// Writes to the single app log via `AppLogStore` on the `.auth` channel, so it +/// survives app restarts and can be retrieved after an unexpected logout — +/// which is the entire reason this channel is persistent and always-on. +/// +/// Consolidating onto the shared file gave this channel a UI ROUTE it never +/// had — **not** a reader. ⚠️ It always had one: `v1.7.14`'s `AuthDiagnostics` +/// declares `readLog()`. What it lacked was any surface that CALLED it; the doc +/// comment named a "Settings > Maintenance" row that does not exist in the tree, +/// and `auth_diagnostics.log` was the only one of the fifteen log files with no +/// share button anywhere. So its entries were written and UNREACHABLE, not +/// unreadable. They are now part of the App Logs share. +/// +/// The symmetric half, recorded because an earlier draft stated only the +/// widening: those entries also gained a DESTROYER. They previously sat outside +/// every clear surface in the app; they are now inside `tabmail.log`, which +/// "Clear All Logs" wipes — so "clear the logs, reproduce, share" now destroys +/// the auth history that predates the repro. Kept deliberately (owner decision, +/// 2026-08-25); do not re-add an exclusion without re-opening `IOS-LOG-002`. +/// +/// The write is dispatched off-main by `AppLogStore`; the previous +/// implementation did a synchronous read-modify-write on the caller's thread, +/// including from `TabMailApp.init` on MainActor. enum AuthDiagnostics { - private static let maxEntries = 50 - private static let fileName = "auth_diagnostics.log" - - private static var fileURL: URL { - let dir = FileManager.default.urls(for: .applicationSupportDirectory, in: .userDomainMask)[0] - .appendingPathComponent("TabMail", isDirectory: true) - try? FileManager.default.createDirectory(at: dir, withIntermediateDirectories: true) - return dir.appendingPathComponent(fileName) - } - - /// Append a diagnostic event. Thread-safe via file coordination. + /// Append an auth diagnostic event. + /// + /// **ASYNCHRONOUS, and that is a deliberate durability trade** — the exact + /// opposite of the call `NSELogStore` makes, so it is stated here in the + /// same terms. + /// + /// Until `v1.7.14` this did a synchronous atomic read-modify-write of + /// `auth_diagnostics.log` on the caller's thread, including from + /// `TabMailApp.init` — i.e. file I/O on MainActor on the launch path. It now + /// hands the entry to `AppLogStore.ioQueue` (`.utility`) and returns + /// immediately. + /// + /// **The cost:** an entry enqueued and not yet flushed is lost if the + /// process dies first — a crash, a jetsam kill, a force-quit. The entries + /// most likely to be lost are the ones written last, which on the auth path + /// is precisely the sequence before an unexpected logout, the thing this + /// channel exists to explain. + /// + /// **Why it is still the right call here, where it is the wrong one for the + /// NSE:** the main app is not hard-killed on a budget the way the NSE is + /// (0xdead10cc suspension, watchdog, ~30 s OS budget), so the window is a + /// scheduling gap rather than a guaranteed truncation; and blocking + /// MainActor at launch is a cost every user pays on every launch, while the + /// lost tail line costs only the rare crash. If a future change makes the + /// tail line load-bearing, the fix is a synchronous FLUSH at a known-risky + /// point, not a return to synchronous appends. static func log(_ message: String) { - let timestamp = Date().iso8601String() - let entry = "[\(timestamp)] \(message)\n" - - // Also print for Xcode console print("[AuthDiag] \(message)") - - let url = fileURL - if var existing = try? String(contentsOf: url, encoding: .utf8) { - existing += entry - // Trim to last N entries - let lines = existing.components(separatedBy: "\n").filter { !$0.isEmpty } - let trimmed = lines.suffix(maxEntries).joined(separator: "\n") + "\n" - try? trimmed.write(to: url, atomically: true, encoding: .utf8) - } else { - try? entry.write(to: url, atomically: true, encoding: .utf8) - } - } - - /// Read the full diagnostic log. Returns empty string if no log exists. - static func readLog() -> String { - (try? String(contentsOf: fileURL, encoding: .utf8)) ?? "(no diagnostic log)" + AppLogStore.append(message, channel: .auth) } } diff --git a/TabMail/Services/BackgroundSyncLogger.swift b/TabMail/Services/BackgroundSyncLogger.swift index d11ccf14..f831877b 100644 --- a/TabMail/Services/BackgroundSyncLogger.swift +++ b/TabMail/Services/BackgroundSyncLogger.swift @@ -4,458 +4,232 @@ import Foundation -/// Persistent diagnostic log for background sync events (BGAppRefreshTask, BGProcessingTask, silent push). -/// Modeled after `AuthDiagnostics` — writes timestamped entries to a file in Application Support -/// so they survive app restarts and can be viewed in the Debug menu. +/// Diagnostic log writers for the main app's background and queue subsystems. +/// +/// Every function here writes to the ONE app log file — see `AppLogStore`, which +/// owns the file, the serial I/O queue, the byte cap and the readers. This type +/// is now only the set of named entry points and, more importantly, the record of +/// **which channels are debug-gated and which are always-on**. +/// +/// That split is a registered decision (`IOS-LOG-002`), not an accident: +/// `log`, `logError` and `logChatError` persist in production because a failure +/// that only reproduces in the field has to leave a trace, while every channel +/// added for investigation is a no-op unless debug mode is unlocked by an allowed +/// user (global `CLAUDE.md` rule 12). Consolidating the files changed neither set. +/// +/// MOST writers also `print` for immediate Xcode-console visibility, on the +/// caller's thread; `logBackfill` and `logBoot` deliberately do NOT, because +/// their callers already echo to the console themselves. Every writer that DOES +/// have a console sink and is debug-gated gates the `print` too — a debug-gated +/// channel must be a no-op in production on BOTH channels, not just on disk. enum BackgroundSyncLogger { - /// Hard cap on log file size before tail-trim kicks in. - private static let maxBytes = 16 * 1024 * 1024 - /// Bytes to retain after a tail-trim. Trim happens at most once per (maxBytes - keepBytes) of growth. - private static let keepBytes = 8 * 1024 * 1024 - private static let fileName = "background_sync.log" - /// Shared serial queue for ALL persistent log file I/O. - /// - /// Even though appends are now O(entry size) (`FileHandle.seekToEnd` + write), - /// disk I/O on MainActor during rapid SwiftUI renders (e.g. `InboxViewModel.init` - /// during fast nav) can still produce visible stalls. Serializing on a background - /// `utility`-QoS queue keeps log I/O off MainActor. Timestamps are captured at - /// call time so on-disk ordering still reflects real call ordering even though - /// writes are async. `print()` stays on the caller's thread for immediate - /// Xcode-console visibility. - private static let ioQueue = DispatchQueue(label: "tabmail.logger.io", qos: .utility) - - /// Shared write helper — appends via `FileHandle.seekToEnd`, periodic byte-cap trim, all on ioQueue. - private static func appendAsync(to url: URL, entry: String) { - ioQueue.async { - guard let data = entry.data(using: .utf8) else { return } - if !FileManager.default.fileExists(atPath: url.path) { - try? Data().write(to: url) - } - if let handle = try? FileHandle(forWritingTo: url) { - do { - try handle.seekToEnd() - try handle.write(contentsOf: data) - } catch { - // Drop on write error; next append will retry. - } - try? handle.close() - } - if let size = (try? FileManager.default.attributesOfItem(atPath: url.path))?[.size] as? Int, - size > maxBytes { - trimTail(url: url) - } - } - } - - /// Atomically replace `url` with its last `keepBytes`, advanced past the first - /// partial line so we never split a log entry. Caller must run this on `ioQueue`. - private static func trimTail(url: URL) { - guard let handle = try? FileHandle(forReadingFrom: url) else { return } - defer { try? handle.close() } - guard let size = try? handle.seekToEnd(), size > UInt64(keepBytes) else { return } - let offset = size - UInt64(keepBytes) - do { try handle.seek(toOffset: offset) } catch { return } - guard var data = try? handle.readToEnd() else { return } - if let newline = data.firstIndex(of: 0x0A) { - data = data.subdata(in: (newline + 1).. String { - flushPendingWrites() - return (try? String(contentsOf: fileURL, encoding: .utf8)) ?? "(no background sync log)" + AppLogStore.append(message, channel: .sync) } - /// Clear the log file. - static func clearLog() { - try? "".write(to: fileURL, atomically: true, encoding: .utf8) - } - - // MARK: - Error Log - - private static let errorFileName = "error.log" - - private static var errorFileURL: URL { - let dir = FileManager.default.urls(for: .applicationSupportDirectory, in: .userDomainMask)[0] - .appendingPathComponent("TabMail", isDirectory: true) - try? FileManager.default.createDirectory(at: dir, withIntermediateDirectories: true) - return dir.appendingPathComponent(errorFileName) - } + // MARK: - Errors (always-on) /// Log an error with source context. Captures sync errors, NIO errors, API errors, etc. static func logError(_ message: String, source: String) { - let entry = "[\(Date().iso8601String())] [\(source)] \(message)\n" print("[ErrorLog:\(source)] \(message)") - appendAsync(to: errorFileURL, entry: entry) + AppLogStore.append("[\(source)] \(message)", channel: .error) } - static func readErrorLog() -> String { - flushPendingWrites() - return (try? String(contentsOf: errorFileURL, encoding: .utf8)) ?? "(no errors logged)" - } + // MARK: - Chat errors (always-on) - static func clearErrorLog() { - try? "".write(to: errorFileURL, atomically: true, encoding: .utf8) - } - - // MARK: - Chat Error Log - - private static let chatErrorFileName = "chat_error.log" - - private static var chatErrorFileURL: URL { - let dir = FileManager.default.urls(for: .applicationSupportDirectory, in: .userDomainMask)[0] - .appendingPathComponent("TabMail", isDirectory: true) - try? FileManager.default.createDirectory(at: dir, withIntermediateDirectories: true) - return dir.appendingPathComponent(chatErrorFileName) - } - - /// Log a chat/AI error with context. Captures tool failures, empty responses, connection errors, etc. + /// Log a chat/AI error with context. Captures tool failures, empty responses, connection errors. + /// + /// **BOTH spans this writes are outside our control, and both are bounded and + /// escaped here — in the façade — rather than at each call site:** + /// + /// * `userMessage` is literal user-typed chat input (`AIChat` passes + /// `userText` straight through); and + /// * `message` carries REMOTE text at most production call sites. `AIChat` + /// interpolates the backend's own `response.error` string + /// (`"Server error: \(error)"`, `"Server error (resume): \(error)"`) and + /// `DynamicIslandChatButton` interpolates `error.localizedDescription` + /// (`"Chat error: …"`, `"Connection lost (resumable): …"`, + /// `"Resume failed: …"`). Stated with its negative case, because "every" + /// was wrong and a reader would have checked it: `BackendClient`'s + /// `"SSE stream ended without final event …"` interpolates nothing at all. + /// That one is safe TODAY by accident of its argument, not by contract — + /// which is exactly why the bound-and-escape lives HERE and not at the + /// call sites that happen to need it. + /// + /// The app log is now a LINE-ORIENTED sink shared by every channel, so an + /// unescaped newline in EITHER span is a forgery rather than a formatting + /// nit: a value carrying `"\n[x] [AUTH] …"` produces a second PHYSICAL line + /// that `AppLogStore.entryTag` parses as a genuine AUTH entry — it surfaces + /// in `read(channel: .auth)`, it truncates the real entry in + /// `read(channel: .chatError)`, and `clear(channel: .chatError)` leaves the + /// forged remainder behind. Before consolidation that forgery was confined to + /// `chat_error.log` and harmless; the shared file is what makes it + /// cross-channel. Escaping only `userMessage` closed one of the two doors. + /// + /// The `\n User message: ` separator BETWEEN the two spans is deliberate and + /// stays a literal: `AppLogStore.read(channel:)` attributes a continuation + /// line upward to this entry, so escaping the newline we write ourselves + /// would destroy the two-line shape the reader needs. Escape the spans, never + /// the separator you write yourself. static func logChatError(_ message: String, userMessage: String? = nil) { - var entry = "[\(Date().iso8601String())] \(message)" + // ⚠️ BOUND BEFORE ESCAPE, AND BOUND BY UNICODE SCALAR — both halves matter. + // + // Escaping collapses a multi-line span into ONE physical line, which is + // the point, and it also removes the newlines `AppLogStore.trimTail` + // depends on. `trimTail` keeps the last `keepBytes` and then advances past + // the first newline in that tail, so an entry whose only newline is its + // own terminal one leaves NOTHING to retain. That outcome is now owned by + // the STORE, not by this façade: `AppLogStore.append` bounds every channel + // at `maxEntryScalars`, and `trimTail` refuses to write an empty file, so + // such a trim is abandoned and the log is left untrimmed rather than + // erased. Bounding each span here is the tightest of the three guards, + // not the only one standing between this writer and a whole-file erase. + // + // The ceiling is over `unicodeScalars`, not `Characters`. `prefix(100)` + // counts extended grapheme CLUSTERS, and a single cluster can carry an + // unbounded run of combining marks, so one pasted grapheme passes a + // Character cap intact (`MIS-IOS-013` — a SIZE question asked with a + // grapheme-level `String` API). Slicing SCALARS cannot split a UTF-8 + // sequence, and it runs BEFORE escaping so it can never slice a generated + // `\uXXXX` in half. + // + // 4000 scalars is a ceiling, not a budget: every call site writes a short + // developer line plus one error string, so ordinary text never reaches it, + // while the escaped worst case (six characters per escaped scalar) still + // stays three orders of magnitude below `AppLogStore.keepBytes`. + var entry = DebugModeManager.escapedForLogLine( + String(String.UnicodeScalarView(message.unicodeScalars.prefix(4000)))) if let userMessage { - entry += "\n User message: \(userMessage.prefix(100))" + // ORDER: cap FIRST, escape SECOND. `prefix(100)` carries the INTENT — + // roughly a hundred characters of the user's own text is what the log + // needs — and escaping afterwards can only expand what survived (one + // control scalar becomes six characters, `\u000a`), so the + // cap can never slice an escape sequence in half. Escaping first would + // also let a message of 100 newlines spend the whole budget on escape + // sequences and preserve ~16 characters of actual evidence. + // + // The scalar cap after it is the HARD ceiling that a single grapheme + // cannot defeat, for the reason spelled out above: `prefix(100)` alone + // bounds neither scalars nor bytes. + let capped = String(userMessage.prefix(100)) + let bounded = String(String.UnicodeScalarView(capped.unicodeScalars.prefix(400))) + entry += "\n User message: \(DebugModeManager.escapedForLogLine(bounded))" } - entry += "\n" print("[ChatErrorLog] \(message)") - appendAsync(to: chatErrorFileURL, entry: entry) - } - - static func readChatErrorLog() -> String { - flushPendingWrites() - return (try? String(contentsOf: chatErrorFileURL, encoding: .utf8)) ?? "(no chat errors logged)" - } - - static func clearChatErrorLog() { - try? "".write(to: chatErrorFileURL, atomically: true, encoding: .utf8) + AppLogStore.append(entry, channel: .chatError) } - // MARK: - BG App Refresh Log - - private static let bgAppRefreshFileName = "bg_app_refresh.log" - - private static var bgAppRefreshFileURL: URL { - let dir = FileManager.default.urls(for: .applicationSupportDirectory, in: .userDomainMask)[0] - .appendingPathComponent("TabMail", isDirectory: true) - try? FileManager.default.createDirectory(at: dir, withIntermediateDirectories: true) - return dir.appendingPathComponent(bgAppRefreshFileName) - } + // MARK: - BG App Refresh (debug-gated) /// Log a BGAppRefreshTask lifecycle event (schedule, start, expire, complete, silent push). - /// Only writes to disk when debug mode is unlocked by an allowed user. static func logBGAppRefresh(_ message: String) { guard DebugModeManager.isLoggingEnabled() else { return } - let entry = "[\(Date().iso8601String())] \(message)\n" print("[BGAppRefreshLog] \(message)") - appendAsync(to: bgAppRefreshFileURL, entry: entry) - } - - static func readBGAppRefreshLog() -> String { - flushPendingWrites() - return (try? String(contentsOf: bgAppRefreshFileURL, encoding: .utf8)) ?? "(no BG App Refresh log)" - } - - static func clearBGAppRefreshLog() { - try? "".write(to: bgAppRefreshFileURL, atomically: true, encoding: .utf8) + AppLogStore.append(message, channel: .bgAppRefresh) } - // MARK: - BG Processing Log - - private static let bgProcessingFileName = "bg_processing.log" - - private static var bgProcessingFileURL: URL { - let dir = FileManager.default.urls(for: .applicationSupportDirectory, in: .userDomainMask)[0] - .appendingPathComponent("TabMail", isDirectory: true) - try? FileManager.default.createDirectory(at: dir, withIntermediateDirectories: true) - return dir.appendingPathComponent(bgProcessingFileName) - } + // MARK: - BG Processing (debug-gated) /// Log a BGProcessingTask lifecycle event (schedule, start, phase progress, expire, complete). - /// Only writes to disk when debug mode is unlocked by an allowed user. static func logBGProcessing(_ message: String) { guard DebugModeManager.isLoggingEnabled() else { return } - let entry = "[\(Date().iso8601String())] \(message)\n" print("[BGProcessingLog] \(message)") - appendAsync(to: bgProcessingFileURL, entry: entry) + AppLogStore.append(message, channel: .bgProcessing) } - static func readBGProcessingLog() -> String { - flushPendingWrites() - return (try? String(contentsOf: bgProcessingFileURL, encoding: .utf8)) ?? "(no BG Processing log)" - } - - static func clearBGProcessingLog() { - try? "".write(to: bgProcessingFileURL, atomically: true, encoding: .utf8) - } - - // MARK: - AI Processing Log - - private static let aiProcessingFileName = "ai_processing.log" - - private static var aiProcessingFileURL: URL { - let dir = FileManager.default.urls(for: .applicationSupportDirectory, in: .userDomainMask)[0] - .appendingPathComponent("TabMail", isDirectory: true) - try? FileManager.default.createDirectory(at: dir, withIntermediateDirectories: true) - return dir.appendingPathComponent(aiProcessingFileName) - } + // MARK: - AI Processing (debug-gated) /// Log an AI processing queue event (enqueue, dispatch, dequeue, complete, retry, context). - /// Only writes to disk when debug mode is unlocked by an allowed user. static func logAIProcessing(_ message: String) { guard DebugModeManager.isLoggingEnabled() else { return } - let entry = "[\(Date().iso8601String())] \(message)\n" print("[AIProcessingLog] \(message)") - appendAsync(to: aiProcessingFileURL, entry: entry) + AppLogStore.append(message, channel: .aiProcessing) } - static func readAIProcessingLog() -> String { - flushPendingWrites() - return (try? String(contentsOf: aiProcessingFileURL, encoding: .utf8)) ?? "(no AI processing log)" - } - - static func clearAIProcessingLog() { - try? "".write(to: aiProcessingFileURL, atomically: true, encoding: .utf8) - } - - // MARK: - Push Notification Log - - private static let pushFileName = "push.log" - - private static var pushFileURL: URL { - let dir = FileManager.default.urls(for: .applicationSupportDirectory, in: .userDomainMask)[0] - .appendingPathComponent("TabMail", isDirectory: true) - try? FileManager.default.createDirectory(at: dir, withIntermediateDirectories: true) - return dir.appendingPathComponent(pushFileName) - } + // MARK: - Push notifications (debug-gated) /// Log a push notification event (registration, subscription, silent push processing). - /// Only writes to disk when debug mode is unlocked by an allowed user. static func logPush(_ message: String) { guard DebugModeManager.isLoggingEnabled() else { return } - let entry = "[\(Date().iso8601String())] \(message)\n" print("[PushLog] \(message)") - appendAsync(to: pushFileURL, entry: entry) + AppLogStore.append(message, channel: .push) } - static func readPushLog() -> String { - flushPendingWrites() - return (try? String(contentsOf: pushFileURL, encoding: .utf8)) ?? "(no push notification log)" - } - - static func clearPushLog() { - try? "".write(to: pushFileURL, atomically: true, encoding: .utf8) - } - - // MARK: - Backfill AI Refinement Log - - private static let backfillAIFileName = "backfill_ai.log" - - private static var backfillAIFileURL: URL { - let dir = FileManager.default.urls(for: .applicationSupportDirectory, in: .userDomainMask)[0] - .appendingPathComponent("TabMail", isDirectory: true) - try? FileManager.default.createDirectory(at: dir, withIntermediateDirectories: true) - return dir.appendingPathComponent(backfillAIFileName) - } + // MARK: - Backfill AI refinement (debug-gated) /// Log a BackfillAIQueue event (enqueue, claim, success, skip, retry, drop, repopulate). - /// Only writes to disk when debug mode is unlocked by an allowed user. static func logBackfillAI(_ message: String) { guard DebugModeManager.isLoggingEnabled() else { return } - let entry = "[\(Date().iso8601String())] \(message)\n" print("[BackfillAILog] \(message)") - appendAsync(to: backfillAIFileURL, entry: entry) - } - - static func readBackfillAILog() -> String { - flushPendingWrites() - return (try? String(contentsOf: backfillAIFileURL, encoding: .utf8)) ?? "(no backfill AI log)" - } - - static func clearBackfillAILog() { - try? "".write(to: backfillAIFileURL, atomically: true, encoding: .utf8) + AppLogStore.append(message, channel: .backfillAI) } - // MARK: - Backfill Log (header walk + body queue) - - private static let backfillFileName = "backfill.log" - - private static var backfillFileURL: URL { - let dir = FileManager.default.urls(for: .applicationSupportDirectory, in: .userDomainMask)[0] - .appendingPathComponent("TabMail", isDirectory: true) - try? FileManager.default.createDirectory(at: dir, withIntermediateDirectories: true) - return dir.appendingPathComponent(backfillFileName) - } + // MARK: - Backfill header walk + body queue (debug-gated) /// Log a backfill lifecycle event (worker start/exit, cycle start, pause reason, /// folder complete, connection backoff, body-queue batch/miss/confirm-gone outcomes). - /// The header/body backfill previously logged via `print()` only, which made - /// exported debug logs useless for diagnosing stalls — this is the file channel. - /// Only writes to disk when debug mode is unlocked by an allowed user. + /// Deliberately does NOT `print` — the header/body backfill already echoes to the + /// console elsewhere, and this is the file channel that makes an exported log + /// useful for diagnosing stalls. static func logBackfill(_ message: String) { guard DebugModeManager.isLoggingEnabled() else { return } - let entry = "[\(Date().iso8601String())] \(message)\n" - appendAsync(to: backfillFileURL, entry: entry) + AppLogStore.append(message, channel: .backfill) } - static func readBackfillLog() -> String { - flushPendingWrites() - return (try? String(contentsOf: backfillFileURL, encoding: .utf8)) ?? "(no backfill log)" - } - - static func clearBackfillLog() { - try? "".write(to: backfillFileURL, atomically: true, encoding: .utf8) - } - - // MARK: - Inbox ViewModel Log - - private static let inboxFileName = "inbox.log" - - private static var inboxFileURL: URL { - let dir = FileManager.default.urls(for: .applicationSupportDirectory, in: .userDomainMask)[0] - .appendingPathComponent("TabMail", isDirectory: true) - try? FileManager.default.createDirectory(at: dir, withIntermediateDirectories: true) - return dir.appendingPathComponent(inboxFileName) - } + // MARK: - Inbox view model (debug-gated) /// Log an InboxViewModel lifecycle or reload event. /// Covers: folder-set transitions, observer registration, reload counts, partial-set heals, - /// ValueObservation emissions. Only writes when debug mode is unlocked. + /// ValueObservation emissions. static func logInbox(_ message: String) { guard DebugModeManager.isLoggingEnabled() else { return } - let entry = "[\(Date().iso8601String())] \(message)\n" print("[InboxLog] \(message)") - appendAsync(to: inboxFileURL, entry: entry) + AppLogStore.append(message, channel: .inbox) } - static func readInboxLog() -> String { - flushPendingWrites() - return (try? String(contentsOf: inboxFileURL, encoding: .utf8)) ?? "(no inbox log)" - } - - static func clearInboxLog() { - try? "".write(to: inboxFileURL, atomically: true, encoding: .utf8) - } - - // MARK: - Boot Profile Log - - private static let bootFileName = "boot.log" - - private static var bootFileURL: URL { - let dir = FileManager.default.urls(for: .applicationSupportDirectory, in: .userDomainMask)[0] - .appendingPathComponent("TabMail", isDirectory: true) - try? FileManager.default.createDirectory(at: dir, withIntermediateDirectories: true) - return dir.appendingPathComponent(bootFileName) - } + // MARK: - Boot profile (debug-gated) - /// Append a `BootProfiler` timeline line to the DOWNLOADABLE boot log. Gated on - /// DebugModeManager so it captures on-device / TestFlight, where no Xcode console - /// is attached and BootProfiler's `print` goes nowhere observable — this file - /// channel is the only way to read a cold-launch timeline there. Called from - /// `BootProfiler.mark`; does not print (BootProfiler handles the console echo) — - /// this is the file channel. + /// Append a `BootProfiler` timeline line. Gated on DebugModeManager so it + /// captures on-device / TestFlight, where no Xcode console is attached and + /// BootProfiler's `print` goes nowhere observable — this file channel is the + /// only way to read a cold-launch timeline there. Called from + /// `BootProfiler.mark`; does not print (BootProfiler handles the console echo). static func logBoot(_ line: String) { guard DebugModeManager.isLoggingEnabled() else { return } - appendAsync(to: bootFileURL, entry: line + "\n") + AppLogStore.append(line, channel: .boot) } - static func readBootLog() -> String { - flushPendingWrites() - return (try? String(contentsOf: bootFileURL, encoding: .utf8)) ?? "(no boot log)" - } - - static func clearBootLog() { - try? "".write(to: bootFileURL, atomically: true, encoding: .utf8) - } + // MARK: - Body render / HTML double-escape (debug-gated) - // MARK: - Body Render / HTML double-escape Log - - /// Dedicated diagnostic channel for the rare "HTML body shows literal `&` / - /// ` ` / visible tags" bug. The symptom is `EmailFilter.plainTextToHTML` - /// escaping content that was ALREADY HTML. The clean fix makes `BodyRenderer` - /// the single conversion authority, so the storage factory no longer re-converts - /// — but we keep this channel to catch any double-escaped body that still reaches - /// storage (e.g. a sender that put HTML in a text/plain part with no html - /// alternative), via `diagnoseStoredBody`. - private static let bodyRenderFileName = "body_render.log" - - private static var bodyRenderFileURL: URL { - let dir = FileManager.default.urls(for: .applicationSupportDirectory, in: .userDomainMask)[0] - .appendingPathComponent("TabMail", isDirectory: true) - try? FileManager.default.createDirectory(at: dir, withIntermediateDirectories: true) - return dir.appendingPathComponent(bodyRenderFileName) - } - - /// Append a body-render diagnostic line. Only writes when debug mode is - /// unlocked by an allowed user (CLAUDE.md rule 12). Prefer `diagnoseStoredBody` - /// at call sites — it gates on the dangerous condition before formatting. + /// Append a body-render diagnostic line for the rare "HTML body shows literal + /// `&` / ` ` / visible tags" bug. The symptom is + /// `EmailFilter.plainTextToHTML` escaping content that was ALREADY HTML. The + /// clean fix makes `BodyRenderer` the single conversion authority, so the + /// storage factory no longer re-converts — but we keep this channel to catch + /// any double-escaped body that still reaches storage (e.g. a sender that put + /// HTML in a text/plain part with no html alternative), via `diagnoseStoredBody`. + /// Prefer `diagnoseStoredBody` at call sites — it gates on the dangerous + /// condition before formatting. static func logBodyRender(_ message: String) { guard DebugModeManager.isLoggingEnabled() else { return } - let entry = "[\(Date().iso8601String())] \(message)\n" print("[BodyRenderLog] \(message)") - appendAsync(to: bodyRenderFileURL, entry: entry) - } - - static func readBodyRenderLog() -> String { - flushPendingWrites() - return (try? String(contentsOf: bodyRenderFileURL, encoding: .utf8)) ?? "(no body render log)" + AppLogStore.append(message, channel: .bodyRender) } - static func clearBodyRenderLog() { - try? "".write(to: bodyRenderFileURL, atomically: true, encoding: .utf8) - } - - // MARK: - Stuck Message Diagnostics Log + // MARK: - Stuck message diagnostics (debug-gated) - /// Dedicated channel for `StuckMessageDiagnostics` — the read-only scan for + /// Append a line from `StuckMessageDiagnostics` — the read-only scan for /// "searchable but can't open / no snippet / not in its folder" rows. Only - /// written by the Debug-menu scan; debug-gated per CLAUDE.md rule 12. - private static let stuckDiagFileName = "stuck_messages.log" - - private static var stuckDiagFileURL: URL { - let dir = FileManager.default.urls(for: .applicationSupportDirectory, in: .userDomainMask)[0] - .appendingPathComponent("TabMail", isDirectory: true) - try? FileManager.default.createDirectory(at: dir, withIntermediateDirectories: true) - return dir.appendingPathComponent(stuckDiagFileName) - } - + /// written by the Debug-menu scan. static func logStuckDiag(_ message: String) { guard DebugModeManager.isLoggingEnabled() else { return } - let entry = "[\(Date().iso8601String())] \(message)\n" print("[StuckDiag] \(message)") - appendAsync(to: stuckDiagFileURL, entry: entry) - } - - static func readStuckDiagLog() -> String { - flushPendingWrites() - return (try? String(contentsOf: stuckDiagFileURL, encoding: .utf8)) ?? "(no stuck-message diagnostics — run the scan from the Debug menu)" - } - - static func clearStuckDiagLog() { - try? "".write(to: stuckDiagFileURL, atomically: true, encoding: .utf8) + AppLogStore.append(message, channel: .stuckDiag) } // MARK: - Body double-escape detector (pure / ungated — unit-testable) @@ -471,10 +245,10 @@ enum BackgroundSyncLogger { || html.contains("&quot;") || html.contains("&#") } - /// Inspect a body about to be STORED and log to `body_render.log` only if it is - /// already double-escaped. Path-agnostic — catches the bug no matter which route - /// produced the body. Debug-mode-gated; a no-op (allocates nothing) in production - /// / when locked. + /// Inspect a body about to be STORED and log to the body-render channel only if + /// it is already double-escaped. Path-agnostic — catches the bug no matter which + /// route produced the body. Debug-mode-gated; a no-op (allocates nothing) in + /// production / when locked. static func diagnoseStoredBody(source: String, headerId: String, htmlContent: String?) { guard DebugModeManager.isLoggingEnabled() else { return } guard let html = htmlContent, htmlLooksDoubleEscaped(html) else { return } diff --git a/TabMail/Services/BootProfiler.swift b/TabMail/Services/BootProfiler.swift index fc161787..5a54dc87 100644 --- a/TabMail/Services/BootProfiler.swift +++ b/TabMail/Services/BootProfiler.swift @@ -23,15 +23,18 @@ import Synchronization /// `processStart` / `lastMark` statics are never initialized (no sysctl, no Mutex /// alloc), so it's effectively free. When UNLOCKED (debug build, or /// TestFlight/Release with debug mode unlocked in Settings) it prints to the -/// console AND appends to the downloadable **boot.log** (`BackgroundSyncLogger`), -/// so a cold-launch timeline can be captured on-device and shared from the debug -/// menu — not just read from the Xcode console. (Was `#if DEBUG`-only; switched to +/// console AND appends to the single downloadable **`tabmail.log`** via +/// `BackgroundSyncLogger.logBoot` (`AppLogStore`, `.boot` channel — read back +/// with `AppLogStore.read(channel: .boot)`), so a cold-launch timeline can be +/// captured on-device and shared from the debug menu — not just read from the +/// Xcode console. (Was `#if DEBUG`-only; switched to /// the runtime gate 2026-06-29 to enable on-device/OOO boot capture, as the old /// doc comment anticipated. Rule 12: a runtime debug gate is the sanctioned /// alternative to `#if DEBUG`.) /// -/// To read a launch: filter on `BootProfile` (console) or download "Boot Profile -/// Logs" from Settings → Debug. The biggest `Δ` between consecutive marks is the +/// To read a launch: filter on `BootProfile` (console) or share "App Logs" from +/// Settings → Debug and filter to the `[BOOT]` tag (`AppLogStore.read(channel: +/// .boot)`). The biggest `Δ` between consecutive marks is the /// next thing to make instant; compare the first mark's `+total` (pre-main) /// against the `first paint` mark to see how much is framework load vs. our work. enum BootProfiler { diff --git a/TabMail/Services/DebugModeManager.swift b/TabMail/Services/DebugModeManager.swift index 06a62a7b..f46a6b37 100644 --- a/TabMail/Services/DebugModeManager.swift +++ b/TabMail/Services/DebugModeManager.swift @@ -94,12 +94,31 @@ final class DebugModeManager { /// `invalidateLoggingCache()` from the auth session save/clear sites. nonisolated private static let loggingAllowedCache = Mutex(nil) + /// Test-only override for `isLoggingEnabled()`, bypassing the UserDefaults + /// unlock flag and the Keychain-derived identity check. + /// + /// `nil` — the default — means "derive it exactly as production does", so + /// the seam's resting value is the production initial value rather than a + /// convenient one (`MIS-IOS-017`). It exists because the always-on vs + /// debug-gated split across `AppLogStore`'s channels is a registered + /// decision (`IOS-LOG-002`) that a test must be able to check from BOTH + /// sides: gated channels silent when locked, AND writing when unlocked. In + /// the test host the real gate is always false (no unlock flag, no session), + /// so without this the unlocked half would be untestable and the assertion + /// one-sided. + #if DEBUG + nonisolated static let loggingEnabledOverrideForTesting = Mutex(nil) + #endif + /// Whether debug logging should be active (unlocked AND allowed user). /// Called from BackgroundSyncLogger to gate file I/O in production. /// Static nonisolated so it can be called from any thread without MainActor hop. /// Reads UserDefaults (thread-safe) + a cached Keychain-derived flag, so the /// per-log-call hot path never blocks on a synchronous Keychain XPC. static nonisolated func isLoggingEnabled() -> Bool { + #if DEBUG + if let override = loggingEnabledOverrideForTesting.withLock({ $0 }) { return override } + #endif let unlocked = UserDefaults.standard.bool(forKey: "debug_mode_unlocked") guard unlocked else { return false } return loggingAllowedCache.withLock { cache in diff --git a/TabMail/Services/DeviceSyncLogger.swift b/TabMail/Services/DeviceSyncLogger.swift index 51f2eda2..5004e799 100644 --- a/TabMail/Services/DeviceSyncLogger.swift +++ b/TabMail/Services/DeviceSyncLogger.swift @@ -4,50 +4,21 @@ import Foundation -/// Persistent diagnostic log for Device Sync events (connection, probes, responses). -/// Writes timestamped entries to a file in Application Support so they survive -/// app restarts and can be viewed in Settings > Debug > Device Sync Logs. +/// Diagnostic log writer for Device Sync events (connection, probes, responses). +/// +/// Writes to the single app log via `AppLogStore` on the `.deviceSync` channel; +/// read back from the Debug menu's App Logs share, or filtered with +/// `AppLogStore.read(channel: .deviceSync)`. +/// +/// Always-on, unchanged by the move off its own `device_sync.log` file: Device +/// Sync failures are reported from the field and there is no second channel that +/// records them (`IOS-LOG-002`). enum DeviceSyncLogger { - private static let maxEntries = 300 - private static let fileName = "device_sync.log" - - /// Serial queue for off-main file I/O. Callers include WebSocket handlers - /// which can run on the main thread — the existing sync read-modify-write - /// was blocking MainActor. See BackgroundSyncLogger.ioQueue for rationale. - private static let ioQueue = DispatchQueue(label: "tabmail.logger.devicesync.io", qos: .utility) - - private static var fileURL: URL { - let dir = FileManager.default.urls(for: .applicationSupportDirectory, in: .userDomainMask)[0] - .appendingPathComponent("TabMail", isDirectory: true) - try? FileManager.default.createDirectory(at: dir, withIntermediateDirectories: true) - return dir.appendingPathComponent(fileName) - } - - /// Append a Device Sync event. File I/O dispatched off-main on the serial - /// `ioQueue`. Timestamp is captured at call time so on-disk ordering - /// matches call ordering. + /// Append a Device Sync event. File I/O is dispatched off-main by + /// `AppLogStore`; callers include WebSocket handlers that run on the main + /// thread. The timestamp is captured at call time, but on-disk ordering is + /// APPEND order rather than call order — see `AppLogStore.append`. static func log(_ message: String) { - let entry = "[\(Date().iso8601String())] \(message)\n" - let url = fileURL - ioQueue.async { - if var existing = try? String(contentsOf: url, encoding: .utf8) { - existing += entry - let lines = existing.components(separatedBy: "\n").filter { !$0.isEmpty } - let trimmed = lines.suffix(maxEntries).joined(separator: "\n") + "\n" - try? trimmed.write(to: url, atomically: true, encoding: .utf8) - } else { - try? entry.write(to: url, atomically: true, encoding: .utf8) - } - } - } - - static func readLog() -> String { - // Drain pending async writes so a write-then-read roundtrip sees the entry. - ioQueue.sync { /* serial queue → .sync drains everything queued */ } - return (try? String(contentsOf: fileURL, encoding: .utf8)) ?? "(no Device Sync log)" - } - - static func clearLog() { - try? "".write(to: fileURL, atomically: true, encoding: .utf8) + AppLogStore.append(message, channel: .deviceSync) } } diff --git a/TabMail/Services/StartupMigrations.swift b/TabMail/Services/StartupMigrations.swift index cee06892..91342b65 100644 --- a/TabMail/Services/StartupMigrations.swift +++ b/TabMail/Services/StartupMigrations.swift @@ -20,9 +20,16 @@ import GRDB /// gate anymore. enum StartupMigrations { - /// `UserDefaults` flags gating the one-time resets, in run order. Keep this - /// in sync with the `bool(forKey:)` checks in `run(_:resetFTS:)` — it's the - /// single source of truth for `allResetsComplete`. + /// `UserDefaults` flags gating the one-time **cached-mail** resets, in run + /// order. Keep this in sync with the `bool(forKey:)` checks in + /// `run(_:resetFTS:legacyLogDirectory:)` — it's the single source of truth + /// for `allResetsComplete`. + /// + /// ⚠️ It lists only the resets that are SLOW on a populated mailbox, because + /// `allResetsComplete` is what decides whether launch shows the "Updating…" + /// splash. `didDeleteLegacyLogFiles_v1` is a one-shot too, but unlinking at + /// most fifteen small files is not splash-worthy work, so it is gated the + /// same way and deliberately kept out of this list. static let resetFlagKeys = [ "didMigrateHeaderIds_v2", "didClearBodiesForAttachmentEncoding_v1", @@ -30,6 +37,52 @@ enum StartupMigrations { "didCleanResetMessageData_v1", ] + /// One-shot flag for the legacy per-subsystem log-file cleanup. Not in + /// `resetFlagKeys` — see the note there. + static let legacyLogCleanupFlagKey = "didDeleteLegacyLogFiles_v1" + + /// The fifteen per-subsystem log files the main app wrote before + /// `AppLogStore` consolidated every channel into `tabmail.log` (GitHub #83). + /// + /// On upgrade these are STRANDED: nothing writes them, nothing reads them, + /// and the Debug menu's "Clear All Logs" no longer knows they exist — so + /// their bytes sit in Application Support forever. That is not merely + /// untidy: `StorageEstimator.totalSizeMB()` measures Application Support + /// recursively, `isOverBudget()` compares it to the user's budget, and + /// `SyncEngine.runPruneIfOverBudget` responds by deleting `MessageBody` and + /// header rows. Orphaned log bytes can therefore buy their size in pruned + /// mail — CONDITIONALLY, not categorically: `isOverBudget()` short-circuits + /// on `budgetMB != Int.max` and `defaultBudgetMB` is `Int.max`, so it bites + /// only once a user has configured a finite budget and usage reaches it. + /// + /// ⚠️ `tabmail.log` (the live app log) and `nse.log` (the NSE's, in the App + /// Group container, not here) are NOT in this list and must never be. + static let legacyLogFileNames = [ + "background_sync.log", + "error.log", + "chat_error.log", + "bg_app_refresh.log", + "bg_processing.log", + "ai_processing.log", + "push.log", + "backfill_ai.log", + "backfill.log", + "inbox.log", + "boot.log", + "body_render.log", + "stuck_messages.log", + "device_sync.log", + "auth_diagnostics.log", + ] + + /// Application Support / TabMail — where the legacy log files were written + /// and where `AppLogStore` writes `tabmail.log` today. Does NOT create the + /// directory: a missing directory means there is nothing to clean up. + static var defaultLegacyLogDirectory: URL { + FileManager.default.urls(for: .applicationSupportDirectory, in: .userDomainMask)[0] + .appendingPathComponent("TabMail", isDirectory: true) + } + /// True once every one-time reset has run (all flags set). Lets startup tell /// — without opening or scanning the mailbox — whether `run(_:)` will do /// (possibly slow, destructive) work, so it can decide to show the migration @@ -47,7 +100,14 @@ enum StartupMigrations { /// with the clean-reset's main-DB deletes (so the flag is set only once /// both halves are done — crash-safe). Injectable so tests don't touch /// the real FTS directory. - static func run(_ writer: some DatabaseWriter, resetFTS: () -> Void = { deleteFTSDirectory() }) { + /// - legacyLogDirectory: directory the orphaned pre-`AppLogStore` log + /// files are deleted from. Injectable for the same reason as `resetFTS` + /// — tests must not unlink files in the real Application Support. + static func run( + _ writer: some DatabaseWriter, + resetFTS: () -> Void = { deleteFTSDirectory() }, + legacyLogDirectory: URL = defaultLegacyLogDirectory + ) { let t0 = CFAbsoluteTimeGetCurrent() if !UserDefaults.standard.bool(forKey: "didMigrateHeaderIds_v2") { @@ -122,10 +182,139 @@ enum StartupMigrations { } } + if !UserDefaults.standard.bool(forKey: legacyLogCleanupFlagKey) { + // Armed ONLY on a fully clean pass, so a name that could not be + // unlinked leaves the flag unset and the next launch retries the + // whole (cheap) list. That is what makes a TRANSIENT obstruction + // self-heal. It is NOT a promise of progress against a PERMANENTLY + // undeletable file (immutable flag, unwritable parent): that pins the + // flag unset and re-runs the fifteen-name scan every launch, forever. + // The cost is bounded — fifteen `unlink` syscalls, fourteen of which + // return ENOENT immediately once the removable names are gone — and + // arming after a partial pass would be strictly worse, stranding + // whatever was left, permanently, with no UI that can reach it. + let cleanup = deleteLegacyLogFiles(in: legacyLogDirectory) + if cleanup.failed == 0 { + UserDefaults.standard.set(true, forKey: legacyLogCleanupFlagKey) + } + // Rule 12: diagnostic, so it must be a no-op in a production build. + if DebugModeManager.isLoggingEnabled() { + print("[Migration] Deleted \(cleanup.deleted) orphaned legacy log file(s); " + + "\(cleanup.failed) failed, \(legacyLogCleanupFlagKey) armed: \(cleanup.failed == 0)") + } + } + let ms = Int((CFAbsoluteTimeGetCurrent() - t0) * 1000) print("[Migration] Startup data resets completed in \(ms)ms") } + /// Outcome of one legacy-log cleanup pass: how many of the fifteen names + /// were unlinked, and how many were present but could not be. The caller + /// arms `legacyLogCleanupFlagKey` only when `failed == 0`. + struct LegacyLogCleanup: Equatable, Sendable { + var deleted = 0 + var failed = 0 + } + + /// Unlink every `legacyLogFileNames` entry present in `directory`, and + /// report how many were removed and how many were present but could not be. + /// + /// A name that is not there is NOT an error — a fresh install has none of + /// them, and a partially-completed previous attempt has some. Only the + /// fifteen listed names are touched; the directory is never enumerated, so + /// `tabmail.log` and anything else living there cannot be caught by a + /// widened pattern. + /// + /// Removal is `unlink(2)`, NOT `FileManager.removeItem(at:)`. Three + /// properties follow from that, and they are the whole reason for the choice: + /// + /// * **It can never recurse, and there is no check/use window.** + /// `removeItem(at:)` is documented recursive, so a directory bearing one of + /// these names would be deleted along with its whole contents — + /// irreversibly, at launch, before any UI exists to report it. Guarding it + /// with an `isRegularFile` query does not close that: the query and the + /// removal are two syscalls with a window between them. `unlink` is one + /// syscall that refuses a directory outright (Darwin returns `EPERM`), so + /// there is no type check to race and nothing to recurse into (THE MANTRA: + /// failing closed is always acceptable, a wrong irreversible delete is not). + /// * **A symlink loses the LINK, never its target.** `unlink` operates on the + /// directory entry, so a legacy name that is a symlink — dangling or valid — + /// has the entry removed and whatever it pointed at is left untouched. That + /// is the correct outcome: the stranded name goes, and this function never + /// reaches through a name it was handed. + /// * **Each name's failure is isolated.** One unremovable name must not + /// abort the pass. It used to: `try` propagated straight out of the loop, + /// so the first failure skipped every later name — and because the + /// one-shot flag is armed only after a full pass, every subsequent launch + /// aborted at the same index, forever. `device_sync.log` and + /// `auth_diagnostics.log` are the last two names AND two of the five + /// channels written in production, so "abort at the first failure" left + /// behind exactly the bytes this function exists to reclaim. + /// + /// A directory at a legacy name is SKIPPED, and a skip is NOT a failure. It + /// is a permanent, deliberate refusal — no later launch could make a + /// directory removable by this function — so it must not block the flag; + /// counting it would re-scan all fifteen names on every launch forever with + /// no progress to show for it. Every OTHER failure IS counted, including one + /// whose cause cannot be determined: erasing an unresolved error into a clean + /// skip would arm the one-shot flag and strand that name's bytes forever. + /// "Directory" there means a directory ENTRY at this name, classified with + /// `lstat(2)` — a link whose unlink failed is a failure and is retried next + /// launch. + @discardableResult + static func deleteLegacyLogFiles(in directory: URL) -> LegacyLogCleanup { + var result = LegacyLogCleanup() + for name in legacyLogFileNames { + let url = directory.appendingPathComponent(name) + // `unlink` and not `FileManager.removeItem`: one atomic syscall with + // no check/use window, and it can NEVER recurse. `removeItem` is + // documented recursive, so a directory that appeared at a legacy name + // between a type check and the removal would be deleted WITH ITS + // CONTENTS, at launch, before any UI exists to report it. + if unlink(url.path) == 0 { + result.deleted += 1 + continue + } + let err = errno // capture before any call below can clobber it + if err == ENOENT { continue } // already gone — the common path + // Darwin returns EPERM for BOTH a directory and an immutable file, and + // the two are not the same outcome, so the ambiguity has to be + // resolved. This query is safe where the old one was not: NO removal + // follows it, it only classifies. An unresolvable answer counts as a + // FAILURE, never as a clean skip — that keeps the one-shot flag unset + // and the name retried, rather than stranding it forever on a + // transient metadata error. + // + // `lstat(2)` rather than `URL.resourceValues(forKeys: [.isDirectoryKey])`. + // ⚠️ This is a BEHAVIOUR-PRESERVING simplification, NOT a bug fix, and + // the distinction is worth the comment because it was reported as a + // defect and is not one. Foundation's `.isDirectoryKey` does NOT follow + // symlinks: on a symlink to a directory it answers `isDirectory == + // false` and `isSymbolicLink == true`, so the old predicate ALSO fell + // through to the failure branch. Verified twice, because the docs do + // not say so plainly — directly against Foundation, and by inverting + // this line and re-running `StartupMigrationsTests`, which stays green + // precisely because both spellings agree. + // `lstat` is kept because it states the intent in the syscall itself: + // one call, no Foundation round-trip, and "does not follow symlinks" is + // its defined contract rather than an empirical finding a future reader + // would have to re-establish. Only a REAL directory entry is the + // permanent refusal this skip exists for; a symlink whose unlink failed + // is a FAILURE either way. + var entry = stat() + if lstat(url.path, &entry) == 0, (entry.st_mode & S_IFMT) == S_IFDIR { + continue // a directory at this name: deliberate, permanent refusal + } + result.failed += 1 + // Rule 12: diagnostic, so it must be a no-op in a production build. + if DebugModeManager.isLoggingEnabled() { + print("[Migration] Could not unlink legacy log \(name): " + + "\(String(cString: strerror(err))) — will retry next launch") + } + } + return result + } + /// Delete the FTS database directory so `SearchIndex.initialize()` rebuilds it /// fresh from the (now-empty) main DB. Safe to call at DB-open: SearchIndex has /// not initialized yet, so no pool/connection is open on these files (this is diff --git a/TabMail/Services/StuckMessageDiagnostics.swift b/TabMail/Services/StuckMessageDiagnostics.swift index a766c8da..fbb234e0 100644 --- a/TabMail/Services/StuckMessageDiagnostics.swift +++ b/TabMail/Services/StuckMessageDiagnostics.swift @@ -22,7 +22,8 @@ import GRDB /// stored UID is stale for the folder it now claims to live in. /// /// This scan only READS the DB + FTS and writes a human-readable report to the -/// `stuck_messages` log channel (shareable from the Debug menu). It mutates nothing. +/// `.stuckDiag` channel of the shared app log, persisted with the `[STUCK]` tag +/// and shareable from the Debug menu's "Stuck Message Report". It mutates nothing. /// Debug-gated per CLAUDE.md rule 12; only reachable from the hidden Debug menu. enum StuckMessageDiagnostics { /// Bounded per-class sample size — display-only, full data stays in the DB. @@ -49,7 +50,9 @@ enum StuckMessageDiagnostics { static func run() async { guard DebugModeManager.isLoggingEnabled() else { return } let pool = AppDatabase.rawPool - BackgroundSyncLogger.clearStuckDiagLog() + // Clear only THIS channel — the report is meant to be one scan's output, + // and the log file it shares now holds every other subsystem's history. + AppLogStore.clear(channel: .stuckDiag) BackgroundSyncLogger.logStuckDiag("==== Stuck-message scan START ====") // --- Aggregate counts (read-only) --------------------------------- diff --git a/TabMail/Services/Sync/BodyFetchProcessor.swift b/TabMail/Services/Sync/BodyFetchProcessor.swift index 369523d6..7c23908e 100644 --- a/TabMail/Services/Sync/BodyFetchProcessor.swift +++ b/TabMail/Services/Sync/BodyFetchProcessor.swift @@ -745,7 +745,9 @@ enum BodyFetchProcessor { // (NOT re-derived from htmlContent, which would round-trip plain→HTML→plain). var body = MessageBody.create(contentKey: contentKey, htmlBody: rendered.htmlContent) // Diagnostic (debug-gated, no-op in prod): flag if a double-escaped body ever - // reaches storage. Captured in body_render.log (DebugMenu › Logs). + // reaches storage. Captured on the `.bodyRender` channel of the single + // tabmail.log (`AppLogStore.read(channel: .bodyRender)`), exported by + // DebugMenu › Logs › "App Logs". BackgroundSyncLogger.diagnoseStoredBody(source: "BodyFetch", headerId: headerId, htmlContent: body.htmlContent) if !fullMessage.attachments.isEmpty { body.attachmentsJSON = String(data: (try? JSONEncoder().encode(fullMessage.attachments)) ?? Data(), encoding: .utf8) diff --git a/TabMail/Views/Settings/DebugLogView.swift b/TabMail/Views/Settings/DebugLogView.swift index c625e3ce..619e1762 100644 --- a/TabMail/Views/Settings/DebugLogView.swift +++ b/TabMail/Views/Settings/DebugLogView.swift @@ -105,7 +105,7 @@ struct DebugMenuView: View { .font(.caption) .foregroundStyle(.secondary) } - LogShareButton(title: "Stuck Message Report", filename: "stuck_messages.txt", readLog: { BackgroundSyncLogger.readStuckDiagLog() }, clearLog: { BackgroundSyncLogger.clearStuckDiagLog() }) + LogShareButton(title: "Stuck Message Report", filename: "stuck_messages.txt", readLog: { AppLogStore.read(channel: .stuckDiag) }, clearLog: { AppLogStore.clear(channel: .stuckDiag) }) Text("Read-only scan for messages that are searchable but can't open / have no snippet / aren't in their folder. Nothing is modified. Run the scan, then share the report.") .font(.caption) .foregroundStyle(.secondary) @@ -160,36 +160,15 @@ struct DebugMenuView: View { } Section("Logs") { - LogShareButton(title: "Sync Logs", filename: "sync_logs.txt", readLog: { BackgroundSyncLogger.readLog() }, clearLog: { BackgroundSyncLogger.clearLog() }) - LogShareButton(title: "Error Logs", filename: "error_logs.txt", readLog: { BackgroundSyncLogger.readErrorLog() }, clearLog: { BackgroundSyncLogger.clearErrorLog() }) - LogShareButton(title: "Chat Error Logs", filename: "chat_error_logs.txt", readLog: { BackgroundSyncLogger.readChatErrorLog() }, clearLog: { BackgroundSyncLogger.clearChatErrorLog() }) - LogShareButton(title: "Device Sync Logs", filename: "device_sync_logs.txt", readLog: { DeviceSyncLogger.readLog() }, clearLog: { DeviceSyncLogger.clearLog() }) - LogShareButton(title: "BG App Refresh Logs", filename: "bgapprefresh_logs.txt", readLog: { BackgroundSyncLogger.readBGAppRefreshLog() }, clearLog: { BackgroundSyncLogger.clearBGAppRefreshLog() }) - LogShareButton(title: "BG Processing Logs", filename: "bgprocessing_logs.txt", readLog: { BackgroundSyncLogger.readBGProcessingLog() }, clearLog: { BackgroundSyncLogger.clearBGProcessingLog() }) - LogShareButton(title: "AI Processing Logs", filename: "ai_logs.txt", readLog: { BackgroundSyncLogger.readAIProcessingLog() }, clearLog: { BackgroundSyncLogger.clearAIProcessingLog() }) - LogShareButton(title: "Backfill AI Refinement Logs", filename: "backfill_ai_logs.txt", readLog: { BackgroundSyncLogger.readBackfillAILog() }, clearLog: { BackgroundSyncLogger.clearBackfillAILog() }) - LogShareButton(title: "Backfill Logs", filename: "backfill_logs.txt", readLog: { BackgroundSyncLogger.readBackfillLog() }, clearLog: { BackgroundSyncLogger.clearBackfillLog() }) - LogShareButton(title: "Push Notification Logs", filename: "push_logs.txt", readLog: { BackgroundSyncLogger.readPushLog() }, clearLog: { BackgroundSyncLogger.clearPushLog() }) - LogShareButton(title: "Inbox Logs", filename: "inbox_logs.txt", readLog: { BackgroundSyncLogger.readInboxLog() }, clearLog: { BackgroundSyncLogger.clearInboxLog() }) - LogShareButton(title: "Body Render Logs", filename: "body_render_logs.txt", readLog: { BackgroundSyncLogger.readBodyRenderLog() }, clearLog: { BackgroundSyncLogger.clearBodyRenderLog() }) - LogShareButton(title: "Boot Profile Logs", filename: "boot_logs.txt", readLog: { BackgroundSyncLogger.readBootLog() }, clearLog: { BackgroundSyncLogger.clearBootLog() }) + LogShareButton(title: "App Logs", filename: "tabmail_logs.txt", readLog: { AppLogStore.read() }, clearLog: { AppLogStore.clear() }) LogShareButton(title: "NSE Logs", filename: "nse_logs.txt", readLog: { NSELogStore.read() }, clearLog: { NSELogStore.clear() }) + Text("One file per process: App Logs is every main-app subsystem interleaved in the order entries were written, each entry tagged with its channel (SYNC, ERROR, AI, BACKFILL, …). NSE Logs is the notification extension's own file — a separate process with its own container.") + .font(.caption) + .foregroundStyle(.secondary) + Button(role: .destructive) { - BackgroundSyncLogger.clearLog() - BackgroundSyncLogger.clearErrorLog() - BackgroundSyncLogger.clearChatErrorLog() - DeviceSyncLogger.clearLog() - BackgroundSyncLogger.clearBGAppRefreshLog() - BackgroundSyncLogger.clearBGProcessingLog() - BackgroundSyncLogger.clearAIProcessingLog() - BackgroundSyncLogger.clearBackfillAILog() - BackgroundSyncLogger.clearBackfillLog() - BackgroundSyncLogger.clearPushLog() - BackgroundSyncLogger.clearInboxLog() - BackgroundSyncLogger.clearBodyRenderLog() - BackgroundSyncLogger.clearStuckDiagLog() - BackgroundSyncLogger.clearBootLog() + AppLogStore.clear() NSELogStore.clear() } label: { Label("Clear All Logs", systemImage: "trash") diff --git a/TabMailTests/Services/AppLogStoreTests.swift b/TabMailTests/Services/AppLogStoreTests.swift new file mode 100644 index 00000000..53750f72 --- /dev/null +++ b/TabMailTests/Services/AppLogStoreTests.swift @@ -0,0 +1,1567 @@ +/* This Source Code Form is subject to the terms of the Mozilla Public + * License, v. 2.0. If a copy of the MPL was not distributed with this + * file, You can obtain one at https://mozilla.org/MPL/2.0/. */ + +import Testing +import Foundation +@testable import TabMail + +/// The timestamp field of an app-log entry line — everything between the +/// line's leading `[` and the first `]`. +/// +/// Shared by the three suites that assert on entry lines (`AppLogStore`, +/// `BackgroundSyncLogger`, `AuthDiagnostics`) so they parse the format one way. +/// Scalar-wise rather than with `hasPrefix`/`split`, matching +/// `AppLogStore.entryTag` and `MIS-IOS-013`. +enum AppLogEntryLine { + static func timestampField(of line: Substring) -> String? { + let scalars = Array(line.unicodeScalars) + guard scalars.first == "[" else { return nil } + guard let end = scalars.firstIndex(of: "]") else { return nil } + var field = String.UnicodeScalarView() + for scalar in scalars[1.. Void + } + + /// The five channels that persist in production regardless of the debug + /// gate — a field failure has to leave a trace (`IOS-LOG-002`). + static let alwaysOnWriters: [ChannelWriter] = [ + ChannelWriter(channel: .sync, backgroundSyncLoggerFunction: "log") { + BackgroundSyncLogger.log($0) + }, + ChannelWriter(channel: .error, backgroundSyncLoggerFunction: "logError") { + BackgroundSyncLogger.logError($0, source: "TestSource") + }, + ChannelWriter(channel: .chatError, backgroundSyncLoggerFunction: "logChatError") { + BackgroundSyncLogger.logChatError($0) + }, + ChannelWriter(channel: .deviceSync, backgroundSyncLoggerFunction: nil) { + DeviceSyncLogger.log($0) + }, + ChannelWriter(channel: .auth, backgroundSyncLoggerFunction: nil) { + AuthDiagnostics.log($0) + }, + ] + + /// The ten channels added for investigation, each a no-op unless debug mode + /// is unlocked (global `CLAUDE.md` rule 12). + static let debugGatedWriters: [ChannelWriter] = [ + ChannelWriter(channel: .bgAppRefresh, backgroundSyncLoggerFunction: "logBGAppRefresh") { + BackgroundSyncLogger.logBGAppRefresh($0) + }, + ChannelWriter(channel: .bgProcessing, backgroundSyncLoggerFunction: "logBGProcessing") { + BackgroundSyncLogger.logBGProcessing($0) + }, + ChannelWriter(channel: .aiProcessing, backgroundSyncLoggerFunction: "logAIProcessing") { + BackgroundSyncLogger.logAIProcessing($0) + }, + ChannelWriter(channel: .push, backgroundSyncLoggerFunction: "logPush") { + BackgroundSyncLogger.logPush($0) + }, + ChannelWriter(channel: .backfillAI, backgroundSyncLoggerFunction: "logBackfillAI") { + BackgroundSyncLogger.logBackfillAI($0) + }, + ChannelWriter(channel: .backfill, backgroundSyncLoggerFunction: "logBackfill") { + BackgroundSyncLogger.logBackfill($0) + }, + ChannelWriter(channel: .inbox, backgroundSyncLoggerFunction: "logInbox") { + BackgroundSyncLogger.logInbox($0) + }, + ChannelWriter(channel: .boot, backgroundSyncLoggerFunction: "logBoot") { + BackgroundSyncLogger.logBoot($0) + }, + ChannelWriter(channel: .bodyRender, backgroundSyncLoggerFunction: "logBodyRender") { + BackgroundSyncLogger.logBodyRender($0) + }, + ChannelWriter(channel: .stuckDiag, backgroundSyncLoggerFunction: "logStuckDiag") { + BackgroundSyncLogger.logStuckDiag($0) + }, + ] + + /// A per-channel marker that cannot be a SUBSTRING of another channel's. + /// + /// ⚠️ This is the shape four tests in this file got wrong. They asserted + /// `contents.contains("sync_\(stamp)")` after writing `devicesync_\(stamp)`, + /// and `"devicesync_X".contains("sync_X")` is `true` — so the assertion + /// passed on a completely different channel's entry and the writer it named + /// could be deleted outright without going red. Delimiting the tag on BOTH + /// sides makes non-containment structural: `marker-AI-X` is not inside + /// `marker-BACKFILL-AI-X`, because what follows `marker-` there is `B`. + static func marker(for channel: AppLogChannel, _ stamp: some StringProtocol) -> String { + "marker-\(channel.tag)-\(stamp)" + } + + /// Point the store at a fresh temp file, inside a directory of its own, for + /// the duration of one test — then restore every override. + /// + /// The DIRECTORY is per-test (not just the file) so that "no channel wrote + /// its own file" is answerable: enumerate the directory and anything beyond + /// the log itself is a regression. Enumerating the shared temp directory + /// instead, as this helper used to, can only ever see files this suite + /// named — which is why the old check could not fail. + private func withTempLog(_ body: (URL) throws -> T) rethrows -> T { + let dir = FileManager.default.temporaryDirectory + .appendingPathComponent("applog_\(UUID().uuidString)", isDirectory: true) + try? FileManager.default.createDirectory(at: dir, withIntermediateDirectories: true) + let url = dir.appendingPathComponent("tabmail.log") + AppLogStore.fileURLOverride.withLock { $0 = url } + defer { + AppLogStore._resetForTesting() + try? FileManager.default.removeItem(at: dir) + } + return try body(url) + } + + /// Force the debug gate for the duration of one test, then restore it. + private func withDebugLogging(_ enabled: Bool, _ body: () throws -> T) rethrows -> T { + DebugModeManager.loggingEnabledOverrideForTesting.withLock { $0 = enabled } + defer { DebugModeManager.loggingEnabledOverrideForTesting.withLock { $0 = nil } } + return try body() + } + + /// Everything in `directory`, sorted. Names, not URLs: `contentsOfDirectory` + /// can hand back a `/private`-resolved URL that compares unequal to the + /// override's own URL for reasons that have nothing to do with logging. + private func fileNames(in directory: URL) throws -> [String] { + try FileManager.default.contentsOfDirectory(atPath: directory.path).sorted() + } + + // MARK: - The single-file invariant + + @Test("Every channel writes to ONE file") + func allChannelsShareOneFile() throws { + try withTempLog { url in + try withDebugLogging(true) { + // One entry per channel, written through the store directly so + // this covers the full channel set rather than only the channels + // that happen to have a façade today. + // + // `Self.marker` — the collision-safe `marker--` shape + // `facadeWritersShareOneFile` uses — and NOT `marker_`. The + // old spelling made this test vacuous for two channels: + // `marker_BACKFILL` is a SUBSTRING of `marker_BACKFILL-AI`, so + // `append` could return early for `.backfill` and the assertion + // still passed on the BACKFILL-AI entry. Delimiting the tag on + // both sides is what makes non-containment structural. + let stamp = UUID().uuidString.prefix(8) + for channel in AppLogChannel.allCases { + AppLogStore.append(Self.marker(for: channel, stamp), channel: channel) + } + let contents = AppLogStore.read() + for channel in AppLogChannel.allCases { + #expect(contents.contains(Self.marker(for: channel, stamp)), + "\(channel.tag) did not land in the shared file") + } + // And `AppLogStore` itself created exactly one file in the + // directory the override points at. + // + // ⚠️ Scope, stated precisely because the earlier wording claimed + // more than this can deliver: every write here goes through + // `AppLogStore.append`, so what is proven is that the STORE does + // not fan out per channel. It does NOT prove that + // `device_sync.log` cannot reappear beside `tabmail.log` — the + // shipped `DeviceSyncLogger` path was a hardcoded real + // Application Support URL, not one derived from + // `AppLogStore.fileURL`, so a writer that reintroduced it would + // write outside this override's directory and be invisible here. + // `facadeWritersShareOneFile` covers the façades, and carries + // the same caveat. + let names = try fileNames(in: url.deletingLastPathComponent()) + #expect(names == [url.lastPathComponent], + "a sibling log file was created: \(names)") + } + } + } + + @Test("The named writers all land in the same file, and open no second one") + func facadeWritersShareOneFile() throws { + try withTempLog { url in + try withDebugLogging(true) { + let stamp = UUID().uuidString.prefix(8) + for writer in Self.alwaysOnWriters + Self.debugGatedWriters { + writer.write(Self.marker(for: writer.channel, stamp)) + } + + let contents = AppLogStore.read() + for writer in Self.alwaysOnWriters + Self.debugGatedWriters { + let marker = Self.marker(for: writer.channel, stamp) + #expect(contents.contains(marker), + "\(writer.channel.tag) writer did not reach the shared file") + } + + // "Reached the shared file" is only half the invariant. A façade + // that kept its own `device_sync.log` AND also called + // `AppLogStore.append` satisfies every substring assertion above + // while production writes two persistent files — which is the + // entire thing consolidation was for. Enumerating the directory + // after the façades have run is what makes that dual write + // visible. + // + // ⚠️ What this cannot see: a writer whose second file is a + // HARDCODED absolute path (the shape the shipped + // `DeviceSyncLogger` actually had — real Application Support, + // not derived from `AppLogStore.fileURL`) lands outside this + // override's directory and is invisible to any enumeration a + // test may safely perform. Covered here: a sibling written + // relative to the log's own directory. + let names = try fileNames(in: url.deletingLastPathComponent()) + #expect(names == [url.lastPathComponent], + "a façade opened a second log file: \(names)") + } + } + } + + @Test("Entries from different channels interleave in append order") + func entriesInterleaveInCallOrder() { + withTempLog { _ in + withDebugLogging(true) { + AppLogStore.append("first", channel: .sync) + AppLogStore.append("second", channel: .inbox) + AppLogStore.append("third", channel: .aiProcessing) + + let contents = AppLogStore.read() + guard let firstPos = contents.range(of: "first"), + let secondPos = contents.range(of: "second"), + let thirdPos = contents.range(of: "third") else { + Issue.record("markers missing from log") + return + } + // Cross-channel interleaving is the whole reason for one file — + // a per-channel file cannot express this ordering at all. + // ⚠️ These writes are SEQUENTIAL, so append order and call order + // coincide here. This test pins the interleaving, NOT a concurrent + // call-order guarantee: across threads a caller preempted between + // stamping and enqueueing lands after one that stamped later. + #expect(firstPos.lowerBound < secondPos.lowerBound) + #expect(secondPos.lowerBound < thirdPos.lowerBound) + } + } + } + + // MARK: - Channel separability + + @Test("read(channel:) returns only that channel's entries") + func channelFilterIsolatesOneChannel() { + withTempLog { _ in + withDebugLogging(true) { + AppLogStore.append("backfill-first", channel: .backfill) + AppLogStore.append("push-only", channel: .push) + AppLogStore.append("backfill-second", channel: .backfill) + + let filtered = AppLogStore.read(channel: .backfill) + // ⚠️ The markers are deliberately not prefixes of each other. + // With `keep_me` / `keep_me_too`, a filter that returned only the + // LAST matching entry still satisfied `contains("keep_me")` — + // via `keep_me_too` — so both assertions passed while every + // earlier entry on the channel was being dropped. + #expect(filtered.contains("backfill-first")) + #expect(filtered.contains("backfill-second")) + #expect(!filtered.contains("push-only")) + // Count too: dropping an entry cannot hide behind a marker that + // happens to appear inside another one. + let lines = filtered.split(separator: "\n", omittingEmptySubsequences: true) + #expect(lines.count == 2, "expected both BACKFILL entries, got: \(filtered)") + } + } + } + + @Test("A multi-line entry stays with its own channel") + func continuationLinesFollowTheirEntry() { + // logChatError deliberately emits a second ` User message: …` line. + // A filter that keyed on every physical line would orphan it, and a + // filter that mis-attributed it would leak user text into another + // channel's export. + let text = """ + [2026-08-25T10:00:00Z] [CHAT] tool failed + User message: hello world + [2026-08-25T10:00:01Z] [PUSH] registered + + """ + let chat = AppLogStore.filter(text, keepingChannel: .chatError) + #expect(chat.contains("tool failed")) + #expect(chat.contains("User message: hello world")) + #expect(!chat.contains("registered")) + + let push = AppLogStore.filter(text, keepingChannel: .push) + #expect(push.contains("registered")) + #expect(!push.contains("hello world")) + } + + @Test("entryTag parses a tag only from a line that starts an entry") + func entryTagParsing() { + #expect(AppLogStore.entryTag(of: "[2026-08-25T10:00:00Z] [SYNC] hello") == "SYNC") + #expect(AppLogStore.entryTag(of: "[2026-08-25T10:00:00Z] [BACKFILL-AI] hello") == "BACKFILL-AI") + // logError nests a source after the channel tag — the CHANNEL still wins. + #expect(AppLogStore.entryTag(of: "[2026-08-25T10:00:00Z] [ERROR] [SyncEngine] boom") == "ERROR") + // An entry whose message is empty still ends `] `. + #expect(AppLogStore.entryTag(of: "[2026-08-25T10:00:00Z] [SYNC] ") == "SYNC") + // Continuation and malformed lines are not entry starts. + #expect(AppLogStore.entryTag(of: " User message: hi") == nil) + #expect(AppLogStore.entryTag(of: "") == nil) + #expect(AppLogStore.entryTag(of: "[2026-08-25T10:00:00Z] no bracket") == nil) + #expect(AppLogStore.entryTag(of: "[2026-08-25T10:00:00Z] [UNTERMINATED") == nil) + } + + @Test("entryTag rejects a tag that is not delimited or is not a real channel") + func entryTagRejectsForgedAndUnknownTags() { + // Both of these used to parse as entry starts, and `read(channel:)` / + // `clear(channel:)` key off exactly this function — so a continuation + // line carrying user-authored text could be attributed to, or cleared + // from, a channel it was never written on. + // + // No space after the tag's `]`: the text is a continuation line that + // merely LOOKS like an entry, not a SYNC entry. + #expect(AppLogStore.entryTag(of: "[junk] [SYNC]forged") == nil) + #expect(AppLogStore.entryTag(of: "[2026-08-25T10:00:00Z] [SYNC]x") == nil) + // A bracketed field that is not an AppLogChannel tag is not a tag. + #expect(AppLogStore.entryTag(of: "[2026-08-25T10:00:00Z] [NOTACHANNEL] hi") == nil) + #expect(AppLogStore.entryTag(of: "[2026-08-25T10:00:00Z] [] hi") == nil) + #expect(AppLogStore.entryTag(of: "[2026-08-25T10:00:00Z] [sync] hi") == nil) + // And the rejection composes: a forged line is filtered/cleared with the + // entry above it, never on its own. + let text = """ + [2026-08-25T10:00:00Z] [CHAT] tool failed + [x] [SYNC]not really sync + [2026-08-25T10:00:01Z] [PUSH] registered + + """ + #expect(!AppLogStore.filter(text, keepingChannel: .sync).contains("not really sync")) + #expect(AppLogStore.filter(text, keepingChannel: .chatError).contains("not really sync")) + } + + // MARK: - The two bounds on the persisted user span + // + // `logChatError` runs TWO different caps over `userMessage`, they answer + // different questions, and an oracle that conflates them is wrong in one + // direction or the other. Named here so every assertion below says which + // one it is measuring. + + /// The PRIVACY cap — `prefix(100)`. It decides how much of what the user + /// actually TYPED is persisted, and it is the tighter of the two. + static let userMessagePrivacyCap = 100 + + /// The SIZE cap, in unicode scalars. This is the hard ceiling a single + /// oversized grapheme cannot defeat (`MIS-IOS-013`) — `prefix(100)` counts + /// extended grapheme clusters and bounds neither scalars nor bytes. + static let userMessageScalarCap = 400 + + /// The most `DebugModeManager.escapedForLogLine` can expand a span by. It + /// rewrites ONE control scalar as the six characters `\uXXXX` and copies + /// every other scalar through unchanged. + static let escapeExpansionFactor = 6 + + /// The ceiling on the POST-escape span these tests read back off disk. + /// + /// ⚠️ Six times the pre-escape cap, NOT the cap itself, and the difference + /// is the code's real guarantee rather than a slack allowance. The caps run + /// BEFORE the escaper on purpose (`chatErrorCapsBeforeEscaping` pins that + /// order — capping afterwards would slice a generated `\uXXXX` in half), so + /// a user message of 400 newlines is 2400 scalars on disk and entirely + /// correct. Asserting the pre-escape number against post-escape text would + /// fail on CORRECT code for any control-character-heavy message. + static var persistedUserSpanCeiling: Int { userMessageScalarCap * escapeExpansionFactor } + + @Test("A newline in logChatError's user message cannot forge another channel's entry") + func chatErrorUserMessageCannotForgeAnotherChannel() { + // `logChatError`'s `userMessage` is LITERAL user-typed chat input — + // `AIChat` passes `userText` straight through — and the writer is + // ALWAYS-ON, so this reaches production on every device. Unescaped, a user + // who types a newline followed by `[x] [AUTH] …` writes a second PHYSICAL + // line that `entryTag` parses as a genuine AUTH entry. + // + // The INVARIANT, not the mechanism: nothing a user can type produces an + // entry attributed to a channel they never wrote on, their own text stays + // wholly inside the CHAT entry that carries it, and clearing CHAT takes + // all of it. Escaping is one way to get there; the properties are what is + // pinned. + // + // Before consolidation the same forgery was confined to `chat_error.log` + // and harmless. The shared file is what makes it cross-channel. + withTempLog { _ in + withDebugLogging(true) { + let stamp = UUID().uuidString.prefix(8) + let chatMarker = Self.marker(for: .chatError, stamp) + let forged = "forged-\(stamp)" + BackgroundSyncLogger.logChatError( + chatMarker, + userMessage: "help\n[x] [AUTH] \(forged) someone@example.com") + + // 1. No AUTH entry carries it. Scoped to this test's own stamp + // rather than to the AUTH channel being empty: `AuthDiagnostics` + // is always-on, so a task escaping an earlier test can land real + // AUTH entries in this same redirected file. + #expect(!AppLogStore.read(channel: .auth).contains(forged), + "user-typed text forged an AUTH entry") + + // 2. The real CHAT entry is still whole — head AND continuation. + // A forged line that STARTS a new entry ends the CHAT run, so + // the user's own text is cut out of the one channel it belongs + // to and the export the reporter reads is silently truncated. + let chat = AppLogStore.read(channel: .chatError) + #expect(chat.contains(chatMarker), "the CHAT entry's own head is missing") + #expect(chat.contains(forged), + "the user's text was truncated out of its own channel") + + // 3. Clearing CHAT takes all of it. A forged tail that no channel + // owns outlives every clear the UI offers short of "Clear All". + AppLogStore.clear(channel: .chatError) + #expect(!AppLogStore.read().contains(forged), + "a forged remainder survived clear(channel: .chatError)") + } + } + } + + @Test("logChatError bounds how much of the user's text it persists") + func chatErrorUserMessageIsCapped() { + // Nothing in the tree writes a `userMessage` longer than a chat prompt, + // so deleting the cap outright leaves every other test in this file + // green. The INVARIANT: what lands on disk is bounded by the CAP, not by + // how much the user happened to type. + withTempLog { _ in + withDebugLogging(true) { + let stamp = String(UUID().uuidString.prefix(8)) + let chatMarker = Self.marker(for: .chatError, stamp) + let head = "head-\(stamp)" + let tail = "tail-\(stamp)" + // `tail` sits far past the cap, so it can only reach the file if + // no cap ran at all. + BackgroundSyncLogger.logChatError( + chatMarker, + userMessage: head + String(repeating: "a", count: 500) + tail) + + let chat = AppLogStore.read(channel: .chatError) + #expect(chat.contains(chatMarker), "the CHAT entry is missing entirely") + // Non-vacuity: the HEAD of the user's text is still there, so + // this measures a cap rather than a writer that dropped the span. + #expect(chat.contains(head), "the user span was dropped, not capped") + #expect(!chat.contains(tail), + "the whole user message was persisted — the cap is gone") + + // And the persisted span itself is bounded, independently of + // where either marker happens to fall inside it. The UNIVERSAL + // ceiling — what holds for any input at all — is the pre-escape + // scalar cap times the escaper's maximum expansion. The tighter + // privacy bound on ordinary text is pinned separately by + // `chatErrorPrivacyCapBoundsOrdinaryText`, which is where an + // exact number can honestly be asserted. + guard let span = Self.userMessageSpan(in: chat, after: chatMarker) else { + Issue.record("no `User message:` continuation line in: \(chat)") + return + } + #expect(span.unicodeScalars.count <= Self.persistedUserSpanCeiling, + "persisted user span is \(span.unicodeScalars.count) scalars") + } + } + } + + @Test("The privacy cap bounds ORDINARY text, not just a pathological grapheme") + func chatErrorPrivacyCapBoundsOrdinaryText() { + // Two caps run over `userMessage` and only ONE of them answers "how much + // of what the user typed is persisted". Delete `prefix(100)` and keep the + // 400-scalar size cap and every other test in this file stays green while + // four times the intended user text lands on disk — the size cap cannot + // stand in for the privacy cap, because it was never asking that question. + // + // ASCII deliberately: `escapedForLogLine` copies every printable scalar + // through unchanged, so for this input the on-disk span IS what the + // pre-escape cap produced and the bound can be stated tightly instead of + // through the escaper's worst-case expansion. + withTempLog { _ in + withDebugLogging(true) { + let stamp = String(UUID().uuidString.prefix(8)) + let chatMarker = Self.marker(for: .chatError, stamp) + let head = "head-\(stamp)" + // Comfortably past the privacy cap but INSIDE the size cap, so + // only the privacy cap can be what bounds the result. + let typed = head + String(repeating: "a", count: Self.userMessagePrivacyCap * 3) + #expect(typed.unicodeScalars.count < Self.userMessageScalarCap, + "the input reaches the SIZE cap — this input cannot discriminate") + BackgroundSyncLogger.logChatError(chatMarker, userMessage: typed) + + let chat = AppLogStore.read(channel: .chatError) + guard let span = Self.userMessageSpan(in: chat, after: chatMarker) else { + Issue.record("no `User message:` continuation line in: \(chat)") + return + } + // Non-vacuity: the head of the user's text survived, so this is + // measuring a cap rather than a writer that dropped the span. + #expect(span.contains(head), "the user span was dropped, not capped") + #expect(span.unicodeScalars.count <= Self.userMessagePrivacyCap, + "persisted span is \(span.unicodeScalars.count) scalars — the \(Self.userMessagePrivacyCap)-character privacy cap is gone") + } + } + } + + @Test("An escaped user span may legitimately exceed the pre-escape scalar cap") + func escapedUserSpanMayExceedTheScalarCap() { + // This is the input that makes the ORACLE, not the code, the thing under + // test. `"\r\n"` is ONE extended grapheme cluster carrying TWO control + // scalars, so a hundred of them pass `prefix(100)` as 200 scalars, sit + // inside the 400-scalar size cap untouched, and the escaper then rewrites + // every one of them as six characters. 1200 scalars on disk, from a + // completely correct implementation. + // + // An assertion of `<= 400` on this post-escape span — which is what two + // tests here used to make — therefore fails on CORRECT code. The bound + // the code actually guarantees is the pre-escape cap times the escaper's + // maximum expansion, and this test is what keeps that constant honest: + // loosen the ceiling below what escaping can produce and it goes red. + withTempLog { _ in + withDebugLogging(true) { + let stamp = String(UUID().uuidString.prefix(8)) + let chatMarker = Self.marker(for: .chatError, stamp) + let crlf = String(repeating: "\r\n", count: Self.userMessagePrivacyCap) + // Precondition, and the whole reason this input discriminates. + #expect(crlf.count == Self.userMessagePrivacyCap, + "the payload is not \(Self.userMessagePrivacyCap) grapheme clusters") + #expect(crlf.unicodeScalars.count == Self.userMessagePrivacyCap * 2) + BackgroundSyncLogger.logChatError(chatMarker, userMessage: crlf) + + let chat = AppLogStore.read(channel: .chatError) + guard let span = Self.userMessageSpan(in: chat, after: chatMarker) else { + Issue.record("no `User message:` continuation line in: \(chat)") + return + } + // Strictly ABOVE the pre-escape cap, and still within the ceiling. + #expect(span.unicodeScalars.count > Self.userMessageScalarCap, + "escaping did not expand the span — this input cannot discriminate") + #expect(span.unicodeScalars.count <= Self.persistedUserSpanCeiling, + "persisted span is \(span.unicodeScalars.count) scalars") + // Every backslash in it still introduces a COMPLETE escape — the + // expansion above came from escaping, not from a sliced sequence. + let truncated = Self.truncatedEscape(in: span) + #expect(truncated == nil, "a sliced escape survived: \(truncated ?? "")") + } + } + } + + @Test("logChatError caps the user's text BEFORE escaping it, never after") + func chatErrorCapsBeforeEscaping() { + // Escape-first-cap-second slices the escape sequence the escaper just + // generated: 99 `a`s plus a newline escapes to 99 `a`s plus a six-scalar + // sequence = 105 characters, and a 100-character cap then cuts INSIDE it + // and leaves a lone backslash behind. + // + // The INVARIANT, not the mechanism: whatever survives the cap, every + // backslash in the persisted span still introduces a COMPLETE escape + // sequence. A half-written one renders as something the user never typed, + // and — because the escaper is deliberately not injective — cannot be + // told apart from text they did. + withTempLog { _ in + withDebugLogging(true) { + let stamp = String(UUID().uuidString.prefix(8)) + let chatMarker = Self.marker(for: .chatError, stamp) + BackgroundSyncLogger.logChatError( + chatMarker, + userMessage: String(repeating: "a", count: 99) + "\n") + + let chat = AppLogStore.read(channel: .chatError) + guard let span = Self.userMessageSpan(in: chat, after: chatMarker) else { + Issue.record("no `User message:` continuation line in: \(chat)") + return + } + // Non-vacuity: the newline WAS escaped, so there is an escape + // sequence present for a mis-ordering to be able to slice. Without + // this the assertion below is satisfied by an empty span. + #expect(span.unicodeScalars.contains("\u{5C}"), + "nothing was escaped — this input cannot discriminate") + let truncated = Self.truncatedEscape(in: span) + #expect(truncated == nil, "a sliced escape survived: \(truncated ?? "")") + } + } + } + + @Test("One grapheme carrying thousands of combining marks cannot erase the log") + func chatErrorBoundsOneOversizedGrapheme() { + // `prefix(100)` counts extended grapheme CLUSTERS, and `"a"` followed by + // several thousand combining acutes is ONE cluster — so a Character cap + // passes it through whole (`MIS-IOS-013`: a SIZE question asked with a + // grapheme-level API). + // + // The consequence is not a long line. The entry then has no newline until + // its own terminal one, so `trimTail` — which keeps the last `keepBytes` + // and advances past the FIRST newline in that tail — is left with nothing + // to retain. Before `trimTail` gained its empty guard the rewrite replaced + // the whole log with an EMPTY file, erasing every channel at once; it now + // abandons the trim and leaves the log untrimmed instead. This test pins + // the OUTCOME: an unrelated channel's history survives. ⚠️ It does NOT + // demonstrate the store's guards — the façade's 400-scalar cap cuts this + // input long before it reaches either `maxEntryScalars` or the trim + // threshold, so what is exercised here is the FAÇADE bound alone. The + // store's two guards are covered separately. + withTempLog { _ in + withDebugLogging(true) { + // Small caps so the oversized-entry path is reachable without megabytes, + // exactly as `trimKeepsWholeEntries` does. + AppLogStore.maxBytesOverride.withLock { $0 = 4096 } + AppLogStore.keepBytesOverride.withLock { $0 = 1024 } + + let stamp = String(UUID().uuidString.prefix(8)) + let survivor = Self.marker(for: .sync, stamp) + let chatMarker = Self.marker(for: .chatError, stamp) + AppLogStore.append(survivor, channel: .sync) + + let oneCluster = "a" + String(repeating: "\u{0301}", count: 5000) + // Precondition, and the whole reason a Character cap is not a size + // bound: thousands of scalars, ONE Character. + #expect(oneCluster.count == 1, "the payload is not a single grapheme cluster") + #expect(oneCluster.unicodeScalars.count == 5001) + BackgroundSyncLogger.logChatError(chatMarker, userMessage: oneCluster) + + let contents = AppLogStore.read() + #expect(contents != "(no log)", "one oversized entry erased the whole log") + #expect(contents.contains(survivor), + "an unrelated channel's history was erased by one oversized entry") + + guard let span = Self.userMessageSpan(in: AppLogStore.read(channel: .chatError), + after: chatMarker) else { + Issue.record("no `User message:` continuation line in: \(contents)") + return + } + // 5001 scalars is what a Character-only cap lets through; the + // ceiling here is the pre-escape scalar cap times the escaper's + // maximum expansion, which is the bound the code guarantees for + // ANY input (combining acutes are not control scalars, so this + // particular span is not expanded at all). + #expect(span.unicodeScalars.count <= Self.persistedUserSpanCeiling, + "persisted span is \(span.unicodeScalars.count) scalars — unbounded") + } + } + } + + @Test("Channel tags are unique") + func channelTagsAreUnique() { + // Two channels sharing a tag would silently merge on every filtered read. + let tags = AppLogChannel.allCases.map(\.tag) + #expect(Set(tags).count == tags.count) + } + + @Test("Every AppLogChannel is classified always-on or debug-gated, exactly once") + func everyChannelIsClassifiedExactlyOnce() { + // The two sets above are hand-maintained; `AppLogChannel.allCases` is + // not. Deriving the oracle from `allCases` is what makes a SIXTEENTH + // channel visible: added with an ungated writer and no entry here, it + // used to slip past both gating tests (they only ever iterate their own + // hand-written marker lists) and ship un-gated in production. + let alwaysOn = Set(Self.alwaysOnWriters.map(\.channel)) + let gated = Set(Self.debugGatedWriters.map(\.channel)) + + #expect(alwaysOn.count == Self.alwaysOnWriters.count, "a channel is listed twice as always-on") + #expect(gated.count == Self.debugGatedWriters.count, "a channel is listed twice as debug-gated") + #expect(alwaysOn.isDisjoint(with: gated), "a channel is classified BOTH ways") + + let classified = alwaysOn.union(gated) + let all = Set(AppLogChannel.allCases) + #expect(classified == all, + "unclassified: \(all.subtracting(classified).map(\.tag).sorted())") + } + + // MARK: - The gating split (IOS-LOG-002) — both sides + + @Test("Always-on channels persist while debug logging is DISABLED") + func alwaysOnChannelsWriteWhenLocked() { + withTempLog { _ in + withDebugLogging(false) { + let stamp = UUID().uuidString.prefix(8) + for writer in Self.alwaysOnWriters { + writer.write(Self.marker(for: writer.channel, stamp)) + } + + // These five are deliberately always-on: a field failure has to + // leave a trace. Consolidation must not have gated them. + // + // Asserted per CHANNEL, not against the whole file: the whole-file + // oracle let one channel's entry satisfy another channel's + // assertion (`devicesync_X` contains `sync_X`), so gating + // `BackgroundSyncLogger.log` outright left this test green. + for writer in Self.alwaysOnWriters { + let marker = Self.marker(for: writer.channel, stamp) + #expect(AppLogStore.read(channel: writer.channel).contains(marker), + "\(writer.channel.tag) was silenced while it must stay always-on") + } + } + } + } + + @Test("Debug-gated channels write NOTHING while debug logging is DISABLED") + func gatedChannelsAreSilentWhenLocked() { + withTempLog { _ in + withDebugLogging(false) { + let stamp = UUID().uuidString.prefix(8) + for writer in Self.debugGatedWriters { + writer.write(Self.marker(for: writer.channel, stamp)) + } + + let contents = AppLogStore.read() + for writer in Self.debugGatedWriters { + let marker = Self.marker(for: writer.channel, stamp) + #expect(!contents.contains(marker), + "\(writer.channel.tag) persisted while debug logging was disabled") + } + } + } + } + + @Test("Debug-gated channels DO write once debug logging is enabled") + func gatedChannelsWriteWhenUnlocked() { + // The other side of the pair above. Without this, a writer that was + // accidentally hard-disabled would pass the silence test and look correct. + withTempLog { _ in + withDebugLogging(true) { + let stamp = UUID().uuidString.prefix(8) + for writer in Self.debugGatedWriters { + writer.write(Self.marker(for: writer.channel, stamp)) + } + + // Per channel, for the same reason as the always-on side: with a + // whole-file `contains`, `backfillai_X` satisfied the assertion + // for `ai_X`, so deleting `logAIProcessing`'s append kept this + // test green. + for writer in Self.debugGatedWriters { + let marker = Self.marker(for: writer.channel, stamp) + #expect(AppLogStore.read(channel: writer.channel).contains(marker), + "\(writer.channel.tag) did not persist while debug logging was enabled") + } + } + } + } + + // MARK: - The gate covers the console too (global CLAUDE.md rule 12) + + @Test("Every debug-gated writer gates its print as well as its file write") + func gatedWritersGateTheirPrintToo() throws { + // Rule 12 is "a no-op in production", not "writes no file in production". + // Every behavioural test in this file reads the FILE, so moving a + // `print` above its `guard` — leaking to the console (and to Console.app + // on a shipped device) for a channel that is supposed to be silent — + // is invisible to all of them. This reads the source instead, in the + // style of `RenderPathLogSinkTests`. + // + // ⚠️ Honest statement of the bar this clears. `gateViolation` is a + // LEXICAL scan for `print(` / `NSLog(` / `os_log(` inside one function + // body, compared by source offset against the guard's own text. It + // catches a sink moved above its guard, and a gated writer that has no + // guard. It does NOT catch an INDIRECT sink: put the `print` in a helper + // and call `emitPush(message)` above the guard and this reports clean, + // because no sink token appears in the scanned body. Real dataflow + // analysis is not attempted and this test does not claim it. + let source = try Self.projectFile("TabMail/Services/BackgroundSyncLogger.swift") + + var scanned = 0 + var withSink = 0 + for writer in Self.debugGatedWriters { + guard let name = writer.backgroundSyncLoggerFunction else { + Issue.record("\(writer.channel.tag) has no BackgroundSyncLogger entry point to scan") + continue + } + guard let body = Self.functionBody(of: name, in: source) else { + Issue.record("could not find the body of BackgroundSyncLogger.\(name)") + continue + } + scanned += 1 + // Non-vacuity: we found the RIGHT body, not an empty range that + // trivially satisfies "no print before the guard". + #expect(body.contains("AppLogStore.append("), + "\(name)'s scanned body does not write to AppLogStore — wrong range?") + if Self.firstConsoleSink(in: body) != nil { withSink += 1 } + let violation = Self.gateViolation(in: body) + #expect(violation == nil, "\(name): \(violation ?? "")") + } + #expect(scanned == Self.debugGatedWriters.count) + // If NO gated writer had a console sink at all, the check above would be + // satisfied by absence and would keep passing after every gate was + // removed. + #expect(withSink > 0, "no debug-gated writer writes to the console — the scan proves nothing") + } + + @Test("The print/guard scanner detects the violations it claims to") + func gateScannerIsNotVacuous() { + // A positive control for the scanner used above: it must flag both + // failure shapes, and must not flag the compliant one. + let compliant = """ + guard DebugModeManager.isLoggingEnabled() else { return } + print("[X] \\(message)") + AppLogStore.append(message, channel: .push) + """ + let printBeforeGuard = """ + print("[X] \\(message)") + guard DebugModeManager.isLoggingEnabled() else { return } + AppLogStore.append(message, channel: .push) + """ + let noGate = """ + print("[X] \\(message)") + AppLogStore.append(message, channel: .push) + """ + // Rule 12 names three sinks, so the scanner must flag all three — a + // logger that reached for NSLog or os_log instead of print would + // otherwise pass while writing to the unified log on a shipped device, + // which is a LOUDER leak than the bare print the scanner started with. + let nsLogBeforeGuard = """ + NSLog("[X] %@", message) + guard DebugModeManager.isLoggingEnabled() else { return } + AppLogStore.append(message, channel: .push) + """ + let osLogBeforeGuard = """ + os_log("[X] %{public}@", message) + guard DebugModeManager.isLoggingEnabled() else { return } + AppLogStore.append(message, channel: .push) + """ + // The gated forms of the same two must NOT be flagged, or the scanner + // would be rejecting compliant code rather than discriminating. + let nsLogAfterGuard = """ + guard DebugModeManager.isLoggingEnabled() else { return } + NSLog("[X] %@", message) + AppLogStore.append(message, channel: .push) + """ + // The documented blind spot, asserted rather than described: an + // indirect sink reached through a helper is NOT detected. This is the + // scanner's limit, not a bug to fix here — pinning it keeps a future + // reader from mistaking a clean scan for a proof. + let indirectSinkBeforeGuard = """ + emitPush(message) + guard DebugModeManager.isLoggingEnabled() else { return } + AppLogStore.append(message, channel: .push) + """ + #expect(AppLogStoreTests.gateViolation(in: compliant) == nil) + #expect(AppLogStoreTests.gateViolation(in: printBeforeGuard) != nil) + #expect(AppLogStoreTests.gateViolation(in: noGate) != nil) + #expect(AppLogStoreTests.gateViolation(in: nsLogBeforeGuard) != nil) + #expect(AppLogStoreTests.gateViolation(in: osLogBeforeGuard) != nil) + #expect(AppLogStoreTests.gateViolation(in: nsLogAfterGuard) == nil) + #expect(AppLogStoreTests.gateViolation(in: indirectSinkBeforeGuard) == nil, + "lexical scan: an indirect sink is a KNOWN blind spot, documented above") + // And the primitive it is built on actually finds tokens. + #expect(AppLogStoreTests.firstConsoleSink(in: compliant)?.token == "print(") + #expect(AppLogStoreTests.firstConsoleSink(in: nsLogAfterGuard)?.token == "NSLog(") + #expect(AppLogStoreTests.firstConsoleSink(in: "no sinks here") == nil) + } + + // MARK: - Clearing + + @Test("clear(channel:) drops one channel and preserves the rest") + func clearOneChannelPreservesOthers() { + withTempLog { _ in + withDebugLogging(true) { + AppLogStore.append("stuck_line", channel: .stuckDiag) + AppLogStore.append("sync_line", channel: .sync) + AppLogStore.append("stuck_line_two", channel: .stuckDiag) + + AppLogStore.clear(channel: .stuckDiag) + + let contents = AppLogStore.read() + // StuckMessageDiagnostics.run clears its channel before each + // scan; with one file that must not take everything else with it. + #expect(!contents.contains("stuck_line")) + #expect(!contents.contains("stuck_line_two")) + #expect(contents.contains("sync_line")) + } + } + } + + @Test("clear(channel:) drops a multi-line entry whole") + func clearOneChannelDropsContinuationLines() { + withTempLog { _ in + withDebugLogging(true) { + BackgroundSyncLogger.logChatError("tool failed", userMessage: "secret user text") + AppLogStore.append("sync_line", channel: .sync) + + AppLogStore.clear(channel: .chatError) + + let contents = AppLogStore.read() + #expect(!contents.contains("tool failed")) + #expect(!contents.contains("secret user text")) + #expect(contents.contains("sync_line")) + } + } + } + + @Test("clear(channel:) removes a LEADING orphan for any channel") + func clearRemovesLeadingOrphanForAnyChannel() throws { + // A tail-trim that cuts between a `logChatError` entry's two lines leaves + // the file starting with ` User message: …` and no entry above it. + // `read(channel:)` drops that orphan for EVERY channel (its filter seeds + // `including = false`), so no export shows it — and `clear(channel:)` + // seeded `dropping = false`, so no clear removed it either. Unreadable + // AND unclearable is how a fragment of user text outlives every clear the + // UI offers short of "Clear All". + // + // EVERY channel, derived from `allCases` rather than from a hand-picked + // pair, because the claim in the name is "any channel" and a sample cannot + // support it. Two channels — `.chatError` (where the orphan's text came + // from) and `.push` (absent from the file entirely) — were enough to catch + // a `dropping` seed that special-cased the orphan's own channel, and NOT + // enough to catch one that special-cases any channel they happen to miss: + // seeding `dropping = channel != .auth` left that pair green while a + // fragment of user text survived `clear(channel: .auth)`. Deriving the + // oracle from `allCases` is also what makes a SIXTEENTH channel covered + // the day it is added, with no edit here. + for channel in AppLogChannel.allCases { + // The surviving entry has to sit on a channel OTHER than the one being + // cleared. With a fixed `.sync` survivor the `.sync` iteration asserts + // that a LEGITIMATE removal did not happen, which is a bug in the + // fixture rather than in `clear(channel:)`. + let survivorChannel: AppLogChannel = (channel == .sync) ? .push : .sync + try withTempLog { url in + // The timestamp is generated rather than hardcoded (no fixed dates + // in tests) — only its SHAPE matters to `entryTag`. + let orphaned = """ + User message: secret user text + [\(Date().iso8601String())] [\(survivorChannel.tag)] survivor + + """ + try Data(orphaned.utf8).write(to: url) + + // Precondition: no channel can read it back (so "it's gone from + // the export" is not what this test is measuring). + #expect(!AppLogStore.read(channel: .chatError).contains("secret user text")) + #expect(!AppLogStore.read(channel: survivorChannel).contains("secret user text")) + + // Clearing a channel the orphan does not belong to still removes + // it, and leaves the real entries alone. + AppLogStore.clear(channel: channel) + #expect(!AppLogStore.read().contains("secret user text"), + "clear(channel: .\(channel.tag)) left the orphan behind") + #expect(AppLogStore.read().contains("survivor"), + "clear(channel: .\(channel.tag)) took an unrelated entry with it") + } + } + } + + @Test("Appending after clear(channel:) starts a new line") + func appendAfterChannelClearStartsANewLine() { + // The dropped entry must not take the file's trailing newline with it. + // If it does, the next append lands on the tail of the surviving entry + // and BOTH become one unparseable line — the surviving entry's text is + // corrupted and the new entry can never be filtered back out. + withTempLog { _ in + withDebugLogging(true) { + AppLogStore.append("survivor", channel: .sync) + AppLogStore.append("doomed", channel: .stuckDiag) // last entry in the file + AppLogStore.clear(channel: .stuckDiag) + AppLogStore.append("after_clear", channel: .sync) + + let contents = AppLogStore.read() + let lines = contents.split(separator: "\n", omittingEmptySubsequences: true) + // Two appends that survived ⇒ two lines. Assert the COUNT, not the + // absence of a concatenated marker: the merged line reads + // `…survivor[] [SYNC] after_clear`, so the two markers + // are never adjacent and a `contains("survivorafter_clear")` check + // passes even when the entries have merged. It also still parses as + // a SYNC entry, because `entryTag` only reads the line's head — so + // neither of those is a usable oracle here. + // + // Counted over THIS test's own markers rather than over the whole + // file: an always-on writer escaping an EARLIER test (a stray + // `BackgroundSyncLogger.log` from a task that outlived it) lands in + // the redirected file and would otherwise make this a flake. A + // merged line contains BOTH markers, so it still counts as one and + // the assertion keeps its full discriminating power. + let mine = lines.filter { $0.contains("survivor") || $0.contains("after_clear") } + #expect(mine.count == 2, "entries merged onto one line: \(contents)") + #expect(lines.filter { $0.hasSuffix("survivor") }.count == 1) + #expect(lines.filter { $0.hasSuffix("after_clear") }.count == 1) + // And the new entry is still separable by channel. + #expect(AppLogStore.read(channel: .sync).contains("after_clear")) + } + } + } + + @Test("A filtered read ends with exactly one newline") + func filteredReadHasNoBlankTail() { + let text = "[2026-08-25T10:00:00Z] [SYNC] only\n" + #expect(AppLogStore.filter(text, keepingChannel: .sync) == text) + } + + @Test("clear() empties every channel") + func clearAllEmptiesFile() { + withTempLog { _ in + withDebugLogging(true) { + AppLogStore.append("a", channel: .sync) + AppLogStore.append("b", channel: .push) + AppLogStore.clear() + #expect(AppLogStore.read() == "(no log)") + } + } + } + + @Test("Reading a MISSING log returns a placeholder, never a crash") + func readPlaceholdersForAMissingFile() { + // Named for the case it actually exercises. It used to say "an empty or + // missing log" while asserting only that the file is ABSENT — the + // empty-file case is a different code path and belongs to the test below, + // which does cover it. The overclaim was in the name, not in the coverage. + withTempLog { url in + #expect(!FileManager.default.fileExists(atPath: url.path), + "this is the MISSING-file case; the empty-file case is a separate test") + #expect(AppLogStore.read() == "(no log)") + #expect(AppLogStore.read(channel: .sync) == "(no SYNC log)") + #expect(AppLogStore.read(channel: .stuckDiag).contains("run the scan")) + } + } + + @Test("Reading an EXISTING but empty log returns a placeholder too") + func readPlaceholdersForAnExistingEmptyFile() throws { + // Distinct code path from the test above: there the file is absent and + // `String(contentsOf:)` throws, so `read`/`read(channel:)` never reach + // their filters. Here the read succeeds and returns "" — which is the + // state the file is actually left in by `clear()`, and by a first + // `append` that creates the file before writing. + try withTempLog { url in + try Data().write(to: url) + #expect(FileManager.default.fileExists(atPath: url.path)) + let size = (try? FileManager.default.attributesOfItem(atPath: url.path))?[.size] as? Int + #expect(size == 0, "precondition: the file exists and is empty") + + #expect(AppLogStore.read() == "(no log)") + #expect(AppLogStore.read(channel: .sync) == "(no SYNC log)") + #expect(AppLogStore.read(channel: .stuckDiag).contains("run the scan")) + } + } + + // MARK: - Torn writes + + @Test("An append onto a torn tail starts a new line instead of merging") + func appendAfterATornWriteStartsANewLine() throws { + // Every entry ends with `\n`, so a file that does not is one whose last + // write was cut short — the process died between the write starting and + // the bytes landing. The INVARIANT: an append onto a torn tail still + // yields two independently parseable, independently FILTERABLE entries. + // Merged, the second entry is attributed to the FIRST one's channel and + // `clear(channel:)` on that channel deletes the survivor with it. + // + // New exposure, not a pre-existing bug: at v1.7.14 `AuthDiagnostics` and + // `DeviceSyncLogger` rewrote their whole file with + // `write(to:atomically:true)` — an atomic replace cannot leave a partial + // line — and every other channel appended to a file only IT wrote. All + // fifteen now append in place to ONE shared file. + try withTempLog { url in + try withDebugLogging(true) { + let stamp = UUID().uuidString.prefix(8) + let tornMarker = Self.marker(for: .sync, stamp) + let nextMarker = Self.marker(for: .push, stamp) + // Deliberately NO trailing newline: this IS the torn tail. The + // timestamp is generated rather than hardcoded (no fixed dates in + // tests) — only its SHAPE matters to `entryTag`. + let torn = "[\(Date().iso8601String())] [SYNC] \(tornMarker)" + try Data(torn.utf8).write(to: url) + + AppLogStore.append(nextMarker, channel: .push) + + let contents = AppLogStore.read() + let lines = contents.split(separator: "\n", omittingEmptySubsequences: true) + // Counted over THIS test's own markers, never the whole file: an + // always-on writer escaping an EARLIER test lands in the + // redirected file. A merged line contains BOTH markers and still + // counts as one, so the oracle keeps its full discriminating power. + let mine = lines.filter { $0.contains(tornMarker) || $0.contains(nextMarker) } + #expect(mine.count == 2, "the torn tail swallowed the next entry: \(contents)") + guard mine.count == 2 else { return } + + // Separability is the half that actually hurts: a merged line + // parses as SYNC, so the PUSH entry can never be filtered back out. + #expect(AppLogStore.read(channel: .sync).contains(tornMarker)) + #expect(AppLogStore.read(channel: .push).contains(nextMarker)) + } + } + } + + @Test("Consecutive appends leave no blank line between entries") + func consecutiveAppendsDoNotInsertABlankLine() { + // The torn-tail repair writes its newline only when the file does NOT + // already end with one. Writing it whenever `size > 0` instead separates + // EVERY pair of entries with a blank line — and every other test in this + // file splits with `omittingEmptySubsequences: true`, so all of them stay + // green while the exported log doubles in height and each blank becomes an + // unattributed continuation line that `read(channel:)` hands to whichever + // entry precedes it. + withTempLog { _ in + withDebugLogging(true) { + let stamp = String(UUID().uuidString.prefix(8)) + let first = Self.marker(for: .sync, stamp) + let second = Self.marker(for: .push, stamp) + AppLogStore.append(first, channel: .sync) + AppLogStore.append(second, channel: .push) + + let contents = AppLogStore.read() + // Empty subsequences KEPT: the blank line IS the thing being + // measured, so dropping it is exactly the blindness that let this + // through everywhere else. + let lines = contents.split(separator: "\n", omittingEmptySubsequences: false) + guard let firstIndex = lines.firstIndex(where: { $0.contains(first) }), + let secondIndex = lines.firstIndex(where: { $0.contains(second) }) else { + Issue.record("this test's markers are missing from the log: \(contents)") + return + } + #expect(firstIndex < secondIndex, "the entries landed out of call order") + guard firstIndex < secondIndex else { return } + + // Scoped to this test's own span rather than to the whole file: an + // always-on writer escaping an EARLIER test lands in the redirected + // file, and its entry between these two is a real line, not a blank. + #expect(lines[firstIndex...secondIndex].allSatisfy { !$0.isEmpty }, + "a blank line was inserted between consecutive entries: \(contents)") + } + } + } + + @Test("One invalid UTF-8 byte leaves the log readable AND clearable") + func invalidUTF8ByteDoesNotHideTheWholeLog() throws { + // A torn write can split a multibyte UTF-8 scalar. The INVARIANT: one bad + // byte costs that byte, not the file — every other entry stays readable + // and filterable, and `clear(channel:)` still removes the channel it + // names. A throwing decode made `read()` return the MISSING-file + // placeholder for the ENTIRE file and turned `clear(channel:)` into a + // silent no-op, so a single byte destroyed the whole diagnostic artifact + // and simultaneously made it unclearable. + try withTempLog { url in + try withDebugLogging(true) { + let stamp = UUID().uuidString.prefix(8) + let syncMarker = Self.marker(for: .sync, stamp) + let pushMarker = Self.marker(for: .push, stamp) + let timestamp = Date().iso8601String() // generated, never hardcoded + + var bytes = Data("[\(timestamp)] [SYNC] \(syncMarker) ".utf8) + bytes.append(0xC3) // a lone UTF-8 lead byte — a scalar cut in half + bytes.append(contentsOf: Array("\n[\(timestamp)] [PUSH] \(pushMarker)\n".utf8)) + try bytes.write(to: url) + + let contents = AppLogStore.read() + #expect(contents != "(no log)", "one torn byte hid the ENTIRE log") + #expect(contents.contains(syncMarker), "the SYNC entry beside the bad byte was lost") + #expect(contents.contains(pushMarker), "an untouched later entry was lost") + #expect(AppLogStore.read(channel: .push).contains(pushMarker), + "the channel filter cannot reach past the bad byte") + + // The half that fails SILENTLY: an unreadable file makes + // `clear(channel:)` a no-op that reports nothing. + AppLogStore.clear(channel: .sync) + let after = AppLogStore.read() + #expect(!after.contains(syncMarker), "clear(channel:) silently did nothing") + #expect(after.contains(pushMarker), "clear(channel:) took another channel with it") + } + } + } + + // MARK: - The serial I/O queue + + @Test("Concurrent writers across channels produce whole, parseable entries") + func concurrentWritersNeverInterleavePartialEntries() { + // `AppLogStore`'s own header calls one serial queue for one file + // "load-bearing rather than merely tidy": `DeviceSyncLogger` used to own a + // SECOND queue and `AuthDiagnostics` wrote synchronously on the caller's + // thread, including from `TabMailApp.init` on MainActor. + // + // Nothing pinned that claim. Every other test in this file writes from a + // single thread, so giving `ioQueue` `attributes: .concurrent` leaves all + // of them green while two `seekToEnd`-then-write pairs race for the same + // offset AND `read`'s own `ioQueue.sync` stops being a drain — on a + // concurrent queue it runs one block, it does not wait for the rest. + // + // The INVARIANT, not the mechanism: however many threads call `append`, + // every physical line in the file parses as an entry, and every write this + // test made is present on exactly one line. + withTempLog { _ in + withDebugLogging(true) { + let stamp = String(UUID().uuidString.prefix(8)) + let channels = AppLogChannel.allCases + let writes = 300 + + DispatchQueue.concurrentPerform(iterations: writes) { iteration in + let channel = channels[iteration % channels.count] + AppLogStore.append("\(Self.marker(for: channel, stamp))-\(iteration)", + channel: channel) + } + + // `read()` drains `ioQueue` before decoding, so every enqueued + // write is on disk by the time this returns. + let contents = AppLogStore.read() + let lines = contents.split(separator: "\n", omittingEmptySubsequences: true) + + // Both oracles are scoped to THIS test's own stamp, never to the + // whole file. An always-on writer escaping an EARLIER test lands in + // the redirected file, and `logChatError`'s deliberate two-line + // entry would contribute a continuation line that legitimately does + // not parse — a whole-file oracle would read that as a torn write. + let mine = lines.filter { $0.contains(stamp) } + + // 1. No torn or merged line among them. A write landing inside + // another entry leaves a line with no valid `[ts] [TAG] ` head, + // which is precisely what `entryTag` refuses. + for line in mine { + #expect(AppLogStore.entryTag(of: line) != nil, + "a concurrent write left an unparseable line: \(line)") + } + + // 2. Every write is present, on its own line. Two entries merged + // onto one physical line still count as ONE, so the count keeps + // its full discriminating power in both directions. + #expect(mine.count == writes, + "expected \(writes) entries from this test, found \(mine.count)") + } + } + } + + // MARK: - Trim + + @Test("The production byte caps are 32 MB, trimmed back to 16 MB") + func productionByteCapsArePinned() { + // The cap has to hold FIFTEEN channels now, not the one + // `background_sync.log` held at 16 MB — and the trim is whole-file with + // no per-channel reservation, so the ceiling is the only thing standing + // between a chatty channel and a quiet channel's evicted history. + #expect(AppLogStore.maxBytes == 32 * 1024 * 1024) + #expect(AppLogStore.keepBytes == 16 * 1024 * 1024) + // The 2:1 ratio bounds how often the whole-file atomic rewrite runs. + #expect(AppLogStore.maxBytes == AppLogStore.keepBytes * 2) + } + + @Test("Tail trim keeps the newest entries and never leaves a partial physical LINE") + func trimKeepsWholeEntries() { + withTempLog { _ in + withDebugLogging(true) { + AppLogStore.maxBytesOverride.withLock { $0 = 4096 } + AppLogStore.keepBytesOverride.withLock { $0 = 1024 } + + for index in 0..<400 { + AppLogStore.append("entry_\(index)_\(String(repeating: "x", count: 40))", channel: .sync) + } + + let contents = AppLogStore.read() + // The newest entry always survives. + #expect(contents.contains("entry_399_")) + // The oldest is gone — the trim actually ran, so this test is + // not silently measuring an untrimmed file. + #expect(!contents.contains("entry_0_")) + // Every surviving line is a complete physical LINE: the trim + // advances past the first partial line rather than slicing one in + // half. The oracle is "parses as SOME channel", not "== SYNC": a + // partial line has no valid `[ts] [TAG] ` head and returns nil, + // which is exactly the defect being guarded, while an always-on + // entry that escaped an earlier test into the redirected file + // parses fine and must not flake this. + // + // ⚠️ LINE, not logical ENTRY — the distinction is real and the + // stronger claim would be false. `logChatError` deliberately emits + // a TWO-LINE entry, and a cut that lands inside its first line + // leaves the ` User message: …` continuation as a LEADING ORPHAN: + // a complete physical line belonging to no entry. That is a known, + // accepted consequence of a whole-file tail trim, not a defect — + // `filter(_:keepingChannel:)` seeds `including = false` so no + // export shows the orphan, and `clear(channel:)` removes it for + // whichever channel is cleared (pinned by + // `clearRemovesLeadingOrphanForAnyChannel`). + for line in contents.split(separator: "\n", omittingEmptySubsequences: true) { + #expect(AppLogStore.entryTag(of: line) != nil, + "trim left a partial line: \(line)") + } + } + } + } + + @Test("One oversized newline-free entry leaves the log untrimmed instead of ERASING it") + func oneOversizedEntryNeverEmptiesTheLog() { + // `trimTail` keeps the last `keepBytes` and then advances past the FIRST + // newline in that tail so it never leaves half a line behind. When the + // retained tail's only newline is its own TERMINAL byte — which is what + // one entry longer than `keepBytes` produces — that leaves NOTHING. + // BEFORE the empty guard, the atomic rewrite then replaced the whole log + // with an EMPTY file: every channel's history gone at once, from a + // routine size trim. The guard makes that write not happen at all, so + // the log stays ABOVE its cap rather than being trimmed — deliberately, + // because keeping an untrimmed file is strictly better than deleting it, + // and the next bounded append lets the following trim succeed. The test + // name says "untrimmed" for exactly that reason. + // + // The INVARIANT: a trim only ever removes the OLDEST entries. It never + // turns a non-empty log into an empty one, whatever the shape of what + // was written. Nothing here goes through `logChatError` — this is an + // ordinary façade that bounds nothing of its own, so the entry arrives + // at the store carrying only the store's bound. ⚠️ The trigger is driven + // by the 4 KiB/1 KiB test overrides, NOT reachable at production's + // 32/16 MiB: `maxEntryScalars` caps one entry near 256 KB, far under the + // 16 MiB retained tail. This is a defence-in-depth test of the guard, + // not a reproduction of a live production path. + withTempLog { url in + withDebugLogging(true) { + AppLogStore.maxBytesOverride.withLock { $0 = 4096 } + AppLogStore.keepBytesOverride.withLock { $0 = 1024 } + + let stamp = String(UUID().uuidString.prefix(8)) + let survivor = Self.marker(for: .sync, stamp) + AppLogStore.append(survivor, channel: .sync) + AppLogStore.append(String(repeating: "x", count: 8 * 1024), channel: .inbox) + + let contents = AppLogStore.read() + #expect(contents != "(no log)", "the trim erased the whole log") + #expect(contents.contains(survivor), + "an unrelated channel's history was erased by one oversized entry") + // Non-vacuity: the file really did pass `maxBytes`, so a trim was + // attempted rather than skipped for being under the cap. + let size = (try? FileManager.default.attributesOfItem(atPath: url.path))?[.size] as? Int + #expect((size ?? 0) > 4096, + "the log is \(size ?? -1) bytes — it never reached maxBytes") + } + } + } + + @Test("The store bounds an entry from a writer that bounds nothing itself") + func appendBoundsAnUnboundedWriter() { + // `logChatError` is the only façade that bounds its own spans. The other + // fourteen hand `AppLogStore.append` whatever they were given, so the + // SIZE bound belongs at the STORE boundary, where it covers every writer + // rather than only the one that bounds itself. ⚠️ This is defence in + // depth, not a live production path: with the bound in place no façade + // can reach production's 16 MiB retained tail, since one entry now caps + // near 256 KB. The bound is what MAKES that true — it is not evidence + // that an unbounded façade is currently producing oversized entries. + // + // Deliberately redundant with `logChatError`'s own cap and with + // `trimTail`'s refusal to write an empty file: three independent things + // have to fail before one oversized entry can cost the log. + withTempLog { _ in + withDebugLogging(true) { + let stamp = String(UUID().uuidString.prefix(8)) + let head = "head-\(stamp)" + let tail = "tail-\(stamp)" + // `tail` sits past the ceiling, so it can only reach the file if + // no bound ran at all. + BackgroundSyncLogger.log( + head + String(repeating: "a", count: AppLogStore.maxEntryScalars) + tail) + + let sync = AppLogStore.read(channel: .sync) + // Non-vacuity: the head survived, so this measures a bound rather + // than a writer that dropped the entry. + #expect(sync.contains(head), "the entry was dropped, not bounded") + #expect(!sync.contains(tail), + "the whole unbounded entry was persisted — the store bound is gone") + + guard let line = sync.split(separator: "\n", omittingEmptySubsequences: false) + .first(where: { $0.contains(head) }) else { + Issue.record("the entry is missing entirely from: \(sync.prefix(200))") + return + } + // The only part of the physical line the message bound does not + // cover is the `[] [] ` head the store writes itself. + let entryHead = "[\(Date().iso8601String())] [\(AppLogChannel.sync.tag)] " + #expect(line.unicodeScalars.count + <= AppLogStore.maxEntryScalars + entryHead.unicodeScalars.count, + "persisted entry is \(line.unicodeScalars.count) scalars") + + // ⚠️ The façade above cannot LOCATE the bound: an identical bound + // living only in `BackgroundSyncLogger.log` would satisfy every + // assertion so far, while `DeviceSyncLogger`, `AuthDiagnostics` + // and the other twelve went on persisting unbounded entries. + // Driving `AppLogStore.append` directly is what distinguishes a + // STORE-boundary bound from a façade-only one, and `appendRaw` is + // private, so this is the same door all fifteen writers use. + let direct = "direct-\(stamp)" + let directTail = "directtail-\(stamp)" + AppLogStore.append( + direct + String(repeating: "b", count: AppLogStore.maxEntryScalars) + directTail, + channel: .push) + + let push = AppLogStore.read(channel: .push) + #expect(push.contains(direct), "the direct entry was dropped, not bounded") + #expect(!push.contains(directTail), + "the bound is not at the store boundary — it lives in the façade") + } + } + } +} + +// MARK: - Source scanning for `gatedWritersGateTheirPrintToo` + +extension AppLogStoreTests { + + static func projectFile(_ relativePath: String) throws -> String { + let root = URL(fileURLWithPath: #filePath) + .deletingLastPathComponent() // Services + .deletingLastPathComponent() // TabMailTests + .deletingLastPathComponent() // repository root + return try String(contentsOf: root.appendingPathComponent(relativePath), encoding: .utf8) + } + + /// Scalar offset of `token` in `text`, or `nil`. Scalar-wise, per + /// `MIS-IOS-013`: a grapheme-level `range(of:)` answers a different question + /// than "where do these source characters appear". + static func firstIndex(ofToken token: String, in text: String) -> Int? { + let haystack = Array(text.unicodeScalars) + let needle = Array(token.unicodeScalars) + guard !needle.isEmpty, haystack.count >= needle.count else { return nil } + for start in 0...(haystack.count - needle.count) { + var matched = true + for offset in 0..(` in `source` — the text between its + /// opening brace and the matching close — or `nil` when the function is not + /// found or its braces do not balance. + /// + /// Deliberately simple: `BackgroundSyncLogger` is a flat list of small + /// static functions whose signatures contain no braces and whose bodies + /// contain no brace inside a string literal. The caller asserts each + /// recovered body contains `AppLogStore.append(`, which is what rules out a + /// mis-parsed range rather than trusting the parser. + static func functionBody(of name: String, in source: String) -> String? { + let scalars = Array(source.unicodeScalars) + guard let signature = firstIndex(ofToken: "static func \(name)(", in: source) else { return nil } + guard var index = scalars[signature...].firstIndex(of: "{") else { return nil } + var depth = 0 + var body = String.UnicodeScalarView() + while index < scalars.count { + let scalar = scalars[index] + if scalar == "{" { + depth += 1 + if depth == 1 { index += 1; continue } + } else if scalar == "}" { + depth -= 1 + if depth == 0 { return String(body) } + } + body.append(scalar) + index += 1 + } + return nil + } + + /// The console sinks global `CLAUDE.md` rule 12 names. All three, not just + /// `print`: the rule is "a no-op in production", and `NSLog`/`os_log` reach + /// the unified log on a shipped device where a bare `print` reaches nobody. + static let consoleSinkTokens = ["print(", "NSLog(", "os_log("] + + /// The earliest console sink in `body`, as (scalar offset, token), or `nil`. + static func firstConsoleSink(in body: String) -> (offset: Int, token: String)? { + consoleSinkTokens + .compactMap { token in firstIndex(ofToken: token, in: body).map { (offset: $0, token: token) } } + .min { $0.offset < $1.offset } + } + + /// Why `body` violates "the debug gate covers the console sink too", or + /// `nil`. + /// + /// ⚠️ This is a LEXICAL scan of one function body, and that is all it is. It + /// answers "does the text `print(` / `NSLog(` / `os_log(` appear before the + /// text of the guard, inside this body". It does NOT do dataflow: a body + /// that calls a helper which prints — `emitPush(message)` above the guard, + /// with the `print` inside `emitPush` — contains no sink token and is + /// reported clean. Nothing here rules that out; a reviewer reading a new + /// logger function does. What the scan does buy is the cheap, common + /// regression: someone moves an existing `print` above its guard, or adds a + /// gated writer with no guard at all. + static func gateViolation(in body: String) -> String? { + let gate = firstIndex(ofToken: "guard DebugModeManager.isLoggingEnabled()", in: body) + let sink = firstConsoleSink(in: body) + guard let gate else { return "no DebugModeManager.isLoggingEnabled() guard" } + guard let sink else { return nil } + return sink.offset < gate ? "\(sink.token) appears before the debug gate" : nil + } + + /// The text after ` User message: ` on the continuation line that follows + /// the entry whose head contains `entryMarker`, or `nil`. + /// + /// Anchored on the CALLER'S OWN entry rather than on the first such line in + /// the text: `logChatError` is always-on, so a task escaping an earlier test + /// can land another CHAT entry — with its own `User message:` line — in the + /// same redirected file. + static func userMessageSpan(in text: String, after entryMarker: String) -> String? { + let lines = text.split(separator: "\n", omittingEmptySubsequences: false) + guard let head = lines.firstIndex(where: { $0.contains(entryMarker) }), + head + 1 < lines.count else { return nil } + let prefix = Array(" User message: ".unicodeScalars) + let scalars = Array(lines[head + 1].unicodeScalars) + guard scalars.count >= prefix.count, Array(scalars[0.. String? { + let scalars = Array(span.unicodeScalars) + let hexDigits = Set("0123456789abcdefABCDEF".unicodeScalars) + var index = 0 + while index < scalars.count { + guard scalars[index] == "\u{5C}" else { + index += 1 + continue + } + guard index + 5 < scalars.count else { + return "backslash at \(index) with only \(scalars.count - index - 1) scalars after it" + } + guard scalars[index + 1] == "u" else { + return "backslash at \(index) is not followed by `u`" + } + for offset in 2...5 where !hexDigits.contains(scalars[index + offset]) { + return "backslash at \(index) is followed by a non-hex digit" + } + index += 6 + } + return nil + } +} diff --git a/TabMailTests/Services/AuthDiagnosticsTests.swift b/TabMailTests/Services/AuthDiagnosticsTests.swift index 371a257a..6a1cbc1f 100644 --- a/TabMailTests/Services/AuthDiagnosticsTests.swift +++ b/TabMailTests/Services/AuthDiagnosticsTests.swift @@ -6,42 +6,98 @@ import Testing import Foundation @testable import TabMail -@Suite("AuthDiagnostics", .serialized) +/// `.processGlobalState` as well as `.serialized`: these tests rebind +/// `AppLogStore.fileURLOverride`, which is process-global, and `.serialized` +/// orders tests only WITHIN this suite. `AppLogStoreTests` and +/// `BackgroundSyncLoggerTests` mutate the same seam from their own suites — so +/// without the shared critical section another suite's `_resetForTesting` can +/// point `AuthDiagnostics.log` at the real Application Support log mid-test. +@Suite("AuthDiagnostics", .serialized, .processGlobalState) struct AuthDiagnosticsTests { - @Test("Log and readLog round-trip") + /// Point the shared app log at a fresh temp file for one test. + private func withTempLog(_ body: () throws -> T) rethrows -> T { + let url = FileManager.default.temporaryDirectory + .appendingPathComponent("authdiag_\(UUID().uuidString).log") + AppLogStore.fileURLOverride.withLock { $0 = url } + defer { + AppLogStore._resetForTesting() + try? FileManager.default.removeItem(at: url) + } + return try body() + } + + @Test("Log and read round-trip") func logAndRead() { - let marker = "diag_test_\(UUID().uuidString.prefix(8))" - AuthDiagnostics.log(marker) - // Read immediately — the entry we just wrote must be present - let log = AuthDiagnostics.readLog() - #expect(log.contains(marker)) + withTempLog { + let marker = "diag_test_\(UUID().uuidString.prefix(8))" + AuthDiagnostics.log(marker) + #expect(AppLogStore.read(channel: .auth).contains(marker)) + } } - @Test("Log entries have timestamps") + @Test("Log entries carry a timestamp and the AUTH channel tag") func logTimestamps() { - let marker = "ts_test_\(UUID().uuidString.prefix(8))" - AuthDiagnostics.log(marker) - let log = AuthDiagnostics.readLog() - // ISO8601 timestamps look like [2024-03-15T...] - #expect(log.contains("[")) - #expect(log.contains("]")) - #expect(log.contains(marker)) + withTempLog { + let marker = "ts_test_\(UUID().uuidString.prefix(8))" + AuthDiagnostics.log(marker) + let log = AppLogStore.read(channel: .auth) + #expect(log.contains(marker)) + let line = log.split(separator: "\n").first { $0.contains(marker) } + #expect(line != nil) + if let line { + // ISO8601 timestamps look like [2024-03-15T...] + #expect(line.hasPrefix("[")) + #expect(AppLogStore.entryTag(of: line) == "AUTH") + // …and "looks like" is not enough: `hasPrefix("[")` and + // `entryTag` are both satisfied by `[not-a-date] [AUTH] x`, so + // replacing `Date().iso8601String()` in `AppLogStore.append` + // with a literal string left this test green. Parse it. + let field = AppLogEntryLine.timestampField(of: line) + #expect(field != nil) + #expect(Date.fromISO8601(field ?? "") != nil, + "entry timestamp is not ISO8601: \(field ?? "")") + } + } } - @Test("Most recent log entry is always present") + @Test("Entries accumulate in call order") func multipleEntries() { - let markerA = "multi_A_\(UUID().uuidString.prefix(8))" - let markerB = "multi_B_\(UUID().uuidString.prefix(8))" - AuthDiagnostics.log(markerA) - AuthDiagnostics.log(markerB) - let log = AuthDiagnostics.readLog() - #expect(log.contains(markerB)) + withTempLog { + let markerA = "multi_A_\(UUID().uuidString.prefix(8))" + let markerB = "multi_B_\(UUID().uuidString.prefix(8))" + AuthDiagnostics.log(markerA) + AuthDiagnostics.log(markerB) + let log = AppLogStore.read(channel: .auth) + #expect(log.contains(markerA)) + #expect(log.contains(markerB)) + guard let posA = log.range(of: markerA), let posB = log.range(of: markerB) else { + Issue.record("markers missing from log") + return + } + #expect(posA.lowerBound < posB.lowerBound) + } + } + + @Test("Reading with no auth entries returns a placeholder") + func readFallback() { + withTempLog { + #expect(AppLogStore.read(channel: .auth) == "(no AUTH log)") + } } - @Test("readLog returns fallback when no log exists") - func readLogFallback() { - let log = AuthDiagnostics.readLog() - #expect(!log.isEmpty) + @Test("Auth entries are readable from the shared app log") + func auditIsReachableFromTheSharedLog() { + // Auth diagnostics used to go to `auth_diagnostics.log`, which the Debug + // menu never surfaced — written, never REACHABLE. (Not "never readable": + // `v1.7.14:AuthDiagnostics` did declare `readLog()`; what it lacked was any + // surface that called it, and it was the only one of the fifteen log files + // with no share button anywhere.) The point of the move is + // that they now appear in the one App Logs export. + withTempLog { + let marker = "reachable_\(UUID().uuidString.prefix(8))" + AuthDiagnostics.log(marker) + #expect(AppLogStore.read().contains(marker)) + } } } diff --git a/TabMailTests/Services/BackgroundSyncLoggerTests.swift b/TabMailTests/Services/BackgroundSyncLoggerTests.swift index a3fd1545..09d8455f 100644 --- a/TabMailTests/Services/BackgroundSyncLoggerTests.swift +++ b/TabMailTests/Services/BackgroundSyncLoggerTests.swift @@ -6,59 +6,97 @@ import Testing import Foundation @testable import TabMail -@Suite("BackgroundSyncLogger") +/// `.processGlobalState` as well as `.serialized`: these tests rebind +/// `AppLogStore.fileURLOverride` and `DebugModeManager +/// .loggingEnabledOverrideForTesting`, both process-global. `.serialized` +/// orders tests only WITHIN this suite, and `AppLogStoreTests` / +/// `AuthDiagnosticsTests` mutate the same two seams — so without the shared +/// critical section another suite's `_resetForTesting` can point this suite's +/// writer at the real Application Support log mid-test. +@Suite("BackgroundSyncLogger", .serialized, .processGlobalState) struct BackgroundSyncLoggerTests { - @Test("Log and readLog round-trip") + /// Point the shared app log at a fresh temp file for one test. + /// + /// These tests used to write into the real Application Support log and hedge + /// every assertion with "if the write failed, still pass" — which made them + /// pass whether or not the logger worked. With the file under test control + /// the round-trips are asserted outright. + private func withTempLog(_ body: () throws -> T) rethrows -> T { + let url = FileManager.default.temporaryDirectory + .appendingPathComponent("bgsynclog_\(UUID().uuidString).log") + AppLogStore.fileURLOverride.withLock { $0 = url } + defer { + AppLogStore._resetForTesting() + try? FileManager.default.removeItem(at: url) + } + return try body() + } + + @Test("Log and read round-trip") func logAndRead() { - // Write multiple entries with unique marker to ensure at least one survives - // the 200-entry trim (real device may have existing entries from app usage) - let marker = "bgsync_test_\(UUID().uuidString.prefix(8))" - BackgroundSyncLogger.log(marker) - // Write a second time to increase likelihood of presence after trim - BackgroundSyncLogger.log("verify_\(marker)") - let log = BackgroundSyncLogger.readLog() - // The most recent entry must always survive the trim - #expect(log.contains("verify_\(marker)")) + withTempLog { + let marker = "bgsync_test_\(UUID().uuidString.prefix(8))" + BackgroundSyncLogger.log(marker) + #expect(AppLogStore.read().contains(marker)) + } } - @Test("Log entries have timestamps") + @Test("Log entries carry a timestamp and the SYNC channel tag") func logTimestamps() { - BackgroundSyncLogger.clearLog() - let marker = "bgts_\(UUID().uuidString.prefix(8))" - BackgroundSyncLogger.log(marker) - let log = BackgroundSyncLogger.readLog() - // Log file may be unwritable on simulator (try? silently fails). - // If marker is present, verify format. If not, the write failed — still pass. - if log.contains(marker) { - #expect(log.contains("[")) - #expect(log.contains("]")) + withTempLog { + let marker = "bgts_\(UUID().uuidString.prefix(8))" + BackgroundSyncLogger.log(marker) + let log = AppLogStore.read() + #expect(log.contains(marker)) + let line = log.split(separator: "\n").first { $0.contains(marker) } + #expect(line != nil) + if let line { + #expect(AppLogStore.entryTag(of: line) == "SYNC") + // The timestamp must be a REAL timestamp. `entryTag` deliberately + // does not validate it (it runs once per physical line of a + // 32 MB-capped file), so nothing else in the suite notices if + // `AppLogStore.append` stops formatting a date at all — replacing + // `Date().iso8601String()` with a literal left every other + // assertion here green. + let field = AppLogEntryLine.timestampField(of: line) + #expect(field != nil) + #expect(Date.fromISO8601(field ?? "") != nil, + "entry timestamp is not ISO8601: \(field ?? "")") + } } } - @Test("Error log round-trip with source") + @Test("Error log round-trip preserves the source") func errorLogRoundTrip() { - BackgroundSyncLogger.clearErrorLog() - let marker = "bgerr_\(UUID().uuidString.prefix(8))" - BackgroundSyncLogger.logError(marker, source: "TestSource") - let log = BackgroundSyncLogger.readErrorLog() - if log.contains(marker) { + withTempLog { + let marker = "bgerr_\(UUID().uuidString.prefix(8))" + BackgroundSyncLogger.logError(marker, source: "TestSource") + let log = AppLogStore.read(channel: .error) + #expect(log.contains(marker)) + // The source stays nested inside the ERROR entry — the channel tag + // identifies the file section, the source still identifies the site. #expect(log.contains("[TestSource]")) } } - @Test("readLog returns non-nil result") - func readLogFallback() { - // readLog returns either log content, empty string (cleared), or fallback message. - // All are valid — the key contract is it never crashes. - let log = BackgroundSyncLogger.readLog() - _ = log // no crash = pass + @Test("Chat error round-trip includes the user message continuation line") + func chatErrorRoundTrip() { + withTempLog { + let marker = "bgchat_\(UUID().uuidString.prefix(8))" + BackgroundSyncLogger.logChatError(marker, userMessage: "what happened") + let log = AppLogStore.read(channel: .chatError) + #expect(log.contains(marker)) + #expect(log.contains("User message: what happened")) + } } - @Test("readErrorLog returns non-nil result") - func readErrorLogFallback() { - let log = BackgroundSyncLogger.readErrorLog() - _ = log // no crash = pass + @Test("Reading a channel with no entries returns a placeholder, never a crash") + func readFallback() { + withTempLog { + #expect(AppLogStore.read(channel: .sync) == "(no SYNC log)") + #expect(AppLogStore.read(channel: .error) == "(no ERROR log)") + } } // MARK: - Body double-escape detector @@ -74,12 +112,23 @@ struct BackgroundSyncLoggerTests { #expect(BackgroundSyncLogger.htmlLooksDoubleEscaped("space&nbsp;here")) } - @Test("Body render log read/clear never crashes") - func bodyRenderLogRoundTrip() { - // logBodyRender is debug-gated (no-op when locked), so we don't assert a - // write round-trip here — only that read/clear are crash-safe and return a String. - BackgroundSyncLogger.clearBodyRenderLog() - let log = BackgroundSyncLogger.readBodyRenderLog() - _ = log // no crash = pass + @Test("diagnoseStoredBody writes only for a double-escaped body") + func diagnoseStoredBodyIsConditional() { + withTempLog { + DebugModeManager.loggingEnabledOverrideForTesting.withLock { $0 = true } + defer { DebugModeManager.loggingEnabledOverrideForTesting.withLock { $0 = nil } } + + BackgroundSyncLogger.diagnoseStoredBody( + source: "clean", headerId: "h1", htmlContent: "

Tom & Jerry

" + ) + #expect(AppLogStore.read(channel: .bodyRender) == "(no RENDER log)") + + BackgroundSyncLogger.diagnoseStoredBody( + source: "dirty", headerId: "h2", htmlContent: "Tom &amp; Jerry" + ) + let log = AppLogStore.read(channel: .bodyRender) + #expect(log.contains("DOUBLE-ESCAPE")) + #expect(log.contains("h2")) + } } } diff --git a/TabMailTests/Services/StartupMigrationsTests.swift b/TabMailTests/Services/StartupMigrationsTests.swift index c51e5249..9d567e62 100644 --- a/TabMailTests/Services/StartupMigrationsTests.swift +++ b/TabMailTests/Services/StartupMigrationsTests.swift @@ -16,7 +16,14 @@ import GRDB /// `.serialized` because the resets read/write process-global /// `UserDefaults.standard` flags; each test snapshots + restores them. The FTS /// reset is injected (`resetFTS:`) so tests never touch the real FTS directory. -@Suite("StartupMigrations — one-shot gating", .serialized) +/// +/// `.processGlobalState` as well, for the same reason the three logger suites +/// carry it: `.serialized` orders tests only WITHIN one suite, and these five +/// `UserDefaults` flags — `didDeleteLegacyLogFiles_v1` included — are +/// process-global. Without the shared critical section a parallel suite can run +/// between this suite's snapshot and restore and observe (or be observed by) a +/// half-set flag. +@Suite("StartupMigrations — one-shot gating", .serialized, .processGlobalState) struct StartupMigrationsTests { static let flagKeys = [ @@ -26,16 +33,22 @@ struct StartupMigrationsTests { "didCleanResetMessageData_v1", ] + /// Every one-shot flag `run` touches, including the legacy-log cleanup's — + /// which is deliberately NOT in `StartupMigrations.resetFlagKeys` (it must + /// not arm the "Updating…" splash) but IS process-global state these tests + /// must snapshot and restore like the rest. + static let allFlagKeys = flagKeys + [StartupMigrations.legacyLogCleanupFlagKey] + static func snapshotFlags() -> [String: Any] { var snap: [String: Any] = [:] - for key in flagKeys where UserDefaults.standard.object(forKey: key) != nil { + for key in allFlagKeys where UserDefaults.standard.object(forKey: key) != nil { snap[key] = UserDefaults.standard.object(forKey: key) } return snap } static func restoreFlags(_ snap: [String: Any]) { - for key in flagKeys { + for key in allFlagKeys { if let value = snap[key] { UserDefaults.standard.set(value, forKey: key) } else { @@ -44,6 +57,16 @@ struct StartupMigrationsTests { } } + /// A throwaway directory standing in for Application Support / TabMail. + /// Never the real one: `run` unlinks files there, and the test host's + /// Application Support is not this suite's to modify. + static func makeTempLogDirectory() throws -> URL { + let dir = FileManager.default.temporaryDirectory + .appendingPathComponent("startupmig_\(UUID().uuidString)", isDirectory: true) + try FileManager.default.createDirectory(at: dir, withIntermediateDirectories: true) + return dir + } + /// In-memory DB with just the `messageHeader` table — enough for the /// `didMigrateHeaderIds_v2` delete. Other branches are skipped via flags. static func makeHeaderDB() throws -> DatabaseQueue { @@ -81,6 +104,8 @@ struct StartupMigrationsTests { func reRunPreservesData() async throws { let saved = Self.snapshotFlags() defer { Self.restoreFlags(saved) } + let logDir = try Self.makeTempLogDirectory() + defer { try? FileManager.default.removeItem(at: logDir) } for key in Self.flagKeys { UserDefaults.standard.set(true, forKey: key) } @@ -90,7 +115,7 @@ struct StartupMigrationsTests { } var ftsResets = 0 - StartupMigrations.run(queue, resetFTS: { ftsResets += 1 }) + StartupMigrations.run(queue, resetFTS: { ftsResets += 1 }, legacyLogDirectory: logDir) // Seed survives + FTS untouched: this is what makes "seed after the // DB-open migrations" safe. @@ -102,6 +127,8 @@ struct StartupMigrationsTests { func firstRunDeletesThenNoOps() async throws { let saved = Self.snapshotFlags() defer { Self.restoreFlags(saved) } + let logDir = try Self.makeTempLogDirectory() + defer { try? FileManager.default.removeItem(at: logDir) } // Only the messageHeader migration is pending. UserDefaults.standard.set(false, forKey: "didMigrateHeaderIds_v2") @@ -114,7 +141,7 @@ struct StartupMigrationsTests { try db.execute(sql: "INSERT INTO messageHeader (id) VALUES ('stale-1')") } - StartupMigrations.run(queue, resetFTS: {}) + StartupMigrations.run(queue, resetFTS: {}, legacyLogDirectory: logDir) #expect(try await Self.count(queue, "messageHeader") == 0) #expect(UserDefaults.standard.bool(forKey: "didMigrateHeaderIds_v2") == true) @@ -122,7 +149,7 @@ struct StartupMigrationsTests { try await queue.write { db in try db.execute(sql: "INSERT INTO messageHeader (id) VALUES ('fresh-1')") } - StartupMigrations.run(queue, resetFTS: {}) + StartupMigrations.run(queue, resetFTS: {}, legacyLogDirectory: logDir) #expect(try await Self.count(queue, "messageHeader") == 1) } @@ -130,6 +157,8 @@ struct StartupMigrationsTests { func cleanResetWipesAndResetsFTSOnce() async throws { let saved = Self.snapshotFlags() defer { Self.restoreFlags(saved) } + let logDir = try Self.makeTempLogDirectory() + defer { try? FileManager.default.removeItem(at: logDir) } // Only the clean-reset migration is pending. UserDefaults.standard.set(true, forKey: "didMigrateHeaderIds_v2") @@ -144,7 +173,7 @@ struct StartupMigrationsTests { } var ftsResets = 0 - StartupMigrations.run(queue, resetFTS: { ftsResets += 1 }) + StartupMigrations.run(queue, resetFTS: { ftsResets += 1 }, legacyLogDirectory: logDir) #expect(try await Self.count(queue, "messageHeader") == 0) #expect(try await Self.count(queue, "messageBody") == 0) @@ -155,7 +184,7 @@ struct StartupMigrationsTests { try await queue.write { db in try db.execute(sql: "INSERT INTO messageHeader (id) VALUES ('fresh')") } - StartupMigrations.run(queue, resetFTS: { ftsResets += 1 }) + StartupMigrations.run(queue, resetFTS: { ftsResets += 1 }, legacyLogDirectory: logDir) #expect(try await Self.count(queue, "messageHeader") == 1) #expect(ftsResets == 1) } @@ -163,11 +192,142 @@ struct StartupMigrationsTests { // MARK: - Migration-detection (drives the "Updating…" splash gate) /// `resetFlagKeys` is the single source of truth that `allResetsComplete` - /// reads; if it drifts from the keys `run(_:)` actually checks, the splash - /// gate would mis-fire. Pin it to this test's independently-maintained list. + /// reads; if it drifts from the keys `run(_:)` actually gates on, the splash + /// gate mis-fires — a newly-shipped destructive reset would run at launch with + /// no "Updating…" splash in front of it, or a stale key would keep the splash + /// armed forever. + /// + /// ⚠️ Comparing the constant to a hand-maintained list in this file proved + /// only that TWO LISTS AGREE, which is not what the name claims. Adding a + /// `UserDefaults.standard.bool(forKey: "didNewReset")` branch to `run` touches + /// neither list, so the test stayed green while the migration splash omitted + /// real work. The oracle is now DERIVED FROM THE SOURCE, in the style of + /// `AppLogStoreTests.gatedWritersGateTheirPrintToo` and of + /// `everyChannelIsClassifiedExactlyOnce`: every key `run`'s body actually + /// gates on must be accounted for by exactly one of the two production lists. @Test("StartupMigrations.resetFlagKeys matches the keys run() gates on") - func resetFlagKeysMatchCanonicalList() { + func resetFlagKeysMatchCanonicalList() throws { + // The independently-maintained list still has to agree, ORDER included: + // `resetFlagKeys`' own comment calls it "in run order". #expect(StartupMigrations.resetFlagKeys == Self.flagKeys) + + let source = try AppLogStoreTests.projectFile("TabMail/Services/StartupMigrations.swift") + guard let body = Self.runFunctionBody(in: source) else { + Issue.record("could not find the body of StartupMigrations.run") + return + } + // Non-vacuity: the recovered range really is `run`'s body, and not — say — + // the `resetFTS:` default-value closure that sits inside its signature. + #expect(body.contains("didCleanResetMessageData_v1"), + "the scanned range is not run()'s body") + + let scan = Self.gatedFlagKeys(in: body) + // Every key `run` gates on is accounted for by exactly one list: the slow + // cached-mail resets that arm the splash, plus the one-shot legacy-log + // cleanup that deliberately does NOT. A key in neither is a reset nobody + // classified; a key in a list but never gated on is a stale entry keeping + // the splash armed. + let accounted = Set(StartupMigrations.resetFlagKeys) + .union([StartupMigrations.legacyLogCleanupFlagKey]) + let found = Set(scan.keys) + let unclassified = found.subtracting(accounted).sorted() + let neverGated = accounted.subtracting(found).sorted() + #expect(found == accounted, + "gated but unclassified: \(unclassified); never gated on: \(neverGated)") + // An argument the scan cannot read must never be erased into a clean pass: + // that is how a new, unclassified reset would slip through as "nothing + // found". Same shape as `deleteLegacyLogFiles` counting an unresolvable + // error as a FAILURE rather than a skip. + #expect(scan.unresolved.isEmpty, + "a `bool(forKey:)` argument this scan cannot resolve: \(scan.unresolved)") + } + + /// The body of `StartupMigrations.run` — the text between the brace that + /// opens it and the matching close — or `nil` if it cannot be recovered. + /// + /// `AppLogStoreTests.functionBody(of:in:)` is NOT reusable here, and the + /// reason is worth stating rather than rediscovering: it takes the first `{` + /// after the signature, and `run`'s signature contains one — + /// `resetFTS: () -> Void = { deleteFTSDirectory() }` — so it would hand back + /// that default-value closure. This walks the PARAMETER LIST to its closing + /// paren first (parenthesis depth, which the closure's own `()` does not + /// disturb) and only then takes the next brace. Its scalar-offset primitive is + /// reused, so both scanners agree on what "where does this token appear" means. + static func runFunctionBody(in source: String) -> String? { + let signatureToken = "static func run(" + guard let signature = AppLogStoreTests.firstIndex(ofToken: signatureToken, in: source) else { + return nil + } + let scalars = Array(source.unicodeScalars) + var index = signature + signatureToken.unicodeScalars.count - 1 // at the `(` + var parens = 0 + while index < scalars.count { + if scalars[index] == "(" { + parens += 1 + } else if scalars[index] == ")" { + parens -= 1 + if parens == 0 { + index += 1 + break + } + } + index += 1 + } + while index < scalars.count, scalars[index] != "{" { index += 1 } + guard index < scalars.count else { return nil } + var depth = 0 + var body = String.UnicodeScalarView() + while index < scalars.count { + let scalar = scalars[index] + if scalar == "{" { + depth += 1 + if depth == 1 { + index += 1 + continue + } + } else if scalar == "}" { + depth -= 1 + if depth == 0 { return String(body) } + } + body.append(scalar) + index += 1 + } + return nil + } + + /// Every `UserDefaults.standard.bool(forKey: …)` argument in `body`, resolved + /// to the flag key it names, plus the ones that could not be resolved. + /// + /// Two spellings occur in `run` and both must resolve or the scan + /// under-reports: a string LITERAL (the four cached-mail resets) and the bare + /// identifier `legacyLogCleanupFlagKey`. Anything else is REPORTED, never + /// silently skipped. + static func gatedFlagKeys(in body: String) -> (keys: [String], unresolved: [String]) { + let token = "UserDefaults.standard.bool(forKey: " + let tokenLength = token.unicodeScalars.count + var keys: [String] = [] + var unresolved: [String] = [] + var remaining = body + while let offset = AppLogStoreTests.firstIndex(ofToken: token, in: remaining) { + let scalars = Array(remaining.unicodeScalars) + var cursor = offset + tokenLength + var argument = String.UnicodeScalarView() + while cursor < scalars.count, scalars[cursor] != ")" { + argument.append(scalars[cursor]) + cursor += 1 + } + let text = String(argument).trimmingCharacters(in: .whitespaces) + if text.unicodeScalars.count >= 2, + text.unicodeScalars.first == "\"", text.unicodeScalars.last == "\"" { + keys.append(String(text.dropFirst().dropLast())) + } else if text == "legacyLogCleanupFlagKey" { + keys.append(StartupMigrations.legacyLogCleanupFlagKey) + } else { + unresolved.append(text) + } + remaining = String(String.UnicodeScalarView(scalars[min(cursor, scalars.count)...])) + } + return (keys, unresolved) } @Test("allResetsComplete is true only when every reset flag is set") @@ -216,4 +376,328 @@ struct StartupMigrationsTests { let migrated = try TestDatabase.make() #expect(try AppDatabase.hasPendingMigrationWork(migrated) == true) } + + // MARK: - Legacy per-subsystem log files (GitHub #83) + + /// The names `AppLogStore`'s header records as the files it replaced, + /// maintained here independently of the production list so a name dropped + /// from one side is visible. + static let legacyLogNames = [ + "background_sync.log", "error.log", "chat_error.log", "bg_app_refresh.log", + "bg_processing.log", "ai_processing.log", "push.log", "backfill_ai.log", + "backfill.log", "inbox.log", "boot.log", "body_render.log", + "stuck_messages.log", "device_sync.log", "auth_diagnostics.log", + ] + + @Test("The legacy log list is exactly the fifteen files consolidation orphaned") + func legacyLogNamesMatchTheCanonicalList() { + #expect(Set(StartupMigrations.legacyLogFileNames) == Set(Self.legacyLogNames)) + #expect(StartupMigrations.legacyLogFileNames.count == 15) + // The live log and the NSE's own file are NOT legacy and must never be + // unlinked by this cleanup. + #expect(!StartupMigrations.legacyLogFileNames.contains("tabmail.log")) + #expect(!StartupMigrations.legacyLogFileNames.contains("nse.log")) + } + + @Test("deleteLegacyLogFiles unlinks every orphan and nothing else") + func deleteLegacyLogFilesRemovesOnlyTheOrphans() throws { + let dir = try Self.makeTempLogDirectory() + defer { try? FileManager.default.removeItem(at: dir) } + + for name in Self.legacyLogNames { + try Data("stale".utf8).write(to: dir.appendingPathComponent(name)) + } + // The live app log, and unrelated neighbours, must survive: stranded log + // bytes are what this deletes, not whatever happens to be adjacent. + try Data("live".utf8).write(to: dir.appendingPathComponent("tabmail.log")) + try Data("x".utf8).write(to: dir.appendingPathComponent("tabmail.sqlite")) + // `unrelated.log` carries the SAME EXTENSION as the fifteen and is not one + // of them. Without it this test passes an implementation that deletes + // every `*.log` except `tabmail.log` — which is exactly the widened + // pattern the production code refuses, so the test has to be able to see + // the difference between "the fifteen names" and "anything ending .log". + try Data("keep".utf8).write(to: dir.appendingPathComponent("unrelated.log")) + + let cleanup = StartupMigrations.deleteLegacyLogFiles(in: dir) + #expect(cleanup.deleted == Self.legacyLogNames.count) + #expect(cleanup.failed == 0) + + let remaining = try FileManager.default.contentsOfDirectory(atPath: dir.path).sorted() + #expect(remaining == ["tabmail.log", "tabmail.sqlite", "unrelated.log"], + "left behind: \(remaining)") + } + + @Test("deleteLegacyLogFiles treats a missing file as nothing to do") + func deleteLegacyLogFilesToleratesMissingFiles() throws { + let dir = try Self.makeTempLogDirectory() + defer { try? FileManager.default.removeItem(at: dir) } + + // A fresh install has none of them. + #expect(StartupMigrations.deleteLegacyLogFiles(in: dir) == .init(deleted: 0, failed: 0)) + + // A partially-completed previous attempt has some. + try Data("stale".utf8).write(to: dir.appendingPathComponent("push.log")) + try Data("stale".utf8).write(to: dir.appendingPathComponent("boot.log")) + #expect(StartupMigrations.deleteLegacyLogFiles(in: dir) == .init(deleted: 2, failed: 0)) + + // And a directory that does not exist at all is not an error either. + let absent = dir.appendingPathComponent("nope", isDirectory: true) + #expect(StartupMigrations.deleteLegacyLogFiles(in: absent) == .init(deleted: 0, failed: 0)) + } + + @Test("A legacy file that reappears does NOT re-arm the one-shot flag") + func reappearingLegacyFileDoesNotReArmTheOneShot() throws { + let saved = Self.snapshotFlags() + defer { Self.restoreFlags(saved) } + let logDir = try Self.makeTempLogDirectory() + defer { try? FileManager.default.removeItem(at: logDir) } + + // Every cached-mail reset already done; only the log cleanup is pending. + for key in Self.flagKeys { UserDefaults.standard.set(true, forKey: key) } + UserDefaults.standard.set(false, forKey: StartupMigrations.legacyLogCleanupFlagKey) + + for name in Self.legacyLogNames { + try Data("stale".utf8).write(to: logDir.appendingPathComponent(name)) + } + + let queue = try Self.makeHeaderDB() + StartupMigrations.run(queue, resetFTS: {}, legacyLogDirectory: logDir) + + #expect(try FileManager.default.contentsOfDirectory(atPath: logDir.path).isEmpty) + #expect(UserDefaults.standard.bool(forKey: StartupMigrations.legacyLogCleanupFlagKey) == true) + + // The property pinned here is the GATE, not the filesystem: once the + // flag is set, `run` does not call the cleanup again, so a file that + // reappears under a legacy name is not looked at. That is what "one + // shot, ever" means, and it is what keeps the cleanup off every + // subsequent launch. + // + // ⚠️ Its known consequence, recorded rather than blessed: nothing in + // this build writes those names, but running a PRE-consolidation build + // (a downgrade, a TestFlight rollback, a sideloaded older archive) + // after the cleanup has run recreates one — and it will then never be + // removed again, because the flag stays set and "Clear All Logs" only + // knows about `tabmail.log`. Those bytes still count toward + // `StorageEstimator`'s budget. Accepted: recoverable by deleting and + // reinstalling the app, and a downgrade is not a supported path. Adding + // a `_v2` flag is the fix if that ever stops being true. + try Data("later".utf8).write(to: logDir.appendingPathComponent("push.log")) + StartupMigrations.run(queue, resetFTS: {}, legacyLogDirectory: logDir) + #expect(try FileManager.default.contentsOfDirectory(atPath: logDir.path) == ["push.log"]) + } + + /// Make the file at `url` refuse `removeItem` for the duration of `body`, + /// then make it deletable again so the temp directory can be cleaned up. + /// + /// `UF_IMMUTABLE` (`FileAttributeKey.immutable`) is used because it is + /// per-FILE. Making the parent directory read-only would fail EVERY name, + /// which could not distinguish "aborted at the first failure" from + /// "isolated that one and carried on" — the exact distinction these tests + /// exist to make. + static func withUndeletableFile(at url: URL, _ body: () throws -> T) rethrows -> T { + try? FileManager.default.setAttributes([.immutable: true], ofItemAtPath: url.path) + defer { try? FileManager.default.setAttributes([.immutable: false], ofItemAtPath: url.path) } + return try body() + } + + @Test("One unremovable legacy file does not strand the other fourteen") + func deleteLegacyLogFilesIsolatesOneFailure() throws { + let dir = try Self.makeTempLogDirectory() + defer { try? FileManager.default.removeItem(at: dir) } + + for name in Self.legacyLogNames { + try Data("stale".utf8).write(to: dir.appendingPathComponent(name)) + } + // Block the FIRST name in production order, so "aborts at the first + // failure" and "isolates it and continues" give maximally different + // answers: 0 removed versus 14. + let blocked = dir.appendingPathComponent(StartupMigrations.legacyLogFileNames[0]) + + let cleanup = Self.withUndeletableFile(at: blocked) { + StartupMigrations.deleteLegacyLogFiles(in: dir) + } + + // Non-vacuity: if the immutable flag did not take, the "failure" never + // happened and every assertion below would pass for the wrong reason. + try #require(FileManager.default.fileExists(atPath: blocked.path), + "the immutable flag did not take — this test proves nothing without it") + #expect(cleanup.failed == 1) + #expect(cleanup.deleted == Self.legacyLogNames.count - 1) + #expect(try FileManager.default.contentsOfDirectory(atPath: dir.path) + == [blocked.lastPathComponent]) + } + + @Test("A DIRECTORY bearing a legacy name is never recursed into, and a symlink loses only the LINK") + func deleteLegacyLogFilesNeverRecursesIntoADirectory() throws { + let dir = try Self.makeTempLogDirectory() + defer { try? FileManager.default.removeItem(at: dir) } + + // `removeItem(at:)` is documented as recursive, so a directory bearing a + // legacy name would be deleted WITH ITS CONTENTS, at launch, before any UI + // exists to report it — and an `isRegularFile` check in front of it does + // NOT close that: the check and the removal are two syscalls with a window + // between them. `unlink` is one syscall that refuses a directory outright. + // Nothing in this tree creates such a directory, which is precisely why + // the code must fail closed rather than depend on that staying true. + let asDirectory = dir.appendingPathComponent("push.log", isDirectory: true) + try FileManager.default.createDirectory(at: asDirectory, withIntermediateDirectories: true) + let inside = asDirectory.appendingPathComponent("keep-me.txt") + try Data("precious".utf8).write(to: inside) + + // A VALID symlink at a legacy name, pointing at a file that must survive. + // `unlink` removes the directory ENTRY and never what it points at, so the + // stranded name goes and the cleanup never reaches THROUGH a name it was + // handed. This replaces an earlier DANGLING-symlink case that + // discriminated nothing: `fileExists(atPath:)` follows symlinks and is + // already false for a dangling one, so it passed under every predicate + // this function has ever had. + let target = dir.appendingPathComponent("target-must-survive.txt") + try Data("keep".utf8).write(to: target) + let link = dir.appendingPathComponent("inbox.log") + try FileManager.default.createSymbolicLink(at: link, withDestinationURL: target) + + // A genuine orphan alongside them, so the pass is not trivially empty. + try Data("stale".utf8).write(to: dir.appendingPathComponent("boot.log")) + + let cleanup = StartupMigrations.deleteLegacyLogFiles(in: dir) + + // Two entries removed: `boot.log` (a regular file) and `inbox.log` (the + // symlink's own entry — the LINK, not its target). + #expect(cleanup.deleted == 2) + // A skip is a permanent, deliberate refusal, not a failure: counting it + // as one would leave the flag unset and re-scan all fifteen names on + // every launch forever, with no progress to show for it. + #expect(cleanup.failed == 0) + + // The property that cannot be undone if it is ever wrong. + #expect(FileManager.default.fileExists(atPath: asDirectory.path), + "the directory at a legacy name was removed") + #expect(FileManager.default.fileExists(atPath: inside.path), + "the directory's contents were deleted") + // The link is gone; the file it named is not. + #expect(FileManager.default.fileExists(atPath: target.path), + "the unlink reached through the symlink and destroyed its target") + #expect(try FileManager.default.contentsOfDirectory(atPath: dir.path).sorted() + == ["push.log", "target-must-survive.txt"]) + } + + /// Make every entry in `directory` refuse `unlink` (Darwin returns `EPERM`) + /// for the duration of `body`, then make the directory mutable again so the + /// temp tree can be cleaned up. + /// + /// `UF_IMMUTABLE` on the PARENT rather than on the entry, because the entry + /// under test is a symlink and `FileManager.setAttributes` follows those — + /// it would flag the link's target instead of the link. A name that is not + /// present still fails lookup first and returns `ENOENT`, so the fourteen + /// absent names stay on the "nothing to do" path. + static func withUndeletableEntries(in directory: URL, _ body: () throws -> T) rethrows -> T { + try? FileManager.default.setAttributes([.immutable: true], ofItemAtPath: directory.path) + defer { try? FileManager.default.setAttributes([.immutable: false], ofItemAtPath: directory.path) } + return try body() + } + + @Test("A symlink to a DIRECTORY whose unlink fails is a failure, not a clean skip") + func symlinkToDirectoryThatCannotBeUnlinkedIsAFailure() throws { + // The skip branch exists for ONE thing: a real directory sitting at a + // legacy name, which no future launch could make removable, so counting + // it would re-scan all fifteen names every launch forever with nothing to + // show for it. Everything else — including an unlink that failed for a + // reason this pass could not resolve — must count as a FAILURE, because + // a failure is what keeps the one-shot flag unset and the name retried. + // + // The INVARIANT: the classification must describe the ENTRY this pass + // tried to unlink, never whatever that entry points at. A predicate that + // resolves the link answers a question about the TARGET, so a symlink is + // recorded as a clean skip, `failed` stays 0, the one-shot flag arms — + // and that name's bytes are stranded in Application Support forever, + // counting against `StorageEstimator`'s budget with no UI able to reach + // them. + let saved = Self.snapshotFlags() + defer { Self.restoreFlags(saved) } + let dir = try Self.makeTempLogDirectory() + defer { try? FileManager.default.removeItem(at: dir) } + + // The target lives OUTSIDE the scanned directory, so the link is the only + // entry in it and nothing else can account for the failure count. + let targetDir = try Self.makeTempLogDirectory() + defer { try? FileManager.default.removeItem(at: targetDir) } + let link = dir.appendingPathComponent(StartupMigrations.legacyLogFileNames[0]) + try FileManager.default.createSymbolicLink(at: link, withDestinationURL: targetDir) + + for key in Self.flagKeys { UserDefaults.standard.set(true, forKey: key) } + UserDefaults.standard.set(false, forKey: StartupMigrations.legacyLogCleanupFlagKey) + let queue = try Self.makeHeaderDB() + + let cleanup = Self.withUndeletableEntries(in: dir) { + StartupMigrations.deleteLegacyLogFiles(in: dir) + } + + // Non-vacuity: the unlink genuinely failed, so there IS an ambiguity to + // resolve. `destinationOfSymbolicLink` and not `fileExists`, which + // follows the link and would be answering about the target again. + try #require((try? FileManager.default.destinationOfSymbolicLink(atPath: link.path)) != nil, + "the link was removed — this test proves nothing without a failed unlink") + #expect(cleanup.deleted == 0) + #expect(cleanup.failed == 1, + "a symlink whose unlink failed was recorded as a clean skip") + + // And the consequence that makes it permanent: the one-shot flag must + // stay unset so the next launch retries this name. + Self.withUndeletableEntries(in: dir) { + StartupMigrations.run(queue, resetFTS: {}, legacyLogDirectory: dir) + } + #expect(UserDefaults.standard.bool(forKey: StartupMigrations.legacyLogCleanupFlagKey) == false, + "the one-shot flag armed — this name is now stranded forever") + } + + @Test("The one-shot flag arms only after a pass with zero failures") + func legacyLogCleanupFlagArmsOnlyOnACleanPass() throws { + let saved = Self.snapshotFlags() + defer { Self.restoreFlags(saved) } + let logDir = try Self.makeTempLogDirectory() + defer { try? FileManager.default.removeItem(at: logDir) } + + for key in Self.flagKeys { UserDefaults.standard.set(true, forKey: key) } + UserDefaults.standard.set(false, forKey: StartupMigrations.legacyLogCleanupFlagKey) + + for name in Self.legacyLogNames { + try Data("stale".utf8).write(to: logDir.appendingPathComponent(name)) + } + let blocked = logDir.appendingPathComponent(StartupMigrations.legacyLogFileNames[0]) + let queue = try Self.makeHeaderDB() + + // Launch 1: one name cannot be removed. The other fourteen still are, + // and the flag stays UNSET so the next launch retries the remainder. + Self.withUndeletableFile(at: blocked) { + StartupMigrations.run(queue, resetFTS: {}, legacyLogDirectory: logDir) + } + try #require(FileManager.default.fileExists(atPath: blocked.path), + "the immutable flag did not take — this test proves nothing without it") + #expect(try FileManager.default.contentsOfDirectory(atPath: logDir.path) + == [blocked.lastPathComponent]) + #expect(UserDefaults.standard.bool(forKey: StartupMigrations.legacyLogCleanupFlagKey) == false) + + // Launch 2: the obstruction is gone, the last name goes, and only NOW + // does the flag arm. This exercises a TRANSIENT obstruction only — + // `withUndeletableFile` clears the immutable flag before this launch. A + // PERMANENTLY undeletable file is a different branch: the flag never arms + // and the fifteen-name scan repeats every launch, which is the accepted + // bounded cost documented at the call site, not a progress guarantee. + StartupMigrations.run(queue, resetFTS: {}, legacyLogDirectory: logDir) + #expect(try FileManager.default.contentsOfDirectory(atPath: logDir.path).isEmpty) + #expect(UserDefaults.standard.bool(forKey: StartupMigrations.legacyLogCleanupFlagKey) == true) + } + + @Test("The legacy log cleanup does NOT arm the migration splash") + func legacyLogCleanupIsNotASplashGate() { + let saved = Self.snapshotFlags() + defer { Self.restoreFlags(saved) } + + // Deleting fifteen small files is not slow work, so a pending cleanup + // must not make launch show "Updating…". Only the cached-mail resets do. + for key in Self.flagKeys { UserDefaults.standard.set(true, forKey: key) } + UserDefaults.standard.set(false, forKey: StartupMigrations.legacyLogCleanupFlagKey) + #expect(StartupMigrations.allResetsComplete == true) + #expect(!StartupMigrations.resetFlagKeys.contains(StartupMigrations.legacyLogCleanupFlagKey)) + } } From b6c041acddefa3e274275cb0987865b687c7b562 Mon Sep 17 00:00:00 2001 From: Kwang Moo Yi Date: Fri, 28 Aug 2026 15:24:17 -0700 Subject: [PATCH 2/3] Strengthen the single-log regression coverage Signed-off-by: Kwang Moo Yi --- TabMailTests/Services/AppLogStoreTests.swift | 68 +++++++++++++++----- 1 file changed, 52 insertions(+), 16 deletions(-) diff --git a/TabMailTests/Services/AppLogStoreTests.swift b/TabMailTests/Services/AppLogStoreTests.swift index 53750f72..e1f8d5c6 100644 --- a/TabMailTests/Services/AppLogStoreTests.swift +++ b/TabMailTests/Services/AppLogStoreTests.swift @@ -178,6 +178,24 @@ struct AppLogStoreTests { try FileManager.default.contentsOfDirectory(atPath: directory.path).sorted() } + private func productionSwiftFiles() -> [URL] { + let root = URL(fileURLWithPath: #filePath) + .deletingLastPathComponent() // Services + .deletingLastPathComponent() // TabMailTests + .deletingLastPathComponent() // repository root + return ["TabMail", "Shared", "TabMailNotificationService"].flatMap { sourceRoot -> [URL] in + let directory = root.appendingPathComponent(sourceRoot) + guard let enumerator = FileManager.default.enumerator( + at: directory, + includingPropertiesForKeys: nil + ) else { return [] } + return enumerator.compactMap { entry -> URL? in + guard let url = entry as? URL, url.pathExtension == "swift" else { return nil } + return url + } + } + } + // MARK: - The single-file invariant @Test("Every channel writes to ONE file") @@ -210,14 +228,13 @@ struct AppLogStoreTests { // ⚠️ Scope, stated precisely because the earlier wording claimed // more than this can deliver: every write here goes through // `AppLogStore.append`, so what is proven is that the STORE does - // not fan out per channel. It does NOT prove that + // not fan out per channel. It does NOT by itself prove that // `device_sync.log` cannot reappear beside `tabmail.log` — the // shipped `DeviceSyncLogger` path was a hardcoded real // Application Support URL, not one derived from // `AppLogStore.fileURL`, so a writer that reintroduced it would // write outside this override's directory and be invisible here. - // `facadeWritersShareOneFile` covers the façades, and carries - // the same caveat. + // `legacyLogNamesAreMigrationOnly` covers that production path. let names = try fileNames(in: url.deletingLastPathComponent()) #expect(names == [url.lastPathComponent], "a sibling log file was created: \(names)") @@ -225,7 +242,7 @@ struct AppLogStoreTests { } } - @Test("The named writers all land in the same file, and open no second one") + @Test("The named writers land in the shared override and open no sibling there") func facadeWritersShareOneFile() throws { try withTempLog { url in try withDebugLogging(true) { @@ -249,13 +266,13 @@ struct AppLogStoreTests { // after the façades have run is what makes that dual write // visible. // - // ⚠️ What this cannot see: a writer whose second file is a + // What this cannot see: a writer whose second file is a // HARDCODED absolute path (the shape the shipped // `DeviceSyncLogger` actually had — real Application Support, // not derived from `AppLogStore.fileURL`) lands outside this - // override's directory and is invisible to any enumeration a - // test may safely perform. Covered here: a sibling written - // relative to the log's own directory. + // override's directory. `legacyLogNamesAreMigrationOnly` covers + // that exact production regression; this runtime test covers a + // sibling written relative to the log's own directory. let names = try fileNames(in: url.deletingLastPathComponent()) #expect(names == [url.lastPathComponent], "a façade opened a second log file: \(names)") @@ -263,6 +280,25 @@ struct AppLogStoreTests { } } + @Test("Legacy log filenames appear only in the one-shot migration") + func legacyLogNamesAreMigrationOnly() throws { + let migrationPathSuffix = "/TabMail/Services/StartupMigrations.swift" + var violations: [String] = [] + + for file in productionSwiftFiles() where !file.path.hasSuffix(migrationPathSuffix) { + let source = try String(contentsOf: file, encoding: .utf8) + let names = StartupMigrations.legacyLogFileNames.filter { + source.contains("\"\($0)\"") + } + if !names.isEmpty { + violations.append("\(file.lastPathComponent): \(names.joined(separator: ", "))") + } + } + + #expect(violations.isEmpty, + "a retired per-subsystem log path was reintroduced: \(violations)") + } + @Test("Entries from different channels interleave in append order") func entriesInterleaveInCallOrder() { withTempLog { _ in @@ -780,7 +816,7 @@ struct AppLogStoreTests { // MARK: - The gate covers the console too (global CLAUDE.md rule 12) - @Test("Every debug-gated writer gates its print as well as its file write") + @Test("Every direct console sink in a debug-gated writer follows its guard") func gatedWritersGateTheirPrintToo() throws { // Rule 12 is "a no-op in production", not "writes no file in production". // Every behavioural test in this file reads the FILE, so moving a @@ -1284,13 +1320,12 @@ struct AppLogStoreTests { // The oldest is gone — the trim actually ran, so this test is // not silently measuring an untrimmed file. #expect(!contents.contains("entry_0_")) - // Every surviving line is a complete physical LINE: the trim + // Every surviving line from this test is a complete physical + // LINE: the trim // advances past the first partial line rather than slicing one in - // half. The oracle is "parses as SOME channel", not "== SYNC": a - // partial line has no valid `[ts] [TAG] ` head and returns nil, - // which is exactly the defect being guarded, while an always-on - // entry that escaped an earlier test into the redirected file - // parses fine and must not flake this. + // half. Scope the oracle to our `entry_` markers: an escaped + // always-on `logChatError` task can legitimately add an untagged + // continuation line to the redirected file. // // ⚠️ LINE, not logical ENTRY — the distinction is real and the // stronger claim would be false. `logChatError` deliberately emits @@ -1302,7 +1337,8 @@ struct AppLogStoreTests { // export shows the orphan, and `clear(channel:)` removes it for // whichever channel is cleared (pinned by // `clearRemovesLeadingOrphanForAnyChannel`). - for line in contents.split(separator: "\n", omittingEmptySubsequences: true) { + for line in contents.split(separator: "\n", omittingEmptySubsequences: true) + where line.contains("entry_") { #expect(AppLogStore.entryTag(of: line) != nil, "trim left a partial line: \(line)") } From 0cbb56e5d56de70021aa247473a09f2ae09452d9 Mon Sep 17 00:00:00 2001 From: Kwang Moo Yi Date: Fri, 28 Aug 2026 15:29:45 -0700 Subject: [PATCH 3/3] Restore companion routing-note verification Signed-off-by: Kwang Moo Yi --- Companion/Decisions/Active/adr-ios-038.md | 15 +++++---- Companion/Decisions/V3/manifest.tsv | 1 + .../V3/pre-compaction-index-lines-078-079.md | 32 +++++++++++++++++++ .../compaction-2026-08-28-manifest.tsv | 6 ++++ ...on-reminders-scheduleditem-architecture.md | 9 +++--- DECISIONS.md | 4 +-- 6 files changed, 55 insertions(+), 12 deletions(-) create mode 100644 Companion/Decisions/V3/pre-compaction-index-lines-078-079.md create mode 100644 Companion/Decisions/compaction-2026-08-28-manifest.tsv diff --git a/Companion/Decisions/Active/adr-ios-038.md b/Companion/Decisions/Active/adr-ios-038.md index 3afe4f08..7b47901e 100644 --- a/Companion/Decisions/Active/adr-ios-038.md +++ b/Companion/Decisions/Active/adr-ios-038.md @@ -1,3 +1,9 @@ + +> **Current routing note:** The preserved demo-mode design below names +> `registerAlarmsWithPushWorker` and `TaskEvaluationService.evaluate`. Both symbols were deleted +> with the scheduled-task feature; see ADR-IOS-079. Their guard pattern still applies to any future +> KB-reading background job: demo data must not overwrite real execution state or registrations. + ## ADR-IOS-038: Demo Mode — Custom JWT + Local Mock Provider + Pre-Baked AI Cache @@ -190,12 +196,9 @@ fix gates at shared chokepoints, not per-tool patches: - In-flight refinements that complete DURING demo are dropped at their save sites (`KBRefinementService`, `AIPromptLearning`) — else the real refined KB/action text would be spliced into the demo overlay (visible - in a recording). *(Historical: `registerAlarmsWithPushWorker` + - `TaskEvaluationService.evaluate` were demo-guarded for the same reason — - an empty demo KB would GC real task execution state / clobber wake - registrations. Both symbols were deleted with the scheduled-task feature; - see ADR-IOS-079. The guard pattern they illustrate still applies to any - future KB-reading background job.)* + in a recording). `registerAlarmsWithPushWorker` + + `TaskEvaluationService.evaluate` are demo-guarded (empty demo KB would + GC real task execution state / clobber alarm registrations). - `DisabledRemindersStore` RMW ops capture `activeKeyV2` once (read+write same key even if the mode flips mid-operation). - `DemoSeed.wipe` also deletes `draft` rows (demo compose autosaves). diff --git a/Companion/Decisions/V3/manifest.tsv b/Companion/Decisions/V3/manifest.tsv index 0e156fea..edbc4b18 100644 --- a/Companion/Decisions/V3/manifest.tsv +++ b/Companion/Decisions/V3/manifest.tsv @@ -7,3 +7,4 @@ order source_rev status source_lines sha256 path title 5 508e0e4682116f4c03c95da48981e4d2bef2df03 active 493-555 bdb2833bc45817b942f043d577cc4f6f55f623bef49911e6d5a1a0620be16852 Companion/Decisions/V3/Active/adr-ios-071.md ADR-IOS-071: No Backward Compatibility for the Action Queue 6 508e0e4682116f4c03c95da48981e4d2bef2df03 active 556-667 b6a8d2e4ab098edc81e037c8f9aea3029716425b13b5077f6f926e90a6a29d62 Companion/Decisions/V3/Active/adr-ios-072.md ADR-IOS-072: Content Is Addressed by the Message It Belongs To, Never by the Slot It Occupies 7 b0f628a92 historical 148-149 fd4d0e0818471f89641c282cbe48565f24270b8a37b22fc5c7b20405527e946c Companion/Decisions/V3/pre-compaction-index-lines.md Pre-compaction catalog bullets — DECISIONS.md v3 records (2026-08-13 companion-compact, 2 bullets) +8 8577bcb9c historical 150-151 de9e6dc550f86353f1e87334c0637a5a130d1a28d4aa8f64a2ecade31f625fc3 Companion/Decisions/V3/pre-compaction-index-lines-078-079.md Pre-compaction catalog bullets — ADR-IOS-078 and ADR-IOS-079 (2026-08-28 companion-compact) diff --git a/Companion/Decisions/V3/pre-compaction-index-lines-078-079.md b/Companion/Decisions/V3/pre-compaction-index-lines-078-079.md new file mode 100644 index 00000000..5a67801f --- /dev/null +++ b/Companion/Decisions/V3/pre-compaction-index-lines-078-079.md @@ -0,0 +1,32 @@ +# Pre-compaction catalog bullets — ADR-IOS-078 and ADR-IOS-079 + +**Status:** Historical (preserved source text) · **Routed:** 2026-08-28 `companion-compact` · +**Source:** `tabmail-ios/DECISIONS.md` at `8577bcb9c` + +These two catalog bullets had become second copies of their linked ADR bodies. The compact +`DECISIONS.md` lines retain the status, the discriminating policy boundary, and the symbols needed +for search; the normative records remain ADR-IOS-078 and ADR-IOS-079. The original catalog bytes +are preserved below so no prior citation or search term is lost. + +The bullets are fenced because their links are relative to `DECISIONS.md`; the companion verifier +ignores links inside code fences, preserving the source bytes without rewriting their paths. + +## Source line 150 — `ADR-IOS-078` + + + +```text +- **[ADR-IOS-078](Companion/Decisions/V3/Active/adr-ios-078.md)** — Active. **The newest-100 window bounds SYNC-ORIGIN processing only — existing AI content is NEVER gated from display** (owner, 2026-08-19): summary bubble renders any existing summary in EVERY folder (no window check, no inbox check — `v1.7.9`'s inbox display gate is removed, not restored); action pill/tag buttons stay inbox-membership-only (`ActionTagDisplay.displayedTag`, no window gating). ⛔ `ActiveAIQueue.recentInboxWindowContains` bounds **sync-origin admission + the repopulation sweep ONLY** — manual open, push/NSE merge and moved-into-inbox are window-EXEMPT (`AIJob.windowExempt`, pathway regating, owner directive); **never re-gate an exempt producer to "restore" a global bound.** The `7a31f1d22`/`v1.7.11` display gate + suppression notice were designed in error (`MIS-IOS-018`). Delta sync stays gated, so a message another client moves into the Inbox keeps its INTERNALDATE and may get no automatic summary until opened — accepted (#68). +``` + + + +## Source line 151 — `ADR-IOS-079` + + + +```text +- **[ADR-IOS-079](Companion/Decisions/V3/Active/adr-ios-079.md)** — Active. **Scheduled tasks are DELETED from iOS; Thunderbird keeps them.** Background execution and wake-up pushes are not guaranteed here, so `TaskEvaluationService` / `TaskScheduler` / `TaskExecutionCache` / `KBTaskParser` / `ScheduledTasksSettingsView` / `TaskAddTool`+`TaskDelTool`+`TaskEditTool` / `PushClient.registerAlarms` / the NSE `task_alarm` route are gone, and the engine no longer starts. ⛔ **Do NOT extend this to the desktop side:** `[Task]` KB lines, the `kb` sync field and the unattended prompt tier are Thunderbird's live feature input and are untouched — never write code that strips or migrates `[Task]` prose. **`SyncField.taskCache` is GONE too** (case, `CodingKeys`, property, decode, entry type) — safe because a `KeyedDecodingContainer` never reads an undeclared key, so a desktop payload carrying it still decodes, and the desktop gates its merge on `undefined`, so omitting the key skips it; `PromptStateDataUnknownFieldTests` pins *an undeclared key is ignored*. `"task_result"` chat turns **no longer render** (display predicate only — rows stay, no migration). **KEEPS:** `disabledReminders` incl. `t:` hashes — and `gcStaleEntries` now SKIPS every `t:` hash unconditionally, because GC may only collect namespaces this device can re-derive (absent = enabled, Device Sync retains nothing, so collecting the surviving copy loses the user's disable); the `nse_pending_task_result` `CREATE TABLE` (producer+consumer deleted, no cleanup migration); the `Reminder` struct's now-always-nil schedule fields. **User-visible loss:** a Thunderbird-created task no longer fires on iPhone. +``` + + diff --git a/Companion/Decisions/compaction-2026-08-28-manifest.tsv b/Companion/Decisions/compaction-2026-08-28-manifest.tsv new file mode 100644 index 00000000..273d7fc0 --- /dev/null +++ b/Companion/Decisions/compaction-2026-08-28-manifest.tsv @@ -0,0 +1,6 @@ +# companion-compact manifest — tabmail-ios / Decisions tree (2026-08-28 pass) +# Source: DECISIONS.md at 8577bcb9c BEFORE this pass (26422 B, sha256 b4f21821c3c1ea2e1bd6067af4f1044045cd19265f02b7b3b07f9664a1da2ca2) +# CONTENT DELETED: none. Every row is a byte-exact catalog bullet moved into the route target; DECISIONS.md retains a short searchable link. +fragment_id route_target index_line bytes sha256 +ADR-IOS-078 Companion/Decisions/V3/pre-compaction-index-lines-078-079.md 150 1037 c68b8f1cb8d7f7f773cfd8b5994b9de5a6671d6d6a10c7fc3cc27f628286e8ed +ADR-IOS-079 Companion/Decisions/V3/pre-compaction-index-lines-078-079.md 151 1689 0124a5c820d1441b1bd7df43de9ca02bc673148987b3b09a52bfe4c81dd88f44 diff --git a/Companion/Memory/Current/075-cron-reminders-scheduleditem-architecture.md b/Companion/Memory/Current/075-cron-reminders-scheduleditem-architecture.md index 20b70d93..c3965c32 100644 --- a/Companion/Memory/Current/075-cron-reminders-scheduleditem-architecture.md +++ b/Companion/Memory/Current/075-cron-reminders-scheduleditem-architecture.md @@ -1,11 +1,12 @@ - -### Cron Reminders (ScheduledItem Architecture) - -> ⚠️ **Historical for iOS.** This describes the feature under its earlier `Cron` naming; it was + +> **Current routing note:** ⚠️ **Historical for iOS.** This describes the feature under its earlier `Cron` naming; it was > later renamed `Task`, and **every symbol named below (`KBCronParser`, `CronScheduler`, > `CronExecutionCache`, `cronCache`, `cron_add`) is absent from the tree.** The iOS side of the > feature was then deleted outright — see ADR-IOS-079. Thunderbird still runs it. Read this for > the shared design shape only; do not treat any iOS claim here as live. + + +### Cron Reminders (ScheduledItem Architecture) - **Crons are a subclass of reminders** in the architecture. Both flow through the same unified builder (`ReminderBuilder` / `reminderBuilder.js`), the same disable/enable store (`DisabledRemindersStore` with `c:` hash prefix for crons), and the same Device Sync fields. - **`[Cron]` KB format**: `[Cron] Schedule [], ` — stored in KB text, synced via Device Sync KB field, programmatically protected from LLM rewriting on the backend (`splitKbEntries` + `isProtectedEntry`) diff --git a/DECISIONS.md b/DECISIONS.md index 328a1a3e..bc3779aa 100644 --- a/DECISIONS.md +++ b/DECISIONS.md @@ -147,5 +147,5 @@ These records were authored after `v1.6.38`, so the pinned compaction has no byt - **[ADR-IOS-075](Companion/Decisions/V3/Active/adr-ios-075.md)** — Active. Body processing reports success or confirmed-empty only when the corresponding cache transaction committed; write aborts stay retryable. - **[ADR-IOS-076](Companion/Decisions/V3/Active/adr-ios-076.md)** — Active. ⚠️ **PARTIALLY IMPLEMENTED.** The message document is untrusted content, enforced at the WebKit boundary: `allowsContentJavaScript = false` + the 12-directive `` CSP in `EmailHTMLWrapper.contentSecurityPolicy`; a per-load main-frame navigation permit keyed to an unguessable nonce (`RenderNavigationPolicy`, `RenderDocumentURL`, default-deny `decidePolicyFor`, `metaRefreshIsRefusedByTheProductionCoordinator`); an `http`/`https` allowlist before `UIApplication.shared.open` (`RenderLinkPolicy`); Swift-side bridge validation (`RenderBridgeInput`); `.eml` path traversal (`tabmail-asset`, `BodyAssetSchemeHandler`); deferred-image withholding for `hiddenByViewMode`; and a diagnostic-only `imageLoadFailure` census with no banner. ⚠️ **FOUR owner REVERSALS are registered exceptions, not defects** — `dataDetectorTypes` (`IOS-UI-002`), `allowsLinkPreview` (`IOS-UI-003`), the per-view `nonPersistent()` store (`IOS-PRIVACY-001`, T5 OPEN — one cookie jar across every sender), `font-src 'none'` → `https:` (`IOS-PRIVACY-002`); see also `IOS-PRIVACY-003`. P1d (asset-ownership/view-identity binding) is still spec only, and P1c does not stop same-document `location.hash`/`history.pushState`. `WKWebView` exposes no exact `` ATS error or supported per-resource timeout, so no security-specific notice or timing heuristic is shipped. **Do not cite this ADR as evidence that an unshipped decision is closed — re-derive status from `git log`, not from its status paragraph.** Pre-compaction bullet, byte-for-byte: [pre-compaction-index-lines.md](Companion/Decisions/V3/pre-compaction-index-lines.md). - **[ADR-IOS-077](Companion/Decisions/V3/Active/adr-ios-077.md)** — Active. Hostile attachment filenames are **REJECTED, not reduced** (`c35cfdca2`, net −476): one shared `AttachmentFilename.isSafeFileComponent` predicate, throw before `createDirectory` on save and refuse before the fetch on download, generic `"Unsupported file name"` for all six rules. Reducer + co-edit twin DELETED — all five confirmed defects lived in the *transformation*, none in the classification. ⚠️ **Rejecting at save does NOT make the loaders safe** — `metaBase`/`afterIndexPrefix` stay load-bearing; type-spoof is bounded, not closed; the combining test is `ccc != 0` on NFD, **not** category `Mn`/`Mc`/`Me`. ⚠️ **Consequence 5 retracts the MIGRATION GUARANTEE — there was never a reducer to migrate FROM** (`v1.7.6`/`v1.7.7`/`v1.7.8` write the name verbatim, so legacy on-disk names are RAW sender-authored; stranded set = refused ∩ writable-by-v1.7.8, 3 narrow shapes). `IOS-ATTACH-001` — forward-only by owner verdict: **no migration, rename-on-load or grandfathering path.** Pre-compaction bullet, byte-for-byte: [pre-compaction-index-lines.md](Companion/Decisions/V3/pre-compaction-index-lines.md). -- **[ADR-IOS-078](Companion/Decisions/V3/Active/adr-ios-078.md)** — Active. **The newest-100 window bounds SYNC-ORIGIN processing only — existing AI content is NEVER gated from display** (owner, 2026-08-19): summary bubble renders any existing summary in EVERY folder (no window check, no inbox check — `v1.7.9`'s inbox display gate is removed, not restored); action pill/tag buttons stay inbox-membership-only (`ActionTagDisplay.displayedTag`, no window gating). ⛔ `ActiveAIQueue.recentInboxWindowContains` bounds **sync-origin admission + the repopulation sweep ONLY** — manual open, push/NSE merge and moved-into-inbox are window-EXEMPT (`AIJob.windowExempt`, pathway regating, owner directive); **never re-gate an exempt producer to "restore" a global bound.** The `7a31f1d22`/`v1.7.11` display gate + suppression notice were designed in error (`MIS-IOS-018`). Delta sync stays gated, so a message another client moves into the Inbox keeps its INTERNALDATE and may get no automatic summary until opened — accepted (#68). -- **[ADR-IOS-079](Companion/Decisions/V3/Active/adr-ios-079.md)** — Active. **Scheduled tasks are DELETED from iOS; Thunderbird keeps them.** Background execution and wake-up pushes are not guaranteed here, so `TaskEvaluationService` / `TaskScheduler` / `TaskExecutionCache` / `KBTaskParser` / `ScheduledTasksSettingsView` / `TaskAddTool`+`TaskDelTool`+`TaskEditTool` / `PushClient.registerAlarms` / the NSE `task_alarm` route are gone, and the engine no longer starts. ⛔ **Do NOT extend this to the desktop side:** `[Task]` KB lines, the `kb` sync field and the unattended prompt tier are Thunderbird's live feature input and are untouched — never write code that strips or migrates `[Task]` prose. **`SyncField.taskCache` is GONE too** (case, `CodingKeys`, property, decode, entry type) — safe because a `KeyedDecodingContainer` never reads an undeclared key, so a desktop payload carrying it still decodes, and the desktop gates its merge on `undefined`, so omitting the key skips it; `PromptStateDataUnknownFieldTests` pins *an undeclared key is ignored*. `"task_result"` chat turns **no longer render** (display predicate only — rows stay, no migration). **KEEPS:** `disabledReminders` incl. `t:` hashes — and `gcStaleEntries` now SKIPS every `t:` hash unconditionally, because GC may only collect namespaces this device can re-derive (absent = enabled, Device Sync retains nothing, so collecting the surviving copy loses the user's disable); the `nse_pending_task_result` `CREATE TABLE` (producer+consumer deleted, no cleanup migration); the `Reminder` struct's now-always-nil schedule fields. **User-visible loss:** a Thunderbird-created task no longer fires on iPhone. +- **[ADR-IOS-078](Companion/Decisions/V3/Active/adr-ios-078.md)** — Active. Newest-100 bounds sync-origin AI processing only; existing summaries always display, while action tags remain Inbox-only. `ActiveAIQueue.recentInboxWindowContains`, `AIJob.windowExempt`, `MIS-IOS-018`, #68. [Prior catalog wording](Companion/Decisions/V3/pre-compaction-index-lines-078-079.md#source-line-150--adr-ios-078) +- **[ADR-IOS-079](Companion/Decisions/V3/Active/adr-ios-079.md)** — Active. Scheduled tasks and `taskCache` are deleted from iOS, remain live on Thunderbird; `[Task]` prose and `disabledReminders` `t:` hashes are retained. [Prior catalog wording](Companion/Decisions/V3/pre-compaction-index-lines-078-079.md#source-line-151--adr-ios-079)