diff --git a/src/main/lib/ipc/registerSettingsHandlers.ts b/src/main/lib/ipc/registerSettingsHandlers.ts index 7ae12da96..01b36d8f9 100644 --- a/src/main/lib/ipc/registerSettingsHandlers.ts +++ b/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() || '' + } catch { + return '' + } + })() + console.log(`Settings: set-setting ${JSON.stringify(key)} requested by ${origin}`) applySettingSet(key, value) }) diff --git a/src/main/settings.test.ts b/src/main/settings.test.ts index 8f706031f..7e8820e35 100644 --- a/src/main/settings.test.ts +++ b/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 -> '))).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 + // ` -> 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(' { + 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 diff --git a/src/main/settings.ts b/src/main/settings.ts index 4ba1421f3..02e703d30 100644 --- a/src/main/settings.ts +++ b/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 +} { maybeSeedFromEnv() let parsed: Record | 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 ` -> 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 = { ...(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 '' + if (v === null) return 'null' + if (typeof v === 'boolean' || typeof v === 'number') return String(v) + if (typeof v === 'string') return `` + if (Array.isArray(v)) return `` + if (typeof v === 'object') return `` + 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 + const bo = b as Record + 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 | 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 + 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): 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( 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( (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 }