Skip to content

Consolidate the main app's diagnostic logs into one file - #86

Draft
tabmail-kmyi wants to merge 1 commit into
mainfrom
fix/issue-83-single-log-file
Draft

Consolidate the main app's diagnostic logs into one file#86
tabmail-kmyi wants to merge 1 commit into
mainfrom
fix/issue-83-single-log-file

Conversation

@tabmail-kmyi

@tabmail-kmyi tabmail-kmyi commented Aug 25, 2026

Copy link
Copy Markdown
Contributor

Closes #83.

What changed

The main app wrote fifteen persistent log 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. (Thirteen were byte-capped; device_sync.log used a 300-line ring and auth_diagnostics.log a 50-entry ring, neither of which bounds a single large message.)

There are now two persistent log files, one per process:

process file owner
main app tabmail.log (Application Support / TabMail) new AppLogStore
notification service extension nse.log (App Group container) NSELogStore, unchanged

Every entry is [<ISO8601>] [<TAG>] <message>, where the tag is an AppLogChannel case.

Why one file

The failures worth diagnosing cross subsystems — a stalled backfill that surfaces as an inbox reload storm, a push landing while a BG refresh holds the database, an AI queue starving behind a sync error. With per-subsystem files you had to export several and re-interleave them by hand from their timestamps, and any file you forgot was silently absent rather than visibly empty. All writers share one serial queue onto one file, so a single export carries every subsystem interleaved in append order. Append order, not call order — the timestamp is captured on the caller's thread, so a writer preempted before it reaches the queue lands after one that stamped later and the timestamps can read as decreasing. Line order is the oracle.

The Debug menu's Logs section is now App Logs + NSE Logs in place of thirteen per-subsystem buttons plus NSE. The separate "Stuck Message Report" button keeps its own section and is not one of the thirteen removed — but its readLog/clearLog closures were repointed at the shared store (AppLogStore.read(channel:.stuckDiag) / clear(channel:.stuckDiag)), so it is repointed, not untouched. Separability is kept where it was used: AppLogStore.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.

Legacy files are removed once at launch

Consolidation orphans the fifteen files it replaces: 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, and SyncEngine.runPruneIfOverBudget responds to isOverBudget() by deleting MessageBody and header rows — so orphaned log bytes can buy their own size in pruned mail. ⚠️ Conditionally, not categorically: isOverBudget() is budgetMB != Int.max && totalSizeMB() >= budgetMB and defaultBudgetMB == Int.max, so this bites only once a user has configured a finite storage budget and usage reaches it. For everyone else the orphans are dead weight rather than a cause of deletion. Five of the fifteen are written in production builds, where the Debug menu sits behind a debug unlock and no user gesture could reach them at all.

StartupMigrations.deleteLegacyLogFiles removes them once, keyed on didDeleteLegacyLogFiles_v1. It:

  • names the fifteen files explicitly and never enumerates the directory — a widened pattern would eat tabmail.log itself;
  • uses unlink(2) rather than FileManager.removeItem — one syscall with no check/use window between deciding and acting, and one that can never recurse, so a directory bearing a legacy name cannot be deleted along with its contents;
  • classifies a failed unlink with lstat(2), so only a real directory entry counts as the deliberate permanent skip — a symlink whose unlink failed is a failure and is retried. (Spelled with lstat rather than URL.resourceValues as a behaviour-preserving simplification: .isDirectoryKey does not follow symlinks either, which is not plainly documented and is recorded at the call site.);
  • isolates each name's failure, so one undeletable file cannot strand the fourteen others, and counts an error it cannot classify as a failure rather than as a clean skip;
  • arms the one-shot flag only after a fully clean pass, so a transient obstruction self-heals on the next launch — this is not a promise about a permanently undeletable file, which would leave the pass unarmed at a cost of fifteen unlink syscalls, fourteen returning ENOENT;
  • is deliberately not in resetFlagKeys, which arms the "Updating…" splash — unlinking fifteen small files is not splash-worthy.

