diff --git a/packages/syncloungeserver/src/socketserver/playbackdiagnostics.js b/packages/syncloungeserver/src/socketserver/playbackdiagnostics.js index 1fab99c8cd..8568af2ead 100644 --- a/packages/syncloungeserver/src/socketserver/playbackdiagnostics.js +++ b/packages/syncloungeserver/src/socketserver/playbackdiagnostics.js @@ -48,6 +48,9 @@ const diagnosticSchema = { transcode: true, }, playback: { + reportedState: true, + sourceChanging: 'boolean', + stateMasked: 'boolean', isCasting: 'boolean', buffering: 'nullable-boolean', attached: true, diff --git a/src/__tests__/stream-recovery.test.js b/src/__tests__/stream-recovery.test.js index 022e36d798..8858428a55 100644 --- a/src/__tests__/stream-recovery.test.js +++ b/src/__tests__/stream-recovery.test.js @@ -3,6 +3,8 @@ import { describe, it, expect, vi, beforeEach, } from 'vitest'; import slplayerActions from '@/store/modules/slplayer/actions'; +import slplayerGetters from '@/store/modules/slplayer/getters'; +import roomGetters from '@/store/modules/synclounge/getters'; vi.mock('@/player', () => ({ setPlaybackRate: vi.fn(), @@ -183,6 +185,108 @@ describe('stream recovery fault injection', () => { expect(context.dispatch).toHaveBeenCalledWith('REFRESH_PLAYER_STATE'); }); + it('publishes a progressing room timeline while subtitles remain pending after recovery', async () => { + const context = makeContext(); + const state = { playerState: 'buffering', maskPlayerState: true, isChangingSource: false }; + Object.defineProperties(context.getters, { + GET_MASK_PLAYER_STATE: { get: () => state.maskPlayerState }, + GET_PLAYER_STATE: { get: () => slplayerGetters.GET_PLAYER_STATE(state) }, + }); + context.commit.mockImplementation((type, value) => { + if (type === 'SET_MASK_PLAYER_STATE') state.maskPlayerState = value; + if (type === 'SET_IS_CHANGING_SOURCE') state.isChangingSource = value; + if (type === 'SET_PLAYER_STATE') state.playerState = value; + }); + let finishSubtitles; + const subtitles = new Promise((resolve) => { finishSubtitles = resolve; }); + let host; + const dispatch = context.dispatch.getMockImplementation(); + context.dispatch.mockImplementation((type, payload) => { + if (type === 'CHANGE_SUBTITLES') return subtitles; + if (['REFRESH_PLAYER_STATE', 'FETCH_TIMELINE_POLL_DATA'].includes(type)) { + return slplayerActions[type](context, payload); + } + if (type === 'synclounge/PROCESS_PLAYER_STATE_UPDATE') { + return slplayerActions.FETCH_TIMELINE_POLL_DATA(context).then((data) => { + host = { ...data, updatedAt: Date.now() }; + }); + } + return dispatch(type, payload); + }); + let result; + const recovery = slplayerActions.HANDLE_ERROR(context, error).then((value) => { result = value; }); + try { + await vi.waitFor(() => expect(result).toBe('recovered')); + expect(host).toMatchObject({ state: 'playing', time: 123000 }); + const clock = vi.spyOn(Date, 'now').mockReturnValue(host.updatedAt + 4000); + expect(roomGetters.GET_ADJUSTED_HOST_TIME({}, { GET_HOST_USER: host })()).toBe(127000); + clock.mockRestore(); + } finally { + finishSubtitles(); + await recovery; + } + }); + + const subtitleFailures = [new Error('Subtitle fetch failed'), null, undefined]; + it.each(subtitleFailures)('keeps video running after a late subtitle failure: %s', async (reason) => { + const context = makeContext(); + let failSubtitles; + const subtitles = new Promise((resolve, reject) => { failSubtitles = reject; }); + const dispatch = context.dispatch.getMockImplementation(); + context.dispatch.mockImplementation((type, payload) => (type === 'CHANGE_SUBTITLES' + ? subtitles : dispatch(type, payload))); + expect(await slplayerActions.HANDLE_ERROR(context, error)).toBe('recovered'); + failSubtitles(reason); + await vi.waitFor(() => { + expect(context.dispatch).toHaveBeenCalledWith('REPORT_PLAYBACK_DIAGNOSTIC', { event: 'subtitle-load-failed' }); + }); + expect(context.dispatch.mock.calls.filter(([type]) => type === 'LOAD_PLAYER_SRC')).toHaveLength(1); + expect(context.dispatch).toHaveBeenCalledWith('REFRESH_PLAYER_STATE'); + }); + + it('sends periodic reports for the next item without waiting for subtitles', async () => { + vi.useFakeTimers(); + const context = makeContext(); + context.rootGetters = { + 'plexclients/GET_ACTIVE_PLAY_QUEUE_SELECTED_ITEM': {}, + GET_CONFIG: { slplayer_plex_timeline_update_interval: 1000 }, + }; + const commit = context.commit.getMockImplementation(); + context.commit.mockImplementation((type, value) => { + if (type === 'SET_PLEX_TIMELINE_UPDATER_CANCEL_TOKEN') { + context.getters.GET_PLEX_TIMELINE_UPDATER_CANCEL_TOKEN = value; + } + commit(type, value); + }); + let finishSubtitles; + const subtitles = new Promise((resolve) => { finishSubtitles = resolve; }); + let cadence; + const dispatch = context.dispatch.getMockImplementation(); + context.dispatch.mockImplementation((type, payload) => { + if (type === 'CHANGE_SUBTITLES') return subtitles; + if (type === 'START_PERIODIC_PLEX_TIMELINE_UPDATE') { + cadence = slplayerActions[type](context, payload); + return cadence; + } + if (type === 'CANCEL_PERIODIC_PLEX_TIMELINE_UPDATE') return slplayerActions[type](context); + return dispatch(type, payload); + }); + const transition = slplayerActions.PLAY_ACTIVE_PLAY_QUEUE_SELECTED_ITEM(context); + try { + await vi.advanceTimersByTimeAsync(1000); + expect(context.dispatch).toHaveBeenCalledWith('REPORT_PLAYBACK_DIAGNOSTIC', { event: 'playback-health' }); + expect(context.dispatch).toHaveBeenCalledWith('SEND_PLEX_TIMELINE_UPDATE', { + signal: expect.objectContaining({ aborted: false }), + }); + } finally { + finishSubtitles(); + await transition; + slplayerActions.CANCEL_PERIODIC_PLEX_TIMELINE_UPDATE(context); + await cadence; + vi.useRealTimers(); + } + }); + it('does not show an exhausted notification after stopping at the diagnostic boundary', async () => { const context = makeContext(); for (let attempt = 0; attempt < 3; attempt += 1) await slplayerActions.HANDLE_ERROR(context, error); diff --git a/src/__tests__/subtitle-startup-lifecycle.test.js b/src/__tests__/subtitle-startup-lifecycle.test.js new file mode 100644 index 0000000000..f94dc5ef12 --- /dev/null +++ b/src/__tests__/subtitle-startup-lifecycle.test.js @@ -0,0 +1,121 @@ +/* eslint-disable max-classes-per-file -- Minimal parser and renderer test doubles. */ +import { + beforeEach, describe, expect, it, vi, +} from 'vitest'; +import actions from '@/store/modules/slplayer/subtitleActions'; +import { insertElementBeforeVideo } from '@/player'; + +const fixtures = vi.hoisted(() => ({ pending: [], renderers: [], signals: [] })); +vi.mock('@/player', () => ({ + insertElementBeforeVideo: vi.fn(), +})); +vi.mock('@/utils/fetchutils', () => ({ makeUrl: () => 'https://fixture.invalid/subtitles' })); +vi.mock('@/utils/streams', () => ({ + default: (url, signal) => { fixtures.signals.push(signal); return {}; }, +})); +vi.mock('synclounge-libjass', () => ({ + parser: { + StreamParser: class { + constructor() { + this.ass = Promise.resolve(); + this.minimalASS = new Promise((resolve) => { fixtures.pending.push(resolve); }); + } + }, + }, + renderers: { + WebRenderer: class { + constructor(ass) { + this._ass = ass; + this.libjassSubsWrapper = { remove: vi.fn() }; + fixtures.renderers.push(this); + } + }, + }, +})); + +const makeContext = () => { + const context = { + getters: { GET_DECISION_AND_START_PARAMS: {}, CAN_DIRECT_PLAY_SUBTITLES: false }, + commit: vi.fn(), + }; + context.dispatch = vi.fn((type, payload) => { + if (['PUBLISH_SUBTITLE_SIZE', 'RERENDER_SUBTITLE_CONTAINER', 'GET_OR_MAKE_VIDEO_CLOCK'].includes(type)) { + return Promise.resolve(); + } + return actions[type](context, payload); + }); + return context; +}; + +beforeEach(async () => { + await actions.DESTROY_SUBTITLES(makeContext()); + fixtures.pending.length = 0; + fixtures.renderers.length = 0; + fixtures.signals.length = 0; + vi.clearAllMocks(); +}); + +describe('subtitle startup ownership', () => { + it('cannot overwrite a newer track when the old parser finishes late', async () => { + const context = makeContext(); + const old = actions.SET_SUBTITLE_URL(context); + await vi.waitFor(() => expect(fixtures.pending).toHaveLength(1)); + const current = actions.SET_SUBTITLE_URL(context); + await vi.waitFor(() => expect(fixtures.pending).toHaveLength(2)); + expect(fixtures.signals[0].aborted).toBe(true); + const selected = { track: 'current' }; + fixtures.pending[1](selected); + await current; + fixtures.pending[0]({ track: 'old' }); + await old; + expect(fixtures.renderers).toHaveLength(1); + expect(fixtures.renderers[0]._ass).toBe(selected); + expect(insertElementBeforeVideo).toHaveBeenCalledExactlyOnceWith( + fixtures.renderers[0].libjassSubsWrapper, + ); + }); + + it('does not create a renderer after subtitles have been destroyed', async () => { + const context = makeContext(); + const pending = actions.SET_SUBTITLE_URL(context); + await vi.waitFor(() => expect(fixtures.pending).toHaveLength(1)); + await actions.DESTROY_SUBTITLES(context); + fixtures.pending[0]({ track: 'late' }); + await pending; + expect(fixtures.signals[0].aborted).toBe(true); + expect(fixtures.renderers).toHaveLength(0); + }); + + it('ignores a ready subtitle parser when its video source has been cancelled', async () => { + const context = makeContext(); + let cancelled = false; + const ensureCurrent = () => { + if (cancelled) throw new DOMException('Source cancelled', 'AbortError'); + }; + const pending = actions.SET_SUBTITLE_URL(context, { ensureCurrent }); + await vi.waitFor(() => expect(fixtures.pending).toHaveLength(1)); + cancelled = true; + fixtures.pending[0]({ track: 'cancelled' }); + await pending; + expect(fixtures.renderers).toHaveLength(0); + }); + + it('ignores an already-cancelled request without destroying current subtitles', async () => { + const context = makeContext(); + await actions.SET_SUBTITLE_URL(context, { + ensureCurrent: () => { throw new DOMException('Source cancelled', 'AbortError'); }, + }); + expect(context.dispatch).not.toHaveBeenCalled(); + expect(fixtures.renderers).toHaveLength(0); + }); + + it('only starts the latest of two simultaneous subtitle requests', async () => { + const context = makeContext(); + const first = actions.SET_SUBTITLE_URL(context); + const second = actions.SET_SUBTITLE_URL(context); + await vi.waitFor(() => expect(fixtures.pending).toHaveLength(1)); + fixtures.pending[0]({ track: 'latest' }); + await Promise.all([first, second]); + expect(fixtures.renderers).toHaveLength(1); + }); +}); diff --git a/src/store/modules/slplayer/actions.js b/src/store/modules/slplayer/actions.js index 1bd63cf2d3..ec04d03083 100644 --- a/src/store/modules/slplayer/actions.js +++ b/src/store/modules/slplayer/actions.js @@ -120,7 +120,12 @@ export default { transcodeCode: getters.GET_PLEX_DECISION?.MediaContainer?.transcodeDecisionCode, }, }, - playback: getPlaybackDiagnostics(), + playback: { + ...getPlaybackDiagnostics(), + reportedState: getters.GET_PLAYER_STATE, + sourceChanging: state.isChangingSource, + stateMasked: getters.GET_MASK_PLAYER_STATE, + }, details, }; rememberDiagnostic(diagnostic); @@ -217,14 +222,14 @@ export default { await dispatch('CHANGE_PLAYER_SRC', options); }, - CHANGE_SUBTITLES: async ({ getters, dispatch }) => { + CHANGE_SUBTITLES: async ({ getters, dispatch }, options) => { console.debug('CHANGE_SUBTITLES:', { isUsingNative: getters.IS_USING_NATIVE_SUBTITLES, subtitleStreamId: getters.GET_SUBTITLE_STREAM_ID, canDirectPlaySubs: getters.CAN_DIRECT_PLAY_SUBTITLES, }); if (getters.IS_USING_NATIVE_SUBTITLES) { - await dispatch('SET_SUBTITLE_URL'); + await dispatch('SET_SUBTITLE_URL', options); } else { await dispatch('DESTROY_ASS'); } @@ -254,8 +259,7 @@ export default { commit('SET_SESSION', getRandomPlexId()); - // Suppress seeking/seeked event handlers during source change to prevent them - // from aborting the subtitle fetch that CHANGE_SUBTITLES starts below. + // Suppress intermediate player events until the replacement stream has loaded. commit('SET_IS_CHANGING_SOURCE', true); try { @@ -279,9 +283,6 @@ export default { ensureCurrent(); } - await dispatch('CHANGE_SUBTITLES'); - ensureCurrent(); - // TODO: potentially avoid sending updates on media change since we already do that if (getters.GET_MASK_PLAYER_STATE) { commit('SET_MASK_PLAYER_STATE', false); @@ -297,6 +298,17 @@ export default { if (revision === sourceRevision) commit('SET_IS_CHANGING_SOURCE', false); } ensureCurrent(); + // Subtitle streams can remain pending while video is already playing. They must + // not mask the room timeline or prevent callers from restarting periodic reports. + // Each subtitle task guards its renderer writes against source replacement/stop. + Promise.resolve(dispatch('CHANGE_SUBTITLES', { ensureCurrent })).catch((error) => { + if (error?.name === 'AbortError' || revision !== sourceRevision) return; + dispatch('REPORT_PLAYBACK_DIAGNOSTIC', { event: 'subtitle-load-failed' }); + dispatch('DISPLAY_NOTIFICATION', { + text: 'Subtitles could not be loaded. Try selecting the subtitle track again.', + color: 'warning', + }, { root: true }); + }); // Publish readiness only after cancellation cleanup can no longer unload this source. await dispatch('REFRESH_PLAYER_STATE'); }, diff --git a/src/store/modules/slplayer/subtitleActions.js b/src/store/modules/slplayer/subtitleActions.js index d438e08893..29f0f8e917 100644 --- a/src/store/modules/slplayer/subtitleActions.js +++ b/src/store/modules/slplayer/subtitleActions.js @@ -10,16 +10,13 @@ import VideoClock from '@/utils/videoclock'; let videoClock = null; let subtitleRenderer = null; let assAbortController = null; +let subtitleRevision = 0; -const handleStreamError = async (assPromise) => { +const handleStreamError = async (assPromise, signal) => { try { await assPromise; } catch (e) { - if (assAbortController) { - // If there is no abort controller, we have just aborted - // If there is one, then something went wrong - throw e; - } + if (!signal.aborted) console.warn('Subtitle stream failed'); } }; @@ -59,8 +56,9 @@ export default { } }, - GET_OR_MAKE_VIDEO_CLOCK: async ({ getters, dispatch }) => { + GET_OR_MAKE_VIDEO_CLOCK: async ({ getters, dispatch }, { ensureCurrent = () => {} } = {}) => { const libjass = await import('synclounge-libjass'); + ensureCurrent(); if (!videoClock) { console.debug('GET_OR_MAKE_VIDEO_CLOCK: creating new VideoClock'); @@ -137,6 +135,7 @@ export default { }, DESTROY_ASS: async ({ dispatch, commit }) => { + subtitleRevision += 1; if (assAbortController) { console.debug('DESTROY_ASS'); assAbortController.abort(); @@ -158,7 +157,7 @@ export default { } }, - MAKE_ASS: async ({ getters }) => { + MAKE_ASS: async ({ getters }, { ensureCurrent = () => {} } = {}) => { const subtitleUrl = makeUrl( getters.GET_SUBTITLE_BASE_URL, getters.GET_DECISION_AND_START_PARAMS, @@ -167,6 +166,7 @@ export default { const libjass = await import('synclounge-libjass'); + ensureCurrent(); assAbortController = new AbortController(); const stream = resiliantStreamFactory( @@ -187,7 +187,7 @@ export default { if (!useSrtParser) { // Purposefully not awaited because we never get the full file at once // We still need to catch abort errors to clean up console - handleStreamError(parser.ass); + handleStreamError(parser.ass, assAbortController.signal); } return useSrtParser @@ -195,12 +195,15 @@ export default { : parser.minimalASS; }, - INIT_SUBTITLE_RENDERER: async ({ dispatch }, ass) => { + INIT_SUBTITLE_RENDERER: async ({ dispatch }, { ass, ensureCurrent }) => { console.debug('INIT_SUBTITLE_RENDERER'); const libjass = await import('synclounge-libjass'); + ensureCurrent(); + const clock = await dispatch('GET_OR_MAKE_VIDEO_CLOCK', { ensureCurrent }); + ensureCurrent(); subtitleRenderer = new libjass.renderers.WebRenderer( ass, - await dispatch('GET_OR_MAKE_VIDEO_CLOCK'), + clock, document.createElement('div'), subtitleSettings, ); @@ -208,12 +211,21 @@ export default { insertElementBeforeVideo(subtitleRenderer.libjassSubsWrapper); }, - SET_SUBTITLE_URL: async ({ dispatch }) => { + SET_SUBTITLE_URL: async ({ dispatch }, { ensureCurrent: ensureSource = () => {} } = {}) => { console.debug('SET_SUBTITLE_URL: starting'); - await dispatch('DESTROY_ASS'); - + let revision = subtitleRevision; + const ensureCurrent = () => { + ensureSource(); + if (revision !== subtitleRevision) throw new DOMException('Subtitles replaced', 'AbortError'); + }; try { - const ass = await dispatch('MAKE_ASS'); + ensureSource(); + const cleanup = dispatch('DESTROY_ASS'); + revision = subtitleRevision; + await cleanup; + ensureCurrent(); + const ass = await dispatch('MAKE_ASS', { ensureCurrent }); + ensureCurrent(); if (subtitleRenderer) { console.debug('SET_SUBTITLE_URL: updating existing renderer'); @@ -221,20 +233,19 @@ export default { subtitleRenderer._ass = ass; } else { console.debug('SET_SUBTITLE_URL: creating new renderer'); - await dispatch('INIT_SUBTITLE_RENDERER', ass); + await dispatch('INIT_SUBTITLE_RENDERER', { ass, ensureCurrent }); + ensureCurrent(); } await dispatch('PUBLISH_SUBTITLE_SIZE'); + ensureCurrent(); await dispatch('RERENDER_SUBTITLE_CONTAINER'); console.debug('SET_SUBTITLE_URL: complete'); } catch (e) { - if (assAbortController) { - // If there is no abort controller, we have just aborted - // If there is one, then something went wrong - console.warn('SET_SUBTITLE_URL: error loading subtitles:', e.message); - throw e; - } - console.debug('SET_SUBTITLE_URL: aborted (intentional)'); + if (e?.name === 'AbortError' || revision !== subtitleRevision) return; + ensureCurrent(); + console.warn('SET_SUBTITLE_URL: error loading subtitles'); + throw e; } }, diff --git a/test/playbackdiagnostics.test.js b/test/playbackdiagnostics.test.js index c72c3c0f23..d6a25fdcad 100644 --- a/test/playbackdiagnostics.test.js +++ b/test/playbackdiagnostics.test.js @@ -18,6 +18,9 @@ test('sanitizes structured playback diagnostics without accepting unrelated fiel browser: { name: 'firefox', os: 'Linux\nforged-log-line' }, playback: { currentTime: 10, + reportedState: 'buffering', + sourceChanging: true, + stateMasked: false, isCasting: true, buffering: false, bufferAhead: Number.POSITIVE_INFINITY, @@ -31,6 +34,9 @@ test('sanitizes structured playback diagnostics without accepting unrelated fiel assert.equal(diagnostic.browser.os, 'Linux forged-log-line'); assert.deepEqual(diagnostic.details, { episode: 3, durationMs: 142, attempt: 2 }); assert.equal(diagnostic.playback.currentTime, 10); + assert.equal(diagnostic.playback.reportedState, 'buffering'); + assert.equal(diagnostic.playback.sourceChanging, true); + assert.equal(diagnostic.playback.stateMasked, false); assert.equal(diagnostic.playback.isCasting, true); assert.equal(diagnostic.playback.buffering, false); assert.equal(diagnostic.playback.bufferAhead, null);