diff --git a/Companion/Decisions/Active/adr-ios-038.md b/Companion/Decisions/Active/adr-ios-038.md index 3afe4f0..7b47901 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 0e156fe..edbc4b1 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 0000000..5a67801 --- /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 0000000..273d7fc --- /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 20b70d9..c3965c3 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/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 0000000..3ff495c --- /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 e577b65..2d28113 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 cf167c2..593b8ae 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/DECISIONS.md b/DECISIONS.md index 328a1a3..bc3779a 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) diff --git a/PROJECT_MEMORY.md b/PROJECT_MEMORY.md index 5c7177a..c051a5a 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 067641d..dcfcf36 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 509e2cd..596e17c 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 0000000..a10cbaa --- /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 effbb77..d3a9287 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 d11ccf1..f831877 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 fc16178..5a54dc8 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 06a62a7..f46a6b3 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 51f2eda..5004e79 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 cee0689..91342b6 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 a766c8d..fbb234e 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 369523d..7c23908 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 c625e3c..619e176 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 0000000..e1f8d5c --- /dev/null +++ b/TabMailTests/Services/AppLogStoreTests.swift @@ -0,0 +1,1603 @@ +/* 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() + } + + 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") + 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 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. + // `legacyLogNamesAreMigrationOnly` covers that production path. + let names = try fileNames(in: url.deletingLastPathComponent()) + #expect(names == [url.lastPathComponent], + "a sibling log file was created: \(names)") + } + } + } + + @Test("The named writers land in the shared override and open no sibling there") + 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. `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)") + } + } + } + + @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 + 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 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 + // `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 from this test is a complete physical + // LINE: the trim + // advances past the first partial line rather than slicing one in + // 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 + // 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) + where line.contains("entry_") { + #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 371a257..6a1cbc1 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 a3fd154..09d8455 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 c51e524..9d567e6 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)) + } }