fix(scrobble): Improve dead scrobble iteration and logging · foxxmd.dev/multi-scrobbler@ec87ab9

+28 -28

src/backend/scrobblers/AbstractScrobbleClient.ts

··· 111 111 nowPlayingTaskInterval: number = 5000; 112 112 npLogger: Logger; 113 113 dupeLogger: Logger; 114 + deadLogger: Logger; 114 115 115 116 existingScrobble: (playObjPre: PlayObject, existingScrobbles: PlayObject[], log?: boolean) => Promise<PlayMatchResult> 116 117 ··· 137 138 this.logger = childLogger(logger, this.getIdentifier()); 138 139 this.npLogger = childLogger(this.logger, 'Now Playing'); 139 140 this.dupeLogger = childLogger(this.logger, 'Dupe'); 141 + this.deadLogger = childLogger(this.logger, 'Dead'); 140 142 this.notifier = notifier; 141 143 this.emitter = emitter; 142 144 this.scrobbledPlayObjs = new FixedSizeList<ScrobbledPlayObject>(this.MAX_STORED_SCROBBLES); ··· 762 764 const processable = this.deadLetterScrobbles.filter(x => x.retries < retries); 763 765 const queueStatus = `${processable.length} of ${this.deadLetterScrobbles.length} dead scrobbles have less than ${retries} retries, ${processable.length === 0 ? 'will skip processing.': 'processing now...'}`; 764 766 if (processable.length === 0) { 765 - this.logger.verbose({labels: 'Dead Letter'}, queueStatus); 767 + this.deadLogger.verbose(queueStatus); 766 768 return; 767 769 } 768 - this.logger.info({labels: 'Dead Letter'}, queueStatus); 770 + this.logger.info(queueStatus); 769 771 if(!this.upstreamRefresh.refreshEnabled) { 770 - this.logger.verbose({labels: 'Dead Letter'}, 'Scrobble refresh is DISABLED. All dead scrobbles will likely always be scrobbled (nothing to check duplicates against).'); 772 + this.deadLogger.verbose('Scrobble refresh is DISABLED. All dead scrobbles will likely always be scrobbled (nothing to check duplicates against).'); 771 773 } 772 774 this.handleQueuedScrobbleRanges(); 773 775 774 776 const removedIds = []; 775 - for (const deadScrobble of this.deadLetterScrobbles) { 776 - if (deadScrobble.retries < retries) { 777 - const [scrobbled, dead] = await this.processDeadLetterScrobble(deadScrobble.id); 778 - if (scrobbled) { 779 - removedIds.push(deadScrobble.id); 780 - } 777 + for (const deadScrobble of processable) { 778 + const [scrobbled, dead] = await this.processDeadLetterScrobble(deadScrobble.id); 779 + if (scrobbled) { 780 + removedIds.push(deadScrobble.id); 781 781 } 782 782 } 783 783 if (removedIds.length > 0) { 784 - this.logger.info({labels: 'Dead Letter'}, `Removed ${removedIds.length} scrobbles from dead letter queue`); 784 + this.deadLogger.info(`Removed ${removedIds.length} scrobbles from dead letter queue`); 785 785 } 786 786 } 787 787 788 788 processDeadLetterScrobble = async (id: string): Promise<[boolean, DeadLetterScrobble<PlayObject>?]> => { 789 789 const deadScrobbleIndex = this.deadLetterScrobbles.findIndex(x => x.id === id); 790 + if(deadScrobbleIndex === -1) { 791 + this.deadLogger.warn(`Could not find a dead scrobble with id ${id}`); 792 + return [false]; 793 + } 794 + const deadLabel = {labels: id}; 790 795 const deadScrobble = this.deadLetterScrobbles[deadScrobbleIndex]; 796 + this.deadLogger.trace(deadLabel, `Processing dead scrobble => ${buildTrackString(deadScrobble.play)}`); 791 797 792 798 if (!(await this.isReady())) { 793 - this.logger.warn({labels: 'Dead Letter'}, 'Cannot process dead letter scrobble because client is not ready.'); 799 + this.deadLogger.warn(deadLabel, 'Cannot process dead letter scrobble because client is not ready.'); 794 800 return [false, deadScrobble]; 795 801 } 796 802 let historicalPlays: PlayObject[] = []; ··· 799 805 historicalPlays = await this.getSOTScrobblesForPlay(deadScrobble.play); 800 806 } catch (e) { 801 807 if(e.message === 'Cannot get historical plays due to cached error') { 802 - this.logger.warn(`${buildTrackString(deadScrobble.play)} from Source '${deadScrobble.source}' => Previous error while getting historical scrobbles means this scrobble cannot be compared`); 803 - this.logger.trace(e); 808 + this.deadLogger.warn(deadLabel, `Previous error while getting historical scrobbles means this scrobble cannot be compared`); 809 + this.deadLogger.trace(e); 804 810 } else { 805 - this.logger.warn(new SimpleError(`${buildTrackString(deadScrobble.play)} from Source '${deadScrobble.source}' => cannot get historical scrobbles`, {cause: e, shortStack: true})); 811 + this.deadLogger.warn(new SimpleError(`${id} - ${buildTrackString(deadScrobble.play)} from Source '${deadScrobble.source}' => cannot get historical scrobbles`, {cause: e, shortStack: true})); 806 812 } 807 813 deadScrobble.retries++; 808 814 deadScrobble.error = messageWithCauses(e); ··· 832 838 const scrobbledPlay = await this.scrobble(transformedScrobble); 833 839 this.emitEvent('scrobble', {play: transformedScrobble}); 834 840 this.addScrobbledTrack(transformedScrobble, scrobbledPlay); 841 + this.removeDeadLetterScrobble(deadScrobble.id) 835 842 } catch (e) { 836 843 837 844 const submitError = findCauseByReference(e, ScrobbleSubmitError); ··· 847 854 deadScrobble.retries++; 848 855 deadScrobble.error = messageWithCauses(e); 849 856 deadScrobble.lastRetry = dayjs(); 850 - this.logger.error(new Error(`Could not scrobble ${buildTrackString(transformedScrobble)} from Source '${deadScrobble.source}' due to error`, {cause: e})); 857 + this.deadLogger.error(new Error(`${id} - Could not scrobble ${buildTrackString(transformedScrobble)} from Source '${deadScrobble.source}' due to error`, {cause: e})); 851 858 this.deadLetterScrobbles[deadScrobbleIndex] = deadScrobble; 852 859 this.updateDeadLetterCache(); 853 860 return [false, deadScrobble]; 854 861 } finally { 855 862 await sleep(1000); 856 863 } 857 - } 858 - if(deadScrobble !== undefined) { 864 + } else { 865 + this.deadLogger.verbose(`Looks like ${buildTrackString(deadScrobble.play)} was already scrobbled!\n${summary}`); 859 866 this.removeDeadLetterScrobble(deadScrobble.id) 860 867 } 861 868 862 - return [true]; 869 + return [true, deadScrobble]; 863 870 } 864 871 865 872 removeDeadLetterScrobble = (id: string) => { 866 873 const index = this.deadLetterScrobbles.findIndex(x => x.id === id); 867 874 if (index === -1) { 868 - this.logger.warn(`No scrobble found with ID ${id}`, {leaf: 'Dead Letter'}); 875 + this.deadLogger.warn(`No scrobble found with ID ${id}`); 869 876 } 870 - this.logger.info(`Removed scrobble ${buildTrackString(this.deadLetterScrobbles[index].play)} from queue`, {leaf: 'Dead Letter'}); 877 + this.deadLogger.info({labels: id}, `Removed scrobble ${buildTrackString(this.deadLetterScrobbles[index].play)} from queue`); 871 878 this.deadLetterScrobbles.splice(index, 1); 872 879 this.deadLetterGauge.labels(this.getPrometheusLabels()).set(this.deadLetterScrobbles.length); 873 880 this.updateDeadLetterCache(); ··· 878 885 this.updateDeadLetterCache(); 879 886 this.deadLetterGauge.labels(this.getPrometheusLabels()).set(this.deadLetterScrobbles.length); 880 887 this.logger.info('Removed all scrobbles from queue', {leaf: 'Dead Letter'}); 881 - } 882 - 883 - protected getLatestQueuePlayDate = () => { 884 - if (this.queuedScrobbles.length === 0) { 885 - return undefined; 886 - } 887 - return this.queuedScrobbles[this.queuedScrobbles.length - 1].play.data.playDate; 888 888 } 889 889 890 890 queueScrobble = async (data: PlayObject | PlayObject[], source: string) => { ··· 923 923 return (beforeMain + beforeDead) - (this.queuedScrobbles.length + this.deadLetterScrobbles.length); 924 924 } 925 925 926 - protected addDeadLetterScrobble = (data: QueuedScrobble<PlayObject>, error: (Error | string) = 'Unspecified error') => { 926 + addDeadLetterScrobble = (data: QueuedScrobble<PlayObject>, error: (Error | string) = 'Unspecified error') => { 927 927 let eString = ''; 928 928 if(typeof error === 'string') { 929 929 eString = error;

+2 -2

src/backend/server/api.ts

··· 331 331 332 332 (client as AbstractScrobbleClient).logger.verbose('User requested processing of all dead letter scrobbles via API'); 333 333 334 - await (client as AbstractScrobbleClient).processDeadLetterQueue(1000); 334 + await ((client as AbstractScrobbleClient).processDeadLetterQueue(1000)); 335 335 336 336 const result: DeadLetterScrobble<PlayObject>[] = (client as AbstractScrobbleClient).deadLetterScrobbles; 337 337 ··· 358 358 return res.status(404).send(); 359 359 } 360 360 361 - const [scrobbled, dead] = await (client as AbstractScrobbleClient).processDeadLetterScrobble(deadId); 361 + const [scrobbled, dead] = await ((client as AbstractScrobbleClient).processDeadLetterScrobble(deadId)); 362 362 363 363 if(scrobbled) { 364 364 return res.status(200).send();

+19

src/backend/tests/scrobbler/scrobblers.test.ts

··· 21 21 import { shuffleArray } from '../../utils/DataUtils.js'; 22 22 import { DEFAULT_CONSOLIDATE_DURATION, DEFAULT_GROUP_DURATION, groupPlaysToTimeRanges } from '../../utils/ListenFetchUtils.js'; 23 23 import { asPlay } from '../../../core/tests/utils/fixtures.js'; 24 + import { nanoid } from 'nanoid'; 24 25 25 26 chai.use(asPromised); 26 27 ··· 592 593 await emptied2; 593 594 scrobbler.tryStopScrobbling().then(() => null); 594 595 expect(sp.calledTwice).is.true; 596 + }); 597 + 598 + }); 599 + 600 + describe('Dead Scrobbles', function() { 601 + 602 + it('Processes all dead scrobbles', async function () { 603 + 604 + testScrobbler = generateTestScrobbler(); 605 + await testScrobbler.initialize(); 606 + testScrobbler.testRecentScrobbles = []; 607 + 608 + const deadPlays = generatePlays(3); 609 + for(const dead of deadPlays) { 610 + testScrobbler.addDeadLetterScrobble({source: 'test', play: dead, id: nanoid()}); 611 + } 612 + await testScrobbler.processDeadLetterQueue(); 613 + expect(testScrobbler.deadLetterScrobbles.length).eq(0); 595 614 }); 596 615 597 616 });

Configure Feed

Configure Feed