fix(logging): surface subtitle processing debug/warn logs (#182)

src/core/services/startup-bootstrap.test.ts

@@ -205,7 +205,7 @@ test('runStartupBootstrapRuntime skips lifecycle when generate-config flow handl
   assert.deepEqual(calls, ['setLog:warn:cli', 'forceX11', 'enforceWayland']);
 });
 
-test('runStartupBootstrapRuntime enables quiet background mode by default', () => {
+test('runStartupBootstrapRuntime lets config govern background log level by default', () => {
   const calls: string[] = [];
   const args = makeArgs({ background: true });
 
@@ -222,7 +222,7 @@ test('runStartupBootstrapRuntime enables quiet background mode by default', () =
   });
 
   assert.equal(result.backgroundMode, true);
-  assert.deepEqual(calls, ['setLog:warn:cli', 'forceX11', 'enforceWayland', 'startLifecycle']);
+  assert.deepEqual(calls, ['forceX11', 'enforceWayland', 'startLifecycle']);
 });
 
 test('runStartupBootstrapRuntime enables quiet update mode by default', () => {

src/core/services/startup.ts

@@ -45,7 +45,7 @@ export function runStartupBootstrapRuntime(
 
   if (initialArgs.logLevel) {
     deps.setLogLevel(initialArgs.logLevel, 'cli');
-  } else if (initialArgs.background || initialArgs.update) {
+  } else if (initialArgs.update) {
     deps.setLogLevel('warn', 'cli');
   }
 

src/main.ts

@@ -1982,6 +1982,7 @@ const resolveActiveSubtitleSidebarSourceHandler = createResolveActiveSubtitleSid
   getFfmpegPath: () => configService.getConfig().subsync.ffmpeg_path.trim() || 'ffmpeg',
   extractInternalSubtitleTrack: (ffmpegPath, videoPath, track) =>
     extractInternalSubtitleTrackToTempFile(ffmpegPath, videoPath, track),
+  logDebug: (message) => logger.debug(message),
 });
 
 const refreshSubtitlePrefetchFromActiveTrackHandler =
@@ -1991,6 +1992,8 @@ const refreshSubtitlePrefetchFromActiveTrackHandler =
     shouldKeepExistingCuesOnMissingSource: (videoPath) => isYoutubeMediaPath(videoPath),
     subtitlePrefetchInitController,
     resolveActiveSubtitleSidebarSource: (input) => resolveActiveSubtitleSidebarSourceHandler(input),
+    logDebug: (message) => logger.debug(message),
+    logWarn: (message) => logger.warn(message),
   });
 
 const subtitlePrefetchRuntime = {
@@ -4366,6 +4369,7 @@ const {
     refreshDiscordPresence: () => {
       discordPresenceRuntime.publishDiscordPresence();
     },
+    logSubtitleProcessingDebug: (message: string) => logger.debug(message),
     ensureImmersionTrackerInitialized: () => {
       ensureImmersionTrackerStarted();
     },

src/main/runtime/mpv-main-event-actions.test.ts

@@ -70,6 +70,24 @@ test('subtitle change handler broadcasts cached annotated payload immediately wh
   ]);
 });
 
