feat(settings): log every persisted change with the stack that caused it

src/main/lib/ipc/registerSettingsHandlers.ts

@@ -329,8 +329,22 @@ export function registerSettingsHandlers(): void {
   ipcMain.handle('get-models-sections', () => buildModelsPayload())
   ipcMain.handle('get-media-sections', () => buildMediaSections())
 
-  ipcMain.handle('set-setting', (_event, key: string, value: unknown) => {
+  ipcMain.handle('set-setting', (event, key: string, value: unknown) => {
     recordIpcInvocation('set-setting', { key, value })
+    // The settings log's stack stops at this handler for anything a renderer asked for, so
+    // record WHICH renderer asked. Without it every renderer-driven write looks identical.
+    //
+    // Guarded: `getURL()` throws "Object has been destroyed" when the sender is torn down
+    // between `invoke` and dispatch — a popup closing right after a toggle does exactly that,
+    // and a diagnostic must never be the reason the write it describes is lost.
+    const origin = ((): string => {
+      try {
+        return event.sender.getURL() || '<no url>'
+      } catch {
+        return '<sender gone>'
+      }
+    })()
+    console.log(`Settings: set-setting ${JSON.stringify(key)} requested by ${origin}`)
     applySettingSet(key, value)
   })
 

src/main/settings.test.ts

@@ -702,6 +702,151 @@ describe('locked settings.json served from .bak (issue #1367)', () => {
   })
 })
 
+describe('persisted-write logging', () => {
+  const writeLines = (log: { mock: { calls: unknown[][] } }): string[] =>
+    log.mock.calls
+      .map((call) => String(call[0]))
+      .filter((line) => line.startsWith('Settings: wrote'))
+
+  it('names the key, the change, and the caller', () => {
+    fs.mkdirSync(path.dirname(settingsPath), { recursive: true })
+    fs.writeFileSync(settingsPath, JSON.stringify({ betaFeaturesEnabled: true }))
+    const log = vi.spyOn(console, 'log').mockImplementation(() => {})
+
+    settings.set('betaFeaturesEnabled', false)
+
+    const line = writeLines(log).find((l) => l.includes('betaFeaturesEnabled'))
+    expect(line, 'no write line logged for the key').toBeDefined()
+    expect(line).toContain('"betaFeaturesEnabled": true -> false')
+    // The point of the log: a stack, so an UNKNOWN writer is named. A per-call-site tag would
+    // only ever name the sites someone already thought to annotate. Asserted on the frame
+    // marker rather than on line count, which the format guarantees either way.
+    expect(line).toMatch(/\| via .*settings\.ts/)
+    log.mockRestore()
+  })
+
+  it('stays silent about a key whose value does not change', () => {
+    fs.mkdirSync(path.dirname(settingsPath), { recursive: true })
+    fs.writeFileSync(settingsPath, JSON.stringify({ betaFeaturesEnabled: true }))
+    const log = vi.spyOn(console, 'log').mockImplementation(() => {})
+
+    settings.set('betaFeaturesEnabled', true)
+
+    expect(writeLines(log).filter((l) => l.includes('betaFeaturesEnabled'))).toEqual([])
+    log.mockRestore()
+  })
+
+  it('reports a key being removed rather than going quiet', () => {
+    // `set(key, undefined)` deletes, and a deletion is what makes a later seed re-run and
+    // write a value nobody chose. A log that only reported value changes would catch the
+    // effect and miss the cause.
+    fs.mkdirSync(path.dirname(settingsPath), { recursive: true })
+    fs.writeFileSync(settingsPath, JSON.stringify({ betaFeaturesEnabled: true }))
+    const log = vi.spyOn(console, 'log').mockImplementation(() => {})
+
+    settings.set('betaFeaturesEnabled', undefined)
+
+    expect(writeLines(log).some((l) => l.includes('"betaFeaturesEnabled": true -> <unset>'))).toBe(
+      true
+    )
+    log.mockRestore()
+  })
+
+  it('logs a key the file gains for the first time', () => {
+    // The baseline is what was on DISK, not the defaults-merged view. Baselining from the
+    // merged object would hide every key a sparse file gains on its first real write — they
+    // are already present in a merged baseline — and "no line for key X" would stop meaning
+    // "X was not written", which is the only claim this log exists to support.
+    fs.mkdirSync(path.dirname(settingsPath), { recursive: true })
+    fs.writeFileSync(settingsPath, JSON.stringify({ betaFeaturesEnabled: true }))
+    const log = vi.spyOn(console, 'log').mockImplementation(() => {})
+
+    settings.set('telemetryEnabled', false)
+
+    // `installDir` is a default the sparse file above does not contain, so this write is the
+    // first time it reaches disk.
+    expect(writeLines(log).some((l) => l.includes('installDir'))).toBe(true)
+    log.mockRestore()
+  })
+
+  it('reports a stored null as null, not as absent', () => {
+    // `loadOutcome` strips `null`s the schema does not allow, so the baseline is taken before
+    // that. Otherwise a key stored as `null` reads as never-present and the line claims
+    // `<unset> -> value` — a log that restates the state it is attributing against.
+    fs.mkdirSync(path.dirname(settingsPath), { recursive: true })
+    fs.writeFileSync(settingsPath, JSON.stringify({ betaFeaturesEnabled: null }))
+    const log = vi.spyOn(console, 'log').mockImplementation(() => {})
+
+    settings.set('betaFeaturesEnabled', true)
+
+    const line = writeLines(log).find((l) => l.includes('betaFeaturesEnabled'))
+    expect(line).toContain('"betaFeaturesEnabled": null -> true')
+    log.mockRestore()
+  })
+
+  it('reports what reached disk, not what was in memory', () => {
+    // `JSON.stringify` turns NaN into null. Logging the in-memory object would report a value
+    // the file does not contain, in the one place that exists to say what reached disk.
+    fs.mkdirSync(path.dirname(settingsPath), { recursive: true })
+    fs.writeFileSync(settingsPath, JSON.stringify({ maxCachedDownloads: 1 }))
+    const log = vi.spyOn(console, 'log').mockImplementation(() => {})
+
+    settings.set('maxCachedDownloads', Number.NaN as unknown as number)
+
+    const line = writeLines(log).find((l) => l.includes('maxCachedDownloads'))
+    expect(line).toBeDefined()
+    expect(line).toContain('-> null')
+    expect(line).not.toContain('NaN')
+    log.mockRestore()
+  })
+
+  it('describes a string value by shape instead of printing it', () => {
+    // These lines land in `app.log`, which users attach to support requests. A path or a
+    // mirror host must not be disclosed just because it changed; the shape still answers
+    // "did this key change, and into what kind of thing".
+    fs.mkdirSync(path.dirname(settingsPath), { recursive: true })
+    fs.writeFileSync(settingsPath, JSON.stringify({ pypiMirror: 'https://old.example' }))
+    const log = vi.spyOn(console, 'log').mockImplementation(() => {})
+
+    settings.set('pypiMirror', 'https://user:hunter2@secret.example/simple')
+
+    const line = writeLines(log).find((l) => l.includes('pypiMirror'))
+    expect(line).toBeDefined()
+    expect(line).toContain('<string:')
+    expect(line).not.toContain('hunter2')
+    expect(line).not.toContain('secret.example')
+    log.mockRestore()
+  })
+
+  it('does not log a write that never reached disk', () => {
+    fs.mkdirSync(path.dirname(settingsPath), { recursive: true })
+    fs.writeFileSync(settingsPath, JSON.stringify({ betaFeaturesEnabled: true }))
+    const log = vi.spyOn(console, 'log').mockImplementation(() => {})
+    const realWrite = fs.writeFileSync.bind(fs) as typeof fs.writeFileSync
+    const write = vi.spyOn(fs, 'writeFileSync').mockImplementation(((
+      target: fs.PathOrFileDescriptor,
+      data: string | NodeJS.ArrayBufferView,
+      opts?: unknown
+    ) => {
+      if (String(target).startsWith(settingsPath)) throw new Error('fake ENOSPC')
+      return realWrite(target, data, opts as fs.WriteFileOptions)
+    }) as typeof fs.writeFileSync)
+
+    try {
+      settings.set('betaFeaturesEnabled', false)
+    } catch {
+      // The write failing is the point; whether it propagates is not what this pins.
+    } finally {
+      // Restored in a `finally`: a leaked write mock fails every later test in the file with
+      // this test's fake error, which is a confusing way to learn about a missing cleanup.
+      write.mockRestore()
+    }
+
+    expect(writeLines(log).filter((l) => l.includes('betaFeaturesEnabled'))).toEqual([])
+    log.mockRestore()
+  })
+})
+
 // The beta-features toggle is the gate for injecting core beta launch args.
 // It is deliberately NOT telemetry consent: gating on consent creates a trap
 // where a user hitting beta bugs escapes by disabling telemetry, killing the

src/main/settings.ts

@@ -463,13 +463,19 @@ function load(): Settings {
  *  content is unknown, so saving anything derived from the stand-in would
  *  overwrite the user's intact, newer settings (the failure environment of
  *  issue #1367). */
-function loadOutcome(): { settings: Settings; unreadable: boolean } {
+function loadOutcome(): {
+  settings: Settings
+  unreadable: boolean
+  /** Exactly what was parsed from disk, before defaults are merged in — the baseline the
+   *  change log needs, so a key the file gains for the first time is reported as a change. */
+  persisted: Record<string, unknown>
+} {
   maybeSeedFromEnv()
   let parsed: Record<string, unknown> | null = null
   let unreadable = false
   const read = readFileSafe(dataPath)
   if (read.kind === 'unreadable') {
-    return { settings: { ...defaults }, unreadable: true }
+    return { settings: { ...defaults }, unreadable: true, persisted: {} }
   }
   if (read.kind === 'data') {
     unreadable = read.primaryUnreadable === true
@@ -481,6 +487,12 @@ function loadOutcome(): { settings: Settings; unreadable: boolean } {
       console.warn('Settings: failed to parse settings JSON:', (err as Error).message)
     }
   }
+  // Captured BEFORE the normalisation below, which deletes `null`s that the schema does not
+  // allow. The change log's baseline has to be what the file literally held: a key stored as
+  // `null` would otherwise read as absent, and the line for it would claim `<unset> -> value`
+  // when the truth is `null -> value`. A log whose job is attribution should not quietly
+  // restate the state it is attributing against.
+  const persisted: Record<string, unknown> = { ...(parsed ?? {}) }
   if (parsed) {
     for (const key of KNOWN_SETTING_KEYS) {
       if (parsed[key] === null && !isNullableKnownSettingKey(key)) {
@@ -631,12 +643,105 @@ function loadOutcome(): { settings: Settings; unreadable: boolean } {
       changed = true
     }
   }
-  if (changed && !unreadable) save(result)
-  return { settings: result, unreadable }
+  if (changed && !unreadable) save(result, persisted)
+  return { settings: result, unreadable, persisted }
 }
 
-function save(settings: Settings): void {
-  writeFileSafe(dataPath, JSON.stringify(settings, null, 2), { backup: true })
+/** Describe a value for the log WITHOUT disclosing it.
+ *
+ *  These lines land in `app.log`, which users attach to support requests. `appLog` runs
+ *  `scrubAll` over everything, but that is a best-effort telemetry scrubber for known
+ *  credential shapes — it is not a licence to write every setting a user has. Paths, mirror
+ *  hosts and anything else bespoke would go straight through it.
+ *
+ *  Booleans and numbers are logged exactly, because they cannot carry a secret and they are
+ *  what this log exists to explain — `betaFeaturesEnabled: true -> false` is the whole
+ *  question. Everything else is reduced to its shape, which still answers "did this key
+ *  change, and into what kind of thing", without printing the contents. */
+function describeForLog(v: unknown): string {
+  if (v === undefined) return '<unset>'
+  if (v === null) return 'null'
+  if (typeof v === 'boolean' || typeof v === 'number') return String(v)
+  if (typeof v === 'string') return `<string:${v.length}>`
+  if (Array.isArray(v)) return `<array:${v.length}>`
+  if (typeof v === 'object') return `<object:${Object.keys(v).length}>`
+  return `<${typeof v}>`
+}
+
+/** True when two persisted values differ, order-insensitively for objects.
+ *
+ *  Comparing serializations would make a key-order change read as a real edit, which would
+ *  put a spurious writer in the log — the opposite of useful when the log's whole job is
+ *  attributing a change to a caller. */
+function sameValue(a: unknown, b: unknown): boolean {
+  if (a === b) return true
+  if (typeof a !== typeof b || a === null || b === null) return false
+  if (Array.isArray(a) !== Array.isArray(b)) return false
+  if (typeof a !== 'object') return false
+  const ao = a as Record<string, unknown>
+  const bo = b as Record<string, unknown>
+  const ak = Object.keys(ao)
+  const bk = Object.keys(bo)
+  if (ak.length !== bk.length) return false
+  return ak.every((k) => Object.prototype.hasOwnProperty.call(bo, k) && sameValue(ao[k], bo[k]))
+}
+
+/** One line per key whose persisted value actually changes, with the stack that caused it.
+ *
+ *  Written because a consent-adjacent flag changed itself and nothing in the app could say
+ *  what wrote it. Every candidate writer was excluded by reading the code, which is exactly
+ *  the situation a log has to cover: the useful question is not "which of the writers I know
+ *  about ran" but "who ran", and only a stack answers that.
+ *
+ *  The baseline is what was actually PARSED FROM DISK, not the defaults-merged view. Merging
+ *  first would hide the keys a sparse file gains on its first real write: they are already
+ *  present in a merged baseline, so nothing would be logged for them, and "no line for key X"
+ *  would stop meaning "X was not written" — which is the only claim this log exists to
+ *  support. It is still memory, not a re-read.
+ *  Re-reading looked simpler and was wrong three ways: `readFileSafe` increments the
+ *  process-wide `.bak`-fallback counter that telemetry reports, it blocks the main thread on
+ *  `Atomics.wait` while retrying a locked file, and it cannot tell "no previous value" from
+ *  "previous file unparseable". Reading memory has none of those costs. */
+function logPersistedChanges(
+  before: Record<string, unknown> | undefined,
+  writtenPayload: string
+): void {
+  try {
+    if (!before) return
+    const a = before
+    const parsed: unknown = JSON.parse(writtenPayload)
+    if (!parsed || typeof parsed !== 'object' || Array.isArray(parsed)) return
+    const b = parsed as Record<string, unknown>
+    const changes: string[] = []
+    for (const key of new Set([...Object.keys(a), ...Object.keys(b)])) {
+      if (sameValue(a[key], b[key])) continue
+      changes.push(`${JSON.stringify(key)}: ${describeForLog(a[key])} -> ${describeForLog(b[key])}`)
+    }
+    if (changes.length === 0) return
+    // Frames 0-1 are this helper and `save`; the caller starts after them.
+    const stack = (new Error().stack ?? '')
+      .split('\n')
+      .slice(3, 9)
+      .map((line) => line.trim())
+      .join(' <- ')
+    console.log(`Settings: wrote ${changes.join(', ')} | via ${stack}`)
+  } catch {
+    // Diagnostics must never cost a write, and must never be the reason one is lost.
+  }
+}
+
+/** `before` is the caller's pre-mutation snapshot, used only for the change log. Logged AFTER
+ *  the write lands: `writeFileSafe` can throw, and a line saying a value was written when it
+ *  was not is worse than no line. */
+function save(settings: Settings, before?: Record<string, unknown>): void {
+  // Serialised once, and the log reads back THAT payload rather than the in-memory object.
+  // `JSON.stringify` turns `NaN` and `Infinity` into `null` and drops `undefined`, so the two
+  // genuinely disagree: a renderer can set a key to `NaN` and the file gets `null`. Logging
+  // the object would report a value the file does not contain — which is the one thing a
+  // change log must never do, since its whole purpose is to say what reached disk.
+  const payload = JSON.stringify(settings, null, 2)
+  writeFileSafe(dataPath, payload, { backup: true })
+  logPersistedChanges(before, payload)
 }
 
 /** Sentinel values for `autoLaunchOnStartup`. Any string OTHER than these
@@ -669,7 +774,7 @@ export function set<K extends string>(
   key: K,
   value: K extends KnownSettingKey ? KnownSettings[K] | undefined : unknown
 ): void {
-  const { settings, unreadable } = loadOutcome()
+  const { settings, unreadable, persisted } = loadOutcome()
   if (unreadable) {
     // Fail closed (issue #1367): settings.json exists but can't be read right
     // now, so `settings` holds bare defaults or stale .bak content. Persisting
@@ -687,11 +792,11 @@ export function set<K extends string>(
     (DEFAULT_VALUE_MEANS_UNSET.has(key) && value === DEFAULT_VALUE_MEANS_UNSET.get(key))
   ) {
     delete settings[key]
-    save(settings)
+    save(settings, persisted)
     return
   }
   settings[key] = value
-  save(settings)
+  save(settings, persisted)
 }
 
 export function getAll(): Settings {
@@ -708,13 +813,13 @@ export function getAll(): Settings {
  * beta by revoking consent, taking the diagnostics with them.
  */
 export function resolveBetaFeaturesEnabled(): boolean {
-  const { settings, unreadable } = loadOutcome()
+  const { settings, unreadable, persisted } = loadOutcome()
   const stored = settings.betaFeaturesEnabled
   if (typeof stored === 'boolean') return stored
   if (unreadable) return false
   const seeded = settings.telemetryEnabled === true
   settings.betaFeaturesEnabled = seeded
-  save(settings)
+  save(settings, persisted)
   return seeded
 }