From ec87ab96d6679c3d28dcdf9d8c664fef3a73b1df Mon Sep 17 00:00:00 2001 From: FoxxMD Date: Mon, 16 Mar 2026 18:38:28 +0000 Subject: [PATCH] fix(scrobble): Improve dead scrobble iteration and logging * Use filtered, processable scrobbles in for-loop to avoid any weird in-place array splice issues when iterating * Add more logging with labels/ids to make logging more readable * Move dead scrobble removal function closer blocks where it should happen --- .../scrobblers/AbstractScrobbleClient.ts | 56 +++++++++---------- src/backend/server/api.ts | 4 +- .../tests/scrobbler/scrobblers.test.ts | 19 +++++++ 3 files changed, 49 insertions(+), 30 deletions(-) diff --git a/src/backend/scrobblers/AbstractScrobbleClient.ts b/src/backend/scrobblers/AbstractScrobbleClient.ts index 71f82a71..99a52ccd 100644 --- a/src/backend/scrobblers/AbstractScrobbleClient.ts +++ b/src/backend/scrobblers/AbstractScrobbleClient.ts @@ -111,6 +111,7 @@ export default abstract class AbstractScrobbleClient extends AbstractComponent i nowPlayingTaskInterval: number = 5000; npLogger: Logger; dupeLogger: Logger; + deadLogger: Logger; existingScrobble: (playObjPre: PlayObject, existingScrobbles: PlayObject[], log?: boolean) => Promise @@ -137,6 +138,7 @@ export default abstract class AbstractScrobbleClient extends AbstractComponent i this.logger = childLogger(logger, this.getIdentifier()); this.npLogger = childLogger(this.logger, 'Now Playing'); this.dupeLogger = childLogger(this.logger, 'Dupe'); + this.deadLogger = childLogger(this.logger, 'Dead'); this.notifier = notifier; this.emitter = emitter; this.scrobbledPlayObjs = new FixedSizeList(this.MAX_STORED_SCROBBLES); @@ -762,35 +764,39 @@ export default abstract class AbstractScrobbleClient extends AbstractComponent i const processable = this.deadLetterScrobbles.filter(x => x.retries < retries); const queueStatus = `${processable.length} of ${this.deadLetterScrobbles.length} dead scrobbles have less than ${retries} retries, ${processable.length === 0 ? 'will skip processing.': 'processing now...'}`; if (processable.length === 0) { - this.logger.verbose({labels: 'Dead Letter'}, queueStatus); + this.deadLogger.verbose(queueStatus); return; } - this.logger.info({labels: 'Dead Letter'}, queueStatus); + this.logger.info(queueStatus); if(!this.upstreamRefresh.refreshEnabled) { - this.logger.verbose({labels: 'Dead Letter'}, 'Scrobble refresh is DISABLED. All dead scrobbles will likely always be scrobbled (nothing to check duplicates against).'); + this.deadLogger.verbose('Scrobble refresh is DISABLED. All dead scrobbles will likely always be scrobbled (nothing to check duplicates against).'); } this.handleQueuedScrobbleRanges(); const removedIds = []; - for (const deadScrobble of this.deadLetterScrobbles) { - if (deadScrobble.retries < retries) { - const [scrobbled, dead] = await this.processDeadLetterScrobble(deadScrobble.id); - if (scrobbled) { - removedIds.push(deadScrobble.id); - } + for (const deadScrobble of processable) { + const [scrobbled, dead] = await this.processDeadLetterScrobble(deadScrobble.id); + if (scrobbled) { + removedIds.push(deadScrobble.id); } } if (removedIds.length > 0) { - this.logger.info({labels: 'Dead Letter'}, `Removed ${removedIds.length} scrobbles from dead letter queue`); + this.deadLogger.info(`Removed ${removedIds.length} scrobbles from dead letter queue`); } } processDeadLetterScrobble = async (id: string): Promise<[boolean, DeadLetterScrobble?]> => { const deadScrobbleIndex = this.deadLetterScrobbles.findIndex(x => x.id === id); + if(deadScrobbleIndex === -1) { + this.deadLogger.warn(`Could not find a dead scrobble with id ${id}`); + return [false]; + } + const deadLabel = {labels: id}; const deadScrobble = this.deadLetterScrobbles[deadScrobbleIndex]; + this.deadLogger.trace(deadLabel, `Processing dead scrobble => ${buildTrackString(deadScrobble.play)}`); if (!(await this.isReady())) { - this.logger.warn({labels: 'Dead Letter'}, 'Cannot process dead letter scrobble because client is not ready.'); + this.deadLogger.warn(deadLabel, 'Cannot process dead letter scrobble because client is not ready.'); return [false, deadScrobble]; } let historicalPlays: PlayObject[] = []; @@ -799,10 +805,10 @@ export default abstract class AbstractScrobbleClient extends AbstractComponent i historicalPlays = await this.getSOTScrobblesForPlay(deadScrobble.play); } catch (e) { if(e.message === 'Cannot get historical plays due to cached error') { - this.logger.warn(`${buildTrackString(deadScrobble.play)} from Source '${deadScrobble.source}' => Previous error while getting historical scrobbles means this scrobble cannot be compared`); - this.logger.trace(e); + this.deadLogger.warn(deadLabel, `Previous error while getting historical scrobbles means this scrobble cannot be compared`); + this.deadLogger.trace(e); } else { - this.logger.warn(new SimpleError(`${buildTrackString(deadScrobble.play)} from Source '${deadScrobble.source}' => cannot get historical scrobbles`, {cause: e, shortStack: true})); + this.deadLogger.warn(new SimpleError(`${id} - ${buildTrackString(deadScrobble.play)} from Source '${deadScrobble.source}' => cannot get historical scrobbles`, {cause: e, shortStack: true})); } deadScrobble.retries++; deadScrobble.error = messageWithCauses(e); @@ -832,6 +838,7 @@ export default abstract class AbstractScrobbleClient extends AbstractComponent i const scrobbledPlay = await this.scrobble(transformedScrobble); this.emitEvent('scrobble', {play: transformedScrobble}); this.addScrobbledTrack(transformedScrobble, scrobbledPlay); + this.removeDeadLetterScrobble(deadScrobble.id) } catch (e) { const submitError = findCauseByReference(e, ScrobbleSubmitError); @@ -847,27 +854,27 @@ export default abstract class AbstractScrobbleClient extends AbstractComponent i deadScrobble.retries++; deadScrobble.error = messageWithCauses(e); deadScrobble.lastRetry = dayjs(); - this.logger.error(new Error(`Could not scrobble ${buildTrackString(transformedScrobble)} from Source '${deadScrobble.source}' due to error`, {cause: e})); + this.deadLogger.error(new Error(`${id} - Could not scrobble ${buildTrackString(transformedScrobble)} from Source '${deadScrobble.source}' due to error`, {cause: e})); this.deadLetterScrobbles[deadScrobbleIndex] = deadScrobble; this.updateDeadLetterCache(); return [false, deadScrobble]; } finally { await sleep(1000); } - } - if(deadScrobble !== undefined) { + } else { + this.deadLogger.verbose(`Looks like ${buildTrackString(deadScrobble.play)} was already scrobbled!\n${summary}`); this.removeDeadLetterScrobble(deadScrobble.id) } - return [true]; + return [true, deadScrobble]; } removeDeadLetterScrobble = (id: string) => { const index = this.deadLetterScrobbles.findIndex(x => x.id === id); if (index === -1) { - this.logger.warn(`No scrobble found with ID ${id}`, {leaf: 'Dead Letter'}); + this.deadLogger.warn(`No scrobble found with ID ${id}`); } - this.logger.info(`Removed scrobble ${buildTrackString(this.deadLetterScrobbles[index].play)} from queue`, {leaf: 'Dead Letter'}); + this.deadLogger.info({labels: id}, `Removed scrobble ${buildTrackString(this.deadLetterScrobbles[index].play)} from queue`); this.deadLetterScrobbles.splice(index, 1); this.deadLetterGauge.labels(this.getPrometheusLabels()).set(this.deadLetterScrobbles.length); this.updateDeadLetterCache(); @@ -880,13 +887,6 @@ export default abstract class AbstractScrobbleClient extends AbstractComponent i this.logger.info('Removed all scrobbles from queue', {leaf: 'Dead Letter'}); } - protected getLatestQueuePlayDate = () => { - if (this.queuedScrobbles.length === 0) { - return undefined; - } - return this.queuedScrobbles[this.queuedScrobbles.length - 1].play.data.playDate; - } - queueScrobble = async (data: PlayObject | PlayObject[], source: string) => { const plays = (Array.isArray(data) ? data : [data]).map(x => ({...x, meta: {...x.meta, seenAt: dayjs()}})); for await(const play of pMapIterable(plays, this.staggerMappers.preCompare(async x => await this.transformPlay(x, TRANSFORM_HOOK.preCompare)), {concurrency: 2})) { @@ -923,7 +923,7 @@ export default abstract class AbstractScrobbleClient extends AbstractComponent i return (beforeMain + beforeDead) - (this.queuedScrobbles.length + this.deadLetterScrobbles.length); } - protected addDeadLetterScrobble = (data: QueuedScrobble, error: (Error | string) = 'Unspecified error') => { + addDeadLetterScrobble = (data: QueuedScrobble, error: (Error | string) = 'Unspecified error') => { let eString = ''; if(typeof error === 'string') { eString = error; diff --git a/src/backend/server/api.ts b/src/backend/server/api.ts index ff63e172..9e7a1489 100644 --- a/src/backend/server/api.ts +++ b/src/backend/server/api.ts @@ -331,7 +331,7 @@ export const setupApi = (app: ExpressWithAsync, logger: Logger, appLoggerStream: (client as AbstractScrobbleClient).logger.verbose('User requested processing of all dead letter scrobbles via API'); - await (client as AbstractScrobbleClient).processDeadLetterQueue(1000); + await ((client as AbstractScrobbleClient).processDeadLetterQueue(1000)); const result: DeadLetterScrobble[] = (client as AbstractScrobbleClient).deadLetterScrobbles; @@ -358,7 +358,7 @@ export const setupApi = (app: ExpressWithAsync, logger: Logger, appLoggerStream: return res.status(404).send(); } - const [scrobbled, dead] = await (client as AbstractScrobbleClient).processDeadLetterScrobble(deadId); + const [scrobbled, dead] = await ((client as AbstractScrobbleClient).processDeadLetterScrobble(deadId)); if(scrobbled) { return res.status(200).send(); diff --git a/src/backend/tests/scrobbler/scrobblers.test.ts b/src/backend/tests/scrobbler/scrobblers.test.ts index c0c9d820..224f9666 100644 --- a/src/backend/tests/scrobbler/scrobblers.test.ts +++ b/src/backend/tests/scrobbler/scrobblers.test.ts @@ -21,6 +21,7 @@ import { defaultLifecycle } from '../../utils/PlayTransformUtils.js'; import { shuffleArray } from '../../utils/DataUtils.js'; import { DEFAULT_CONSOLIDATE_DURATION, DEFAULT_GROUP_DURATION, groupPlaysToTimeRanges } from '../../utils/ListenFetchUtils.js'; import { asPlay } from '../../../core/tests/utils/fixtures.js'; +import { nanoid } from 'nanoid'; chai.use(asPromised); @@ -596,6 +597,24 @@ describe('Upstream Scrobbles', function() { }); +describe('Dead Scrobbles', function() { + + it('Processes all dead scrobbles', async function () { + + testScrobbler = generateTestScrobbler(); + await testScrobbler.initialize(); + testScrobbler.testRecentScrobbles = []; + + const deadPlays = generatePlays(3); + for(const dead of deadPlays) { + testScrobbler.addDeadLetterScrobble({source: 'test', play: dead, id: nanoid()}); + } + await testScrobbler.processDeadLetterQueue(); + expect(testScrobbler.deadLetterScrobbles.length).eq(0); + }); + +}); + describe('Scrobble client uses transform plays correctly', function() { -- 2.51.2