From bffb1c5982a4f1141304b7effd8305de3d181491 Mon Sep 17 00:00:00 2001 From: sudacode Date: Mon, 3 Aug 2026 20:44:39 -0700 Subject: [PATCH] fix(logging): surface subtitle processing debug/warn logs (#182) --- changes/background-config-log-level.md | 4 + docs-site/usage.md | 2 +- src/core/services/startup-bootstrap.test.ts | 4 +- src/core/services/startup.ts | 2 +- src/main.ts | 4 + .../runtime/mpv-main-event-actions.test.ts | 18 +++ src/main/runtime/mpv-main-event-actions.ts | 4 + src/main/runtime/mpv-main-event-bindings.ts | 4 + src/main/runtime/mpv-main-event-main-deps.ts | 4 + .../runtime/subtitle-prefetch-init.test.ts | 23 ++++ src/main/runtime/subtitle-prefetch-init.ts | 3 + .../runtime/subtitle-prefetch-runtime.test.ts | 118 ++++++++++++++++++ src/main/runtime/subtitle-prefetch-runtime.ts | 24 +++- 13 files changed, 208 insertions(+), 6 deletions(-) create mode 100644 changes/background-config-log-level.md diff --git a/changes/background-config-log-level.md b/changes/background-config-log-level.md new file mode 100644 index 00000000..0509480c --- /dev/null +++ b/changes/background-config-log-level.md @@ -0,0 +1,4 @@ +type: fixed +area: logging + +- Background startup now respects the configured logging level when `--log-level` is not explicitly provided. diff --git a/docs-site/usage.md b/docs-site/usage.md index 3c58fc13..49db3bbc 100644 --- a/docs-site/usage.md +++ b/docs-site/usage.md @@ -149,7 +149,7 @@ Once Jellyfin is configured, the tray menu includes `Jellyfin Discovery` for sta - `--log-level` controls logger verbosity. - `--dev` and `--debug` are app/dev-mode switches; they are not log-level aliases. -- `--background` defaults to quieter logging (`warn`) unless `--log-level` is set. +- `--background` starts at the default quieter logging level (`warn`), then follows `logging.level` after config loads. An explicit `--log-level` remains the override. - `--background` launched from a terminal detaches and returns the prompt; stop it with tray Quit or `SubMiner.AppImage --stop` (`SubMiner.exe --stop` on Windows). - Linux desktop launcher starts SubMiner with `--background` by default (via electron-builder `linux.executableArgs`). - On Hyprland and other Wayland compositors, the tray icon appears only when your panel provides a StatusNotifier/AppIndicator tray host. diff --git a/src/core/services/startup-bootstrap.test.ts b/src/core/services/startup-bootstrap.test.ts index e2082fde..787a15fe 100644 --- a/src/core/services/startup-bootstrap.test.ts +++ b/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', () => { diff --git a/src/core/services/startup.ts b/src/core/services/startup.ts index 3bc4b7ce..e7ddfe3a 100644 --- a/src/core/services/startup.ts +++ b/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'); } diff --git a/src/main.ts b/src/main.ts index 75154828..0578c84f 100644 --- a/src/main.ts +++ b/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(); }, diff --git a/src/main/runtime/mpv-main-event-actions.test.ts b/src/main/runtime/mpv-main-event-actions.test.ts index 4b2b3277..845a7f08 100644 --- a/src/main/runtime/mpv-main-event-actions.test.ts +++ b/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({ diff --git a/src/main/runtime/mpv-main-event-actions.ts b/src/main/runtime/mpv-main-event-actions.ts index 4b715e44..7f38e596 100644 --- a/src/main/runtime/mpv-main-event-actions.ts +++ b/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 { diff --git a/src/main/runtime/mpv-main-event-bindings.ts b/src/main/runtime/mpv-main-event-bindings.ts index 8bb37f76..4fcbeba9 100644 --- a/src/main/runtime/mpv-main-event-bindings.ts +++ b/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({ diff --git a/src/main/runtime/mpv-main-event-main-deps.ts b/src/main/runtime/mpv-main-event-main-deps.ts index 5219e300..cf3e87ef 100644 --- a/src/main/runtime/mpv-main-event-main-deps.ts +++ b/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, diff --git a/src/main/runtime/subtitle-prefetch-init.test.ts b/src/main/runtime/subtitle-prefetch-init.test.ts index 162e85eb..e918fa91 100644 --- a/src/main/runtime/subtitle-prefetch-init.test.ts +++ b/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/); +}); diff --git a/src/main/runtime/subtitle-prefetch-init.ts b/src/main/runtime/subtitle-prefetch-init.ts index 62291067..f7cf3fec 100644 --- a/src/main/runtime/subtitle-prefetch-init.ts +++ b/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; diff --git a/src/main/runtime/subtitle-prefetch-runtime.test.ts b/src/main/runtime/subtitle-prefetch-runtime.test.ts index 1d2481f7..385b3365 100644 --- a/src/main/runtime/subtitle-prefetch-runtime.test.ts +++ b/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/); +}); diff --git a/src/main/runtime/subtitle-prefetch-runtime.ts b/src/main/runtime/subtitle-prefetch-runtime.ts index 443bb3e8..91ec827c 100644 --- a/src/main/runtime/subtitle-prefetch-runtime.ts +++ b/src/main/runtime/subtitle-prefetch-runtime.ts @@ -86,6 +86,7 @@ export function createResolveActiveSubtitleSidebarSourceHandler(deps: { videoPath: string, track: MpvSubtitleTrackLike, ) => Promise<{ path: string; cleanup: () => Promise } | 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>[0], ) => Promise; + logDebug?: (message: string) => void; + logWarn?: (message: string) => void; }) { return async (): Promise => { 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) + }`, + ); } }; }