From 1c424b4a0bc85d78cfa375b90ee7de9cc532dd3e Mon Sep 17 00:00:00 2001 From: sudacode Date: Fri, 20 Feb 2026 20:45:33 -0800 Subject: [PATCH] fix(logging): suppress mpv connect-request info log spam --- ...s-MPV-IPC-connect-request-info-log-spam.md | 40 +++++++++++++++++ docs/subagents/INDEX.md | 4 +- ...x-mpv-connect-log-20260221T043748Z-q7m1.md | 35 +++++++++++++++ docs/subagents/collaboration.md | 3 ++ src/core/services/mpv.test.ts | 44 +++++++++++++++++++ src/core/services/mpv.ts | 2 +- 6 files changed, 126 insertions(+), 2 deletions(-) create mode 100644 backlog/tasks/task-95 - Suppress-MPV-IPC-connect-request-info-log-spam.md create mode 100644 docs/subagents/agents/codex-mpv-connect-log-20260221T043748Z-q7m1.md diff --git a/backlog/tasks/task-95 - Suppress-MPV-IPC-connect-request-info-log-spam.md b/backlog/tasks/task-95 - Suppress-MPV-IPC-connect-request-info-log-spam.md new file mode 100644 index 0000000..f23c49f --- /dev/null +++ b/backlog/tasks/task-95 - Suppress-MPV-IPC-connect-request-info-log-spam.md @@ -0,0 +1,40 @@ +--- +id: TASK-95 +title: Suppress MPV IPC connect-request info log spam +status: Done +assignee: [] +created_date: '2026-02-21 04:38' +updated_date: '2026-02-21 04:40' +labels: + - logging + - mpv + - electron + - quality +dependencies: [] +priority: high +--- + +## Description + + +Follow-up to TASK-33: `[main:mpv] MPV IPC connect requested.` still emits at INFO repeatedly during startup retries. Gate this request-attempt log behind debug level so normal runs stay quiet. + + +## Acceptance Criteria + +- [x] #1 Non-debug runs do not emit repeated 'MPV IPC connect requested.' lines during retry loops. +- [x] #2 Debug runs still emit connect-request attempt logs for diagnosis. +- [x] #3 Connection behavior and retry timing are unchanged. + + +## Final Summary + + +Moved MPV connect-request log in `src/core/services/mpv.ts` from INFO to DEBUG so retry loops are silent at default log level while preserving diagnostics in debug mode. Added regression tests in `src/core/services/mpv.test.ts` asserting zero connect-request logs at info level and one connect-request log at debug level. Validation: `bun run build && node dist/core/services/mpv.test.js` (pass). + + +## Definition of Done + +- [x] #1 Add/adjust unit tests covering debug vs non-debug logging for connect requests. +- [x] #2 Run targeted mpv service tests and build/typecheck path used for this change. + diff --git a/docs/subagents/INDEX.md b/docs/subagents/INDEX.md index 40480bf..9cb6bd7 100644 --- a/docs/subagents/INDEX.md +++ b/docs/subagents/INDEX.md @@ -27,4 +27,6 @@ Read first. Keep concise. | `codex-review-refactor-cleanup-20260220T113818Z-i2ov` | `codex-review-refactor-cleanup` | `Review recent TASK-85 refactor effort and identify remaining cleanup work` | `handoff` | `docs/subagents/agents/codex-review-refactor-cleanup-20260220T113818Z-i2ov.md` | `2026-02-20T11:48:28Z` | | `codex-commit-unstaged-20260220T115057Z-k7q2` | `codex-commit-unstaged` | `Commit all current unstaged repository changes with content-derived conventional message` | `in_progress` | `docs/subagents/agents/codex-commit-unstaged-20260220T115057Z-k7q2.md` | `2026-02-20T11:51:18Z` | | `codex-overlay-whitespace-newline-20260221T040705Z-aw2j` | `codex-overlay-whitespace-newline` | `Fix visible overlay whitespace/newline token rendering bug with TDD regression coverage` | `completed` | `docs/subagents/agents/codex-overlay-whitespace-newline-20260221T040705Z-aw2j.md` | `2026-02-21T04:18:16Z` | -| `codex-duplicate-kiku-20260221T043006Z-5vkz` | `codex-duplicate-kiku` | `Fix Kiku duplicate-card detection/grouping regression for Yomitan duplicate-marked + N+1-highlighted cards` | `completed` | `docs/subagents/agents/codex-duplicate-kiku-20260221T043006Z-5vkz.md` | `2026-02-21T04:33:17Z` | +| `codex-duplicate-kiku-20260221T043006Z-5vkz` | `codex-duplicate-kiku` | `Fix Kiku duplicate-card detection/grouping regression for Yomitan duplicate-marked + N+1-highlighted cards` | `completed` | `docs/subagents/agents/codex-duplicate-kiku-20260221T043006Z-5vkz.md` | `2026-02-21T04:38:25Z` | +| `codex-mpv-connect-log-20260221T043748Z-q7m1` | `codex-mpv-connect-log` | `Suppress repetitive MPV IPC connect-request INFO logs during startup` | `completed` | `docs/subagents/agents/codex-mpv-connect-log-20260221T043748Z-q7m1.md` | `2026-02-21T04:41:15Z` | +| `codex-add-backlog-tasks-20260221T044104Z-m3n8` | `codex-add-backlog-tasks` | `Add two unrelated backlog tasks: secondary subtitle decoupling and intro skip` | `done` | `docs/subagents/agents/codex-add-backlog-tasks-20260221T044104Z-m3n8.md` | `2026-02-21T04:44:12Z` | diff --git a/docs/subagents/agents/codex-mpv-connect-log-20260221T043748Z-q7m1.md b/docs/subagents/agents/codex-mpv-connect-log-20260221T043748Z-q7m1.md new file mode 100644 index 0000000..8434df5 --- /dev/null +++ b/docs/subagents/agents/codex-mpv-connect-log-20260221T043748Z-q7m1.md @@ -0,0 +1,35 @@ +# Agent: `codex-mpv-connect-log-20260221T043748Z-q7m1` + +- alias: `codex-mpv-connect-log` +- mission: `Suppress repetitive MPV IPC connect-request INFO logs during startup` +- status: `done` +- branch: `main` +- started_at: `2026-02-21T04:37:48Z` +- heartbeat_minutes: `5` + +## Current Work (newest first) +- [2026-02-21T04:41:15Z] handoff: switched connect-request logging from INFO to DEBUG in `src/core/services/mpv.ts`; added regression tests for info/debug behavior in `src/core/services/mpv.test.ts`; build + mpv suite passing; linked and completed `TASK-95`. +- [2026-02-21T04:40:32Z] test: `bun run build && node dist/core/services/mpv.test.js` (pass, 15/15). +- [2026-02-21T04:39:42Z] test: red confirmed before implementation (2 failing assertions for info/debug log-level expectations). +- [2026-02-21T04:38:20Z] progress: created backlog ticket `TASK-95` for this logger-path follow-up to `TASK-33`. +- [2026-02-21T04:37:48Z] intent: TDD-first fix for `[main:mpv] MPV IPC connect requested.` log spam; keep functional behavior unchanged. +- [2026-02-21T04:37:48Z] progress: read `docs/subagents/INDEX.md`, `docs/subagents/collaboration.md`; identified emitter in `src/core/services/mpv.ts`. +- [2026-02-21T04:37:48Z] progress: backlog check found prior related completed task `TASK-33`; scoping follow-up for current logger path. + +## Files Touched +- `docs/subagents/agents/codex-mpv-connect-log-20260221T043748Z-q7m1.md` +- `docs/subagents/INDEX.md` +- `docs/subagents/collaboration.md` +- `backlog/tasks/task-95 - Suppress-MPV-IPC-connect-request-info-log-spam.md` +- `src/core/services/mpv.ts` +- `src/core/services/mpv.test.ts` + +## Assumptions +- Noise source is `logger.info('MPV IPC connect requested.')` in `src/core/services/mpv.ts`. +- Desired behavior: suppress this line at non-debug log levels. + +## Open Questions / Blockers +- none + +## Next Step +- Await user verification in runtime logs; no further code changes planned. diff --git a/docs/subagents/collaboration.md b/docs/subagents/collaboration.md index 0ea3cc2..37ad529 100644 --- a/docs/subagents/collaboration.md +++ b/docs/subagents/collaboration.md @@ -24,3 +24,6 @@ Shared notes. Append-only. - [2026-02-21T04:27:24Z] [codex-jellyfin-secret-store-20260220T101428Z-om4z|codex-jellyfin-secret-store] completed TASK-93: removed Jellyfin accessToken/userId config fields; resolver now uses env-first (`SUBMINER_JELLYFIN_ACCESS_TOKEN` + optional `SUBMINER_JELLYFIN_USER_ID`) then stored encrypted session payload; login/setup save session and logout clears session. - [2026-02-21T04:30:06Z] [codex-duplicate-kiku-20260221T043006Z-5vkz|codex-duplicate-kiku] investigating Kiku duplicate grouping regression; expecting touches in `src/anki-integration/duplicate.ts` and duplicate-detection tests only. - [2026-02-21T04:33:17Z] [codex-duplicate-kiku-20260221T043006Z-5vkz|codex-duplicate-kiku] completed TASK-94: duplicate check now resolves `word`/`expression` alias fields when validating candidate notes; added regression test `src/anki-integration/duplicate.test.ts`; targeted build + duplicate/anki-integration tests passed. +- [2026-02-21T04:38:25Z] [codex-duplicate-kiku-20260221T043006Z-5vkz|codex-duplicate-kiku] follow-up repro fixed: duplicate search now queries both alias fields (`word` + `expression`) and unions note ids before exact compare; added second regression test for alias-query fallback. +- [2026-02-21T04:37:48Z] [codex-mpv-connect-log-20260221T043748Z-q7m1|codex-mpv-connect-log] overlap note: touching `src/core/services/mpv.ts` + mpv service tests for startup connection-request log level gating; coordinating with historical TASK-33 behavior (same symptom, new logger path). +- [2026-02-21T04:41:15Z] [codex-mpv-connect-log-20260221T043748Z-q7m1|codex-mpv-connect-log] completed TASK-95: changed `MpvIpcClient.connect()` connect-request line to `logger.debug`, added regression tests for info/debug level log behavior in `src/core/services/mpv.test.ts`; verified via `bun run build && node dist/core/services/mpv.test.js` (pass). diff --git a/src/core/services/mpv.test.ts b/src/core/services/mpv.test.ts index 98816ce..0e35064 100644 --- a/src/core/services/mpv.test.ts +++ b/src/core/services/mpv.test.ts @@ -89,6 +89,50 @@ test('MpvIpcClient requestProperty throws on mpv error response', async () => { ); }); +test('MpvIpcClient connect does not log connect-request at info level', () => { + const originalLevel = process.env.SUBMINER_LOG_LEVEL; + const originalInfo = console.info; + const infoLines: string[] = []; + process.env.SUBMINER_LOG_LEVEL = 'info'; + console.info = (message?: unknown) => { + infoLines.push(String(message ?? '')); + }; + + try { + const client = new MpvIpcClient('/tmp/mpv.sock', makeDeps()); + (client as any).transport.connect = () => {}; + client.connect(); + } finally { + process.env.SUBMINER_LOG_LEVEL = originalLevel; + console.info = originalInfo; + } + + const requestLogs = infoLines.filter((line) => line.includes('MPV IPC connect requested.')); + assert.equal(requestLogs.length, 0); +}); + +test('MpvIpcClient connect logs connect-request at debug level', () => { + const originalLevel = process.env.SUBMINER_LOG_LEVEL; + const originalDebug = console.debug; + const debugLines: string[] = []; + process.env.SUBMINER_LOG_LEVEL = 'debug'; + console.debug = (message?: unknown) => { + debugLines.push(String(message ?? '')); + }; + + try { + const client = new MpvIpcClient('/tmp/mpv.sock', makeDeps()); + (client as any).transport.connect = () => {}; + client.connect(); + } finally { + process.env.SUBMINER_LOG_LEVEL = originalLevel; + console.debug = originalDebug; + } + + const requestLogs = debugLines.filter((line) => line.includes('MPV IPC connect requested.')); + assert.equal(requestLogs.length, 1); +}); + test('MpvIpcClient failPendingRequests resolves outstanding requests as disconnected', () => { const client = new MpvIpcClient('/tmp/mpv.sock', makeDeps()); const resolved: unknown[] = []; diff --git a/src/core/services/mpv.ts b/src/core/services/mpv.ts index d810491..9f40a21 100644 --- a/src/core/services/mpv.ts +++ b/src/core/services/mpv.ts @@ -248,7 +248,7 @@ export class MpvIpcClient implements MpvClient { return; } - logger.info('MPV IPC connect requested.'); + logger.debug('MPV IPC connect requested.'); this.connecting = true; this.transport.connect(); }