+test('subtitle change handler logs debug when a cached payload is emitted immediately', () => {
+  const debugs: string[] = [];
+  const handler = createHandleMpvSubtitleChangeHandler({
+    setCurrentSubText: () => {},
+    getImmediateSubtitlePayload: (text) => (text ? { text, tokens: [] } : null),
+    broadcastSubtitle: () => {},
+    onSubtitleChange: () => {},
+    refreshDiscordPresence: () => {},
+    logDebug: (message) => debugs.push(message),
+  });
+
+  handler({ text: 'キャッシュ済みの行' });
+  handler({ text: '' });
+
+  assert.equal(debugs.length, 1);
+  assert.match(debugs[0]!, /cached subtitle/);
+});
+
 test('subtitle change handler emits cached annotation after forwarding the subtitle change', () => {
   const calls: string[] = [];
   const handler = createHandleMpvSubtitleChangeHandler({

src/main/runtime/mpv-main-event-actions.ts

@@ -20,11 +20,15 @@ export function createHandleMpvSubtitleChangeHandler(deps: {
   broadcastSubtitle: (payload: SubtitleData) => void;
   onSubtitleChange: (text: string) => void;
   refreshDiscordPresence: () => void;
+  logDebug?: (message: string) => void;
 }) {
   return ({ text }: { text: string }): void => {
     deps.setCurrentSubText(text);
     const immediatePayload = deps.getImmediateSubtitlePayload?.(text) ?? null;
     if (immediatePayload) {
+      deps.logDebug?.(
+        `[subtitle-processing] emitted cached subtitle immediately (${text.length} chars)`,
+      );
       deps.onSubtitleChange(text);
       (deps.emitImmediateSubtitle ?? deps.broadcastSubtitle)(immediatePayload);
     } else {

src/main/runtime/mpv-main-event-bindings.ts

@@ -47,6 +47,7 @@ export function createBindMpvMainEventHandlersHandler(deps: {
   emitImmediateSubtitle?: (payload: SubtitleData) => void;
   broadcastSubtitle: (payload: SubtitleData) => void;
   onSubtitleChange: (text: string) => void;
+  logSubtitleProcessingDebug?: (message: string) => void;
   refreshDiscordPresence: () => void;
 
   setCurrentSubAssText: (text: string) => void;
@@ -123,6 +124,9 @@ export function createBindMpvMainEventHandlersHandler(deps: {
         : undefined,
       broadcastSubtitle: (payload) => deps.broadcastSubtitle(payload),
       onSubtitleChange: (text) => deps.onSubtitleChange(text),
+      logDebug: deps.logSubtitleProcessingDebug
+        ? (message) => deps.logSubtitleProcessingDebug?.(message)
+        : undefined,
       refreshDiscordPresence: () => deps.refreshDiscordPresence(),
     });
     const handleMpvSubtitleAssChange = createHandleMpvSubtitleAssChangeHandler({

src/main/runtime/mpv-main-event-main-deps.ts

@@ -54,6 +54,7 @@ export function createBuildBindMpvMainEventHandlersMainDepsHandler(deps: {
   getImmediateSubtitlePayload?: (text: string) => SubtitleData | null;
   emitImmediateSubtitle?: (payload: SubtitleData) => void;
   onSubtitleChange: (text: string) => void;
+  logSubtitleProcessingDebug?: (message: string) => void;
   onSubtitleTrackChange?: (sid: number | null) => void;
   onSubtitleTrackListChange?: (trackList: unknown[] | null) => void;
   updateCurrentMediaPath: (path: string) => void;
@@ -155,6 +156,9 @@ export function createBuildBindMpvMainEventHandlersMainDepsHandler(deps: {
     broadcastSubtitle: (payload: SubtitleData) =>
       deps.broadcastToOverlayWindows('subtitle:set', payload),
     onSubtitleChange: (text: string) => deps.onSubtitleChange(text),
+    logSubtitleProcessingDebug: deps.logSubtitleProcessingDebug
+      ? (message: string) => deps.logSubtitleProcessingDebug!(message)
+      : undefined,
     onSubtitleTrackChange: deps.onSubtitleTrackChange
       ? (sid: number | null) => deps.onSubtitleTrackChange!(sid)
       : undefined,

src/main/runtime/subtitle-prefetch-init.test.ts

@@ -234,3 +234,26 @@ test('subtitle prefetch init clears parsed cues when initialization fails', asyn
 
   assert.deepEqual(cueUpdates, [null]);
 });
+
+test('subtitle prefetch init logs a warning when the source parses to zero cues', async () => {
+  const warnings: string[] = [];
+  const controller = createSubtitlePrefetchInitController({
+    getCurrentService: () => null,
+    setCurrentService: () => {},
+    loadSubtitleSourceText: async () => 'not really subtitles',
+    parseSubtitleCues: (): SubtitleCue[] => [],
+    createSubtitlePrefetchService: () => {
+      throw new Error('should not create a service without cues');
+    },
+    tokenizeSubtitle: async () => null,
+    preCacheTokenization: () => {},
+    isCacheFull: () => false,
+    logInfo: () => {},
+    logWarn: (message) => warnings.push(message),
+  });
+
+  await controller.initSubtitlePrefetch('/tmp/broken.ass', 0);
+
+  assert.equal(warnings.length, 1);
+  assert.match(warnings[0]!, /\[subtitle-prefetch\].*0 cues.*\/tmp\/broken\.ass/);
+});

src/main/runtime/subtitle-prefetch-init.ts

@@ -59,6 +59,9 @@ export function createSubtitlePrefetchInitController(
       const cues = deps.parseSubtitleCues(content, sourcePath);
       if (revision !== initRevision || cues.length === 0) {
         if (revision === initRevision) {
+          deps.logWarn(
+            `[subtitle-prefetch] parsed 0 cues from ${sourcePath}; prefetch disabled for this source`,
+          );
           deps.onParsedSubtitleCuesChanged?.(null, null);
         }
         return;

src/main/runtime/subtitle-prefetch-runtime.test.ts

@@ -130,3 +130,121 @@ test('subtitle prefetch runtime does not extract internal subtitle tracks from r
   assert.equal(resolved, null);
   assert.equal(extracted, false);
 });
+
+test('subtitle prefetch refresh logs a warning when source resolution throws', async () => {
+  const warnings: string[] = [];
+  const refresh = createRefreshSubtitlePrefetchFromActiveTrackHandler({
+    getMpvClient: () => ({
+      connected: true,
+      requestProperty: async (name) => (name === 'path' ? '/media/video.mkv' : null),
+    }),
+    getLastObservedTimePos: () => 0,
+    subtitlePrefetchInitController: {
+      cancelPendingInit: () => {},
+      initSubtitlePrefetch: async () => {},
+    },
+    resolveActiveSubtitleSidebarSource: async () => {
+      throw new Error('ffmpeg ENOENT');
+    },
+    logWarn: (message) => warnings.push(message),
+  });
+
+  await refresh();
+
+  assert.equal(warnings.length, 1);
+  assert.match(warnings[0]!, /\[subtitle-prefetch\].*ffmpeg ENOENT/);
+});
+
+test('subtitle prefetch refresh logs debug when mpv client is not connected', async () => {
+  const debugs: string[] = [];
+  const refresh = createRefreshSubtitlePrefetchFromActiveTrackHandler({
+    getMpvClient: () => null,
+    getLastObservedTimePos: () => 0,
+    subtitlePrefetchInitController: {
+      cancelPendingInit: () => {},
+      initSubtitlePrefetch: async () => {},
+    },
+    resolveActiveSubtitleSidebarSource: async () => null,
+    logDebug: (message) => debugs.push(message),
+  });
+
+  await refresh();
+
+  assert.equal(debugs.length, 1);
+  assert.match(debugs[0]!, /\[subtitle-prefetch\].*not connected/);
+});
+
+test('subtitle prefetch refresh logs debug when no subtitle source resolves', async () => {
+  const debugs: string[] = [];
+  const cancels: number[] = [];
+  const refresh = createRefreshSubtitlePrefetchFromActiveTrackHandler({
+    getMpvClient: () => ({
+      connected: true,
+      requestProperty: async (name) => (name === 'path' ? '/media/video.mkv' : null),
+    }),
+    getLastObservedTimePos: () => 0,
+    subtitlePrefetchInitController: {
+      cancelPendingInit: () => {
+        cancels.push(1);
+      },
+      initSubtitlePrefetch: async () => {},
+    },
+    resolveActiveSubtitleSidebarSource: async () => null,
+    logDebug: (message) => debugs.push(message),
+  });
+
+  await refresh();
+
+  assert.deepEqual(cancels, [1]);
+  assert.equal(debugs.length, 1);
+  assert.match(debugs[0]!, /\[subtitle-prefetch\].*no active subtitle source/);
+});
+
+test('subtitle source resolver logs debug when internal track extraction is unavailable', async () => {
+  const debugs: string[] = [];
+  const resolveSource = createResolveActiveSubtitleSidebarSourceHandler({
+    getFfmpegPath: () => 'ffmpeg',
+    extractInternalSubtitleTrack: async () => null,
+    logDebug: (message) => debugs.push(message),
+  });
+
+  const resolved = await resolveSource({
+    currentExternalFilenameRaw: null,
+    currentTrackRaw: {
+      type: 'sub',
+      id: 3,
+      'ff-index': 7,
+      codec: 'hdmv_pgs_subtitle',
+    },
+    trackListRaw: [],
+    sidRaw: 3,
+    videoPath: '/media/video.mkv',
+  });
+
+  assert.equal(resolved, null);
+  assert.equal(debugs.length, 1);
+  assert.match(debugs[0]!, /\[subtitle-prefetch\].*extraction.*hdmv_pgs_subtitle/);
+});
+
+test('subtitle source resolver logs debug when no active subtitle track is selected', async () => {
+  const debugs: string[] = [];
+  const resolveSource = createResolveActiveSubtitleSidebarSourceHandler({
+    getFfmpegPath: () => 'ffmpeg',
+    extractInternalSubtitleTrack: async () => {
+      throw new Error('should not extract without a track');
+    },
+    logDebug: (message) => debugs.push(message),
+  });
+
+  const resolved = await resolveSource({
+    currentExternalFilenameRaw: null,
+    currentTrackRaw: null,
+    trackListRaw: [],
+    sidRaw: null,
+    videoPath: '/media/video.mkv',
+  });
+
+  assert.equal(resolved, null);
+  assert.equal(debugs.length, 1);
+  assert.match(debugs[0]!, /\[subtitle-prefetch\].*no active subtitle track/);
+});

src/main/runtime/subtitle-prefetch-runtime.ts

@@ -86,6 +86,7 @@ export function createResolveActiveSubtitleSidebarSourceHandler(deps: {
     videoPath: string,
     track: MpvSubtitleTrackLike,
   ) => Promise<{ path: string; cleanup: () => Promise<void> } | null>;
+  logDebug?: (message: string) => void;
 }) {
   return async (input: {
     currentExternalFilenameRaw: unknown;
@@ -104,6 +105,7 @@ export function createResolveActiveSubtitleSidebarSourceHandler(deps: {
 
     const track = getActiveSubtitleTrack(input.currentTrackRaw, input.trackListRaw, input.sidRaw);
     if (!track) {
+      deps.logDebug?.('[subtitle-prefetch] no active subtitle track selected yet');
       return null;
     }
 
@@ -114,6 +116,7 @@ export function createResolveActiveSubtitleSidebarSourceHandler(deps: {
     }
 
     if (isRemoteMediaPath(input.videoPath)) {
+      deps.logDebug?.('[subtitle-prefetch] skipping internal subtitle extraction for remote media');
       return null;
     }
 
@@ -123,6 +126,9 @@ export function createResolveActiveSubtitleSidebarSourceHandler(deps: {
       track,
     );
     if (!extracted) {
+      deps.logDebug?.(
+        `[subtitle-prefetch] internal subtitle extraction unavailable (codec=${String(track.codec ?? 'unknown')}, ff-index=${String(track['ff-index'] ?? 'unknown')})`,
+      );
       return null;
     }
 
@@ -144,10 +150,13 @@ export function createRefreshSubtitlePrefetchFromActiveTrackHandler(deps: {
   resolveActiveSubtitleSidebarSource: (
     input: Parameters<ReturnType<typeof createResolveActiveSubtitleSidebarSourceHandler>>[0],
   ) => Promise<ActiveSubtitleSidebarSource | null>;
+  logDebug?: (message: string) => void;
+  logWarn?: (message: string) => void;
 }) {
   return async (): Promise<void> => {
     const client = deps.getMpvClient();
     if (!client?.connected) {
+      deps.logDebug?.('[subtitle-prefetch] skipped refresh: mpv client not connected');
       return;
     }
 
@@ -162,6 +171,7 @@ export function createRefreshSubtitlePrefetchFromActiveTrackHandler(deps: {
         ]);
       const videoPath = typeof videoPathRaw === 'string' ? videoPathRaw : '';
       if (!videoPath) {
+        deps.logDebug?.('[subtitle-prefetch] skipped refresh: no media path');
         deps.subtitlePrefetchInitController.cancelPendingInit();
         return;
       }
@@ -175,8 +185,14 @@ export function createRefreshSubtitlePrefetchFromActiveTrackHandler(deps: {
       });
       if (!resolvedSource) {
         if (deps.shouldKeepExistingCuesOnMissingSource?.(videoPath) === true) {
+          deps.logDebug?.(
+            '[subtitle-prefetch] no active subtitle source resolved; keeping existing cues',
+          );
           return;
         }
+        deps.logDebug?.(
+          '[subtitle-prefetch] no active subtitle source resolved; cancelling prefetch',
+        );
         deps.subtitlePrefetchInitController.cancelPendingInit();
         return;
       }
@@ -190,8 +206,12 @@ export function createRefreshSubtitlePrefetchFromActiveTrackHandler(deps: {
       } finally {
         await resolvedSource.cleanup?.();
       }
-    } catch {
-      // Skip refresh when the track query fails.
+    } catch (error) {
+      deps.logWarn?.(
+        `[subtitle-prefetch] failed to refresh from active track: ${
+          error instanceof Error ? error.message : String(error)
+        }`,
+      );
     }
   };
 }