fix(logging): suppress mpv connect-request info log spam

2026-02-27 18:22:41 -08:00 · 2026-02-20 20:45:33 -08:00
parent e1338113b5
commit 1c424b4a0b
6 changed files with 126 additions and 2 deletions
--- a/Suppress-MPV-IPC-connect-request-info-log-spam.md
+++ b/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
+
+<!-- SECTION:DESCRIPTION:BEGIN -->
+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.
+<!-- SECTION:DESCRIPTION:END -->
+
+## Acceptance Criteria
+<!-- AC:BEGIN -->
+- [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.
+<!-- AC:END -->
+
+## Final Summary
+
+<!-- SECTION:FINAL_SUMMARY:BEGIN -->
+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).
+<!-- SECTION:FINAL_SUMMARY:END -->
+
+## Definition of Done
+<!-- DOD:BEGIN -->
+- [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.
+<!-- DOD:END -->
--- 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` |
--- a/docs/subagents/agents/codex-mpv-connect-log-20260221T043748Z-q7m1.md
+++ 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.
--- 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).
--- 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[] = [];
--- 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();
  }