One shared file means one entry can cost every channel

trimTail keeps the last keepBytes and then advances past the first newline in that tail. An entry whose only newline is its own terminal byte therefore left nothing, and the rewrite replaced the whole log with an empty file — a routine size trim destroying every channel's history at once. Two independent guards now close that:

  • AppLogStore.append truncates a message at maxEntryScalars (64 Ki), at the store boundary, so it covers all fifteen façades rather than only the one that bounds its own spans. Scalars, not Characters — prefix(n) counts extended grapheme clusters, so one "a" carrying thousands of combining marks defeats a Character cap.
  • trimTail refuses to replace a non-empty log with empty content, unconditionally and without inspecting why the tail came out empty. Keeping an untrimmed file is strictly better than deleting it, and it self-corrects on the next append.

They are deliberately redundant with each other and with logChatError's own caps.

Reads are serialized, not merely drained

read() and clear(channel:) previously drained the queue with a barrier and then decoded outside it. A barrier only proves the writes queued before it have landed; an append queued after it ran concurrently with the decode, so an export could observe a half-written entry or a split UTF-8 scalar. The decode now happens inside the queue, which removes the window and removes the separate flush helper.

What did NOT change

  • The always-on vs debug-gated split is identical (IOS-LOG-002). BackgroundSyncLogger.log / .logError / .logChatError, DeviceSyncLogger.log and AuthDiagnostics.log still persist in production; every other channel keeps its guard DebugModeManager.isLoggingEnabled() else { return }, which gates the print as well as the disk write. AppLogStore.append never gates — the caller still owns that decision.
  • No BackgroundSyncLogger log-emission call site was added, removed or re-worded.
  • No pre-existing stdout print site was changedIOS-LOG-001 and IOS-LOG-003 still own that corpus. Two new console sites were added, both in the migration and both debug-gated per rule 12; the corpus grew from 11 to 13 rather than staying fixed.
  • No NSE code path changed. NSELogStore's synchronous append (the process can be hard-killed at any instant) and its in-place-truncate clear are unchanged — AppLogStore's async queue is correct only for the main app. Its one modified line is a doc-comment cross-reference, BackgroundSyncLogger.trimTailAppLogStore.trimTail, following that symbol's move.

Line forgery, which one shared file makes cross-channel

logChatError is always-on and is the one writer that takes literal user-typed text. It now bounds and escapes both of its spans inside the façade rather than at each call site. Order matters in both directions: capping after escaping slices a generated escape sequence in half and renders as text the user never typed, while escaping without a bound collapses a multi-line message onto one physical line — and an entry whose only newline is its terminal one is exactly the shape that used to make trimTail rewrite the file to nothing. The store's two guards above now stop that independently of this façade; this bound is the tightest of the three, not the only one. The bound is over unicode scalars, not Characters, because prefix(100) counts extended grapheme clusters, so one "a" carrying thousands of combining marks passes a Character cap intact.

AppLogStore.append still accepts an unbounded message on every other channel — this is closed for logChatError, not in general.

Deliberate behaviour changes

  • Retention is no longer isolated per channel. One 32 MB cap trimmed back to 16 MB replaces thirteen independent 16 MB budgets, a 300-line device_sync ring and a 50-entry auth ring. A noisy channel can now evict another's entries, including always-on [ERROR] and [AUTH] ones. Accepted: this is diagnostics, and per-channel floors are not worth the machinery.
  • AuthDiagnostics gained a UI route it never had. It already had a readLog(), but nothing called it — its doc comment named a "Settings > Maintenance > Auth Diagnostics" row that does not exist in the tree — so its entries were written and unreachable. They are now in the single App Logs export.
  • AuthDiagnostics entries are now destroyed by "Clear All Logs". It previously had no clear function and was absent from DebugLogView, so its entries were immune to every clear surface.
  • AuthDiagnostics writes asynchronously. It previously completed a synchronous atomic write on the caller's thread, including from TabMailApp.init on MainActor. Unblocking launch is the better trade; the cost is a tail entry lost to termination, documented on AuthDiagnostics.log's own declaration. Its four call sites in TabMailApp are unchanged and are not in this diff.

Accepted limitations

  • entryTag validates the tag against AppLogChannel and requires a delimiter after it, but does not validate the timestamp — date-parsing every physical line of a 32 MB file is not worth it. [junk] [SYNC] forged parses as SYNC.
  • Cross-channel line forgery is closed for logChatError only. The other fourteen façades, and AppLogStore.append itself, still pass their message through unescaped, so a raw newline in any of them still produces a physical line that another channel's filtered read will claim, truncates the originating channel's read at that point, and survives that channel's clear. The raw-newline caveat itself is inherited, not introduced — call sites must still pass such values through DebugModeManager.escapedForLogLine — but consolidation is what made the consequence cross-channel. Registered deliberately: this is diagnostics on the user's own device. Continuation lines are attributed to the entry above them, which is what logChatError's deliberate two-line entry needs.
  • Some added tests are weaker than their titles suggest, and are recorded rather than hardened here. The dual-write test cannot observe a façade that also writes an absolute legacy path outside the redirected directory; the console-gating test is a lexical scan rather than an injected sink; the concurrency test is probabilistic rather than a pinned mutual-exclusion seam.
  • Running a pre-consolidation build after the cleanup has run recreates a legacy file that the armed one-shot flag will not remove again, and "Clear All Logs" does not cover it.
  • trimTail can discard one whole entry more than it needs to. When size - keepBytes lands exactly on an entry boundary, the retained tail already starts at a complete entry and the unconditional "advance past the first newline" drops it anyway. Byte-identical to v1.7.14, so consolidation neither introduced nor widened it, and deliberately left: the unconditional form can never leave half a line behind, and one extra entry out of a 16 MB retained tail of diagnostics is cheaper than the conditional that would avoid it.
  • The cleanup trusts the container directory, and guards only the final path components. unlink resolves symlinks in the parent path, so the lstat classification protects the fifteen names, not the directory holding them. Not fixed: nothing in the app creates that symlink, anyone who could plant it already has arbitrary write access to the container, and v1.7.14 extended the identical trust — all fifteen loggers resolved the same parent on every write.

Tests

New coverage pins that every façade's entries land in the one file; per-channel filtering and clearing across every AppLogChannel case, including a leading orphan continuation left by a trim; the always-on vs debug-gated classification, derived from allCases so a new channel cannot slip in unclassified; that every debug-gated writer gates its console output as well as its file write; that concurrent writers across channels leave every line parseable and every write present exactly once; that consecutive appends leave no blank line between entries; that one oversized newline-free entry leaves the log untrimmed instead of erasing it; that the store bounds an entry from a writer which bounds nothing itself; logChatError's privacy cap on ordinary text and its cap-before-escape ordering; ISO8601 timestamps; empty- and missing-file placeholders; and the legacy cleanup's one-shot, never-recursing, failure-isolating behaviour, including a symlink-to-directory whose unlink fails. Every test guarding changed behaviour was confirmed to fail against that behaviour's pre-change form, by inverting the change and re-running it. The symlink test is a deliberate exception: it pins the invariant that an entry whose unlink failed counts as a failure, and both spellings of that classification satisfy it.

The trim tests drive the boundary through test-only overrides rather than writing 32 MB; a separate test pins the production 32/16 MB constants themselves.

Routed documentation

Consolidation falsifies references in eight routed Companion/ files that this change does not otherwise touch, and which name the per-subsystem log files, the removed share buttons, or BackgroundSyncLogger.trimTail as current. Five of those eight are hash-pinned bodies whose only sanctioned edit is a prepended COMPANION-CURRENT-NOTE wrapper — amending one without that wrapper is the operation with a long recurrence history of aborting Scripts/compact_companion_docs.rb verify. They are therefore corrected in one place, as a closed list in the topic that registers this change, naming every dead artifact literally so a search for one returns the stale sentence and its correction in the same result set. The known-issues verifier exits 0; the companion-docs verifier reconstructs both source documents byte-identically with every hash, census and routing check green. Its two link checks exit non-zero on pre-existing references to the monorepo-root tree above this checkout — untouched here, and satisfied when the checkout's parent is that root.

The main app wrote fifteen persistent log files — background_sync, error,
chat_error, bg_app_refresh, bg_processing, ai_processing, push, backfill_ai,
backfill, inbox, boot, body_render and stuck_messages (BackgroundSyncLogger),
plus device_sync (DeviceSyncLogger) and auth_diagnostics (AuthDiagnostics) —
each with its own retention policy and its own reader — thirteen byte-capped,
a 300-line device_sync ring and a 50-entry auth ring, neither of which bounds
a single large message. Diagnosing anything that crossed two subsystems meant
exporting several files and re-interleaving them by hand from their
timestamps, and a file the reporter forgot was silently absent rather than
visibly empty.

There are now two persistent log files, one per process: tabmail.log for the
main app (new AppLogStore) and nse.log for the notification service extension,
whose behaviour is unchanged. Every entry is `[ISO8601] [TAG] message`, and
because every writer goes through one serial queue onto one file, a single
export carries every subsystem interleaved in append order — the one thing a
per-channel file cannot express. Append order, not call order: the timestamp
is captured on the caller's thread, so a writer preempted before it reaches
the queue lands after one that stamped later and the timestamps can even read
as decreasing. Line order is the oracle, not the timestamp.
AppLogStore.read(channel:) filters back to one subsystem and clear(channel:)
drops one channel's entries while preserving the rest, which is what
StuckMessageDiagnostics needs when it clears its own channel before a scan.
The Debug menu's Logs section is App Logs plus NSE Logs instead of thirteen
per-subsystem buttons plus NSE; the Stuck Message Report button keeps its own
section and is not one of the thirteen, though its read/clear closures are
repointed at the shared store.

Consolidation orphans the fifteen files it replaces. Left in place they are
unreadable, unclearable, and counted: StorageEstimator.totalSizeMB() measures
Application Support recursively, and SyncEngine.runPruneIfOverBudget answers
isOverBudget() by deleting MessageBody and header rows — so orphaned log bytes
can buy their own size in pruned mail. That is conditional, not categorical:
isOverBudget() is `budgetMB != Int.max && totalSizeMB() >= budgetMB` and
defaultBudgetMB is Int.max, so it bites only once a user has configured a
finite budget and usage reaches it. Five of the fifteen are written in
production builds, where the Debug menu is behind a debug unlock and no user
gesture could reach them.

StartupMigrations.deleteLegacyLogFiles removes them once, keyed on
didDeleteLegacyLogFiles_v1. It names the fifteen explicitly and never
enumerates the directory, since a widened pattern would eat tabmail.log
itself. It uses unlink(2) rather than FileManager.removeItem: one syscall with
no check/use window between deciding and acting, and one that can never
recurse, so a directory bearing a legacy name cannot be deleted with its
contents. When unlink fails it classifies the entry with lstat(2), so only a
real directory entry counts as the deliberate permanent skip and a symlink
whose unlink failed is a failure that is retried. That classification is
spelled with lstat rather than URL.resourceValues as a behaviour-preserving
simplification, not a fix: Foundation's isDirectoryKey does not follow
symlinks either, which the code comment records because it is not plainly
documented and had to be established empirically. Each name's failure is
isolated so one undeletable file cannot strand the other fourteen, and an
error that cannot be classified counts as a failure rather than a clean skip.
The one-shot flag is armed only after a fully clean pass, which makes a
transient obstruction self-heal on the next launch; it is not a promise about
a permanently undeletable file, which keeps the pass unarmed at a cost of
fifteen unlink syscalls, fourteen returning ENOENT. The flag is deliberately
absent from resetFlagKeys, which arms the "Updating…" splash.

One shared file means one entry can cost every channel's history, so size is
bounded at the store: AppLogStore.append truncates a message at
maxEntryScalars, and trimTail refuses to replace a non-empty log with an empty
file. Both matter. trimTail keeps the last keepBytes and then advances past
the first newline in that tail, so an entry whose only newline is its own
terminal byte previously left nothing and the rewrite erased the file — a
routine size trim destroying every channel at once. The bound is over unicode
scalars rather than Characters because prefix(n) counts extended grapheme
clusters, so one "a" carrying thousands of combining marks defeats a Character
cap. The two guards are deliberately redundant with each other and with
logChatError's own caps.

Reads and clears now run inside the serial queue rather than after a drain
barrier. A barrier only proves the writes queued before it have landed; an
append queued after it ran concurrently with the decode, so an export could
observe a half-written entry or a split UTF-8 scalar. Doing the decode inside
the queue removes that window and removes the separate flush helper.

logChatError additionally bounds and escapes both of its spans inside the
façade rather than at each call site, because it is always-on and is the one
writer that takes literal user-typed text. Order matters in both directions:
capping after escaping slices a generated escape sequence in half and renders
as text the user never typed, while escaping without a bound collapses a
multi-line message onto one physical line. Its prefix(100) on the user span is
a privacy bound, not a size bound, and the two do not substitute for each
other.

Invariant impact: the always-on versus debug-gated split registered by
IOS-LOG-002 is unchanged. BackgroundSyncLogger.log/logError/logChatError,
DeviceSyncLogger.log and AuthDiagnostics.log still persist in production;
every other channel keeps its `guard DebugModeManager.isLoggingEnabled()`,
which gates the print as well as the disk write. AppLogStore itself never
gates; the caller owns that decision. No BackgroundSyncLogger log-emission
call site was added, removed or re-worded — all 437
`BackgroundSyncLogger.log*(` sites are byte-identical to main. The 40-site
drop against main is entirely the per-file `read*Log(`/`clear*Log(` surface
this change removes. No pre-existing stdout print site was changed, and
IOS-LOG-001/IOS-LOG-003 still own that corpus; two new console sites were
added, both in the migration and both debug-gated per rule 12, taking it from
eleven to thirteen. The NSE keeps its synchronous append and in-place truncate
clear, which are correct for a process that can be hard-killed at any instant;
its one modified line is a doc-comment cross-reference following trimTail's
move.

Four behaviour changes are deliberate. Retention is no longer isolated per
channel: one 32 MB cap trimmed back to 16 MB replaces thirteen independent 16
MB budgets, a 300-line device_sync ring and a 50-entry auth ring, so a noisy
channel can now evict another's entries, including always-on ERROR and AUTH
ones. That is accepted for diagnostics rather than fixed with per-channel
floors. AuthDiagnostics gained a UI route it never had — it already had a
readLog(), but nothing called it and its doc comment named a Settings >
Maintenance row absent from the tree, so its entries were written and
unreachable rather than unreadable. Correspondingly they are now destroyed by
"Clear All Logs", which previously could not touch them. AuthDiagnostics also
writes asynchronously now instead of completing a synchronous atomic write on
the caller's thread, including from TabMailApp.init on MainActor; unblocking
launch is the better trade and the cost, a tail entry lost to termination, is
documented on its own declaration.

Verification: TEST BUILD SUCCEEDED from a clean derived-data tree with zero
errors and zero compiler warnings; the only diagnostic emitted is the
documented benign ExtractAppIntentsMetadata one. The full suite passes. New
tests pin that every façade's entries land in the one file, per-channel
filtering and clearing over every AppLogChannel case including a leading
orphan continuation left by a trim, the always-on versus debug-gated
classification derived from allCases so a new channel cannot slip in
unclassified, that every debug-gated writer gates its console output as well
as its file write, that concurrent writers across channels leave every line
parseable, that consecutive appends leave no blank line between entries, that
one oversized newline-free entry leaves the log untrimmed instead of erasing
it, that the store bounds an entry from a writer which bounds nothing itself,
logChatError's privacy cap on ordinary text and its cap-before-escape
ordering, ISO8601 timestamps, empty- and missing-file placeholders, and the
legacy cleanup's one-shot, never-recursing, failure-isolating behaviour
including a symlink-to-directory whose unlink fails. Every test guarding
changed behaviour was confirmed to fail against that behaviour's pre-change
form, by inverting the change and re-running it. The symlink test is the one
exception and deliberately so: it pins the invariant that an entry whose
unlink failed counts as a failure, and both the old and new spellings of that
classification satisfy it, so it stays green under inversion. The trim tests
drive the boundary through test-only overrides; a separate test pins the
production 32/16 MB constants themselves.

Accepted limitations: entryTag validates the tag against AppLogChannel and
requires a delimiter after it but does not validate the timestamp, so "[junk]
[SYNC] forged" parses as SYNC — date-parsing every physical line of a 32 MB
file is not worth it. Cross-channel line forgery is closed for logChatError
only; the other fourteen façades and AppLogStore.append pass their message
through unescaped, so a raw newline still yields a line another channel's
filtered read will claim and that channel's clear will not remove. The
raw-newline caveat is inherited, but consolidation is what made its
consequence cross-channel. Reading or clearing from the Debug menu still runs
on the calling thread, as it did before. Running a pre-consolidation build
after the cleanup has run recreates a legacy file that the armed flag will not
remove again, and "Clear All Logs" does not cover it. Some added tests are
deliberately weaker than their titles suggest and are recorded rather than
hardened here: the dual-write test cannot observe a facade that also writes an
absolute legacy path outside the redirected directory, the console-gating test
is a lexical scan rather than an injected sink, and the concurrency test is
probabilistic. Two further costs are registered rather than fixed, both
pre-existing rather than introduced here. trimTail can discard one whole entry
more than necessary when size - keepBytes lands exactly on an entry boundary;
the unconditional advance past the first newline is byte-identical to v1.7.14
and is kept because it can never leave half a line behind. And unlink resolves
symlinks in the parent path, so the lstat classification guards the fifteen
names rather than the directory holding them; nothing in the app creates such
a symlink, and v1.7.14 extended the same trust from all fifteen loggers on
every write.

Consolidation also falsifies references in eight routed Companion files that
this change does not otherwise touch, which name the per-subsystem log files,
the removed share buttons, or BackgroundSyncLogger.trimTail as current. Five
of those eight are hash-pinned bodies; the only sanctioned edit to one is a
prepended COMPANION-CURRENT-NOTE wrapper, which exact_body strips before
hashing, and amending such a body WITHOUT that wrapper is the operation
MIS-IOS-009 records. They are therefore corrected in one place — a closed list
in topic 122, naming every dead artifact literally so a search for one returns
the stale sentence and its correction together — rather than patched at eight
sites. The two routed files that register this change, topic 122 and
ios-log-002.md, name the same artifacts deliberately and carry their
corrections inline here. The known-issues verifier exits 0. The companion-docs
verifier reconstructs PROJECT_MEMORY.md and DECISIONS.md byte-identically and
passes its ADR-census, ported-decision, memory-routing and ported-topic
checks. Its two link checks exit non-zero on pre-existing references to the
monorepo-root tree above this checkout — untouched here, and satisfied when
the checkout's parent is that root.

Signed-off-by: Kwang Moo Yi <kmyi@tabmail.ai>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

Consolidate on-device error logger for debug builds

1 participant