From 1eab06c51dc875de01cbf8d8e3f9d65c49687109 Mon Sep 17 00:00:00 2001 From: FoxxMD Date: Wed, 3 Dec 2025 17:04:42 +0000 Subject: [PATCH] recfactor(transform): Use async hooks for logging to identify transform Reduces logging noise --- package-lock.json | 8 +++--- package.json | 2 +- src/backend/common/AbstractComponent.ts | 20 +++++++------- .../common/transforms/AbstractTransformer.ts | 26 +++++++++--------- .../transforms/MusicbrainzTransformer.ts | 27 +++++++++---------- .../common/transforms/NativeTransformer.ts | 3 --- .../common/transforms/TransformerManager.ts | 22 ++++++++------- .../common/transforms/UserTransformer.ts | 3 --- .../musicbrainz/MusicbrainzApiClient.ts | 2 +- src/backend/tests/ytm/ytm.test.ts | 2 +- 10 files changed, 57 insertions(+), 58 deletions(-) diff --git a/package-lock.json b/package-lock.json index c352121b..36262411 100644 --- a/package-lock.json +++ b/package-lock.json @@ -22,7 +22,7 @@ "@fortawesome/react-fontawesome": "^0.2.0", "@foxxmd/chromecast-client": "^1.0.4", "@foxxmd/get-version": "^0.0.3", - "@foxxmd/logging": "^0.2.3", + "@foxxmd/logging": "^0.2.4", "@foxxmd/redact-string": "^0.1.2", "@foxxmd/regex-buddy-core": "^0.1.2", "@foxxmd/string-sameness": "^0.4.0", @@ -1634,9 +1634,9 @@ } }, "node_modules/@foxxmd/logging": { - "version": "0.2.3", - "resolved": "https://registry.npmjs.org/@foxxmd/logging/-/logging-0.2.3.tgz", - "integrity": "sha512-KMqWy42niMLMyz8YmQ09XVay5szhU2Y8lWzM3Fbm+zyfFRTiaYCSal5tQSeWmVdjps6LqtQNGDH4KG5a3Wgnrw==", + "version": "0.2.4", + "resolved": "https://registry.npmjs.org/@foxxmd/logging/-/logging-0.2.4.tgz", + "integrity": "sha512-pBqfs7OVtRtdmqyfF7eIRMGTpv8aOQwss7ROBt5HdF+0dnmmyz9HMcc9FHKSV2WzhV5K55+DTzPfrwJlFedFbg==", "license": "MIT", "dependencies": { "pino": "^9.2.0", diff --git a/package.json b/package.json index 28d47425..613c56aa 100644 --- a/package.json +++ b/package.json @@ -54,7 +54,7 @@ "@fortawesome/react-fontawesome": "^0.2.0", "@foxxmd/chromecast-client": "^1.0.4", "@foxxmd/get-version": "^0.0.3", - "@foxxmd/logging": "^0.2.3", + "@foxxmd/logging": "^0.2.4", "@foxxmd/redact-string": "^0.1.2", "@foxxmd/regex-buddy-core": "^0.1.2", "@foxxmd/string-sameness": "^0.4.0", diff --git a/src/backend/common/AbstractComponent.ts b/src/backend/common/AbstractComponent.ts index f950b841..f9733e05 100644 --- a/src/backend/common/AbstractComponent.ts +++ b/src/backend/common/AbstractComponent.ts @@ -19,6 +19,7 @@ import AbstractInitializable from "./AbstractInitializable.js"; import play = Simulate.play; import TransformerManager from "./transforms/TransformerManager.js"; import { getRoot } from "../ioc.js"; +import { nanoid } from "nanoid"; export default abstract class AbstractComponent extends AbstractInitializable { @@ -154,9 +155,9 @@ export default abstract class AbstractComponent extends AbstractInitializable { public transformPlay = async (play: PlayObject, hookType: TransformHook, log?: boolean) => { - let logger: Logger; - const labels = ['Play Transform', hookType]; - const getLogger = () => logger !== undefined ? logger : childLogger(this.logger, labels); + + const asyncId = nanoid(6); + let logger = childLogger(this.logger, ['Play Transform', hookType, asyncId]); try { let hook: StageConfig[]; @@ -180,6 +181,7 @@ export default abstract class AbstractComponent extends AbstractInitializable { return play; } + logger.debug(`Transform start for => ${buildTrackString(play)}`); let transformedPlay: PlayObject = play; let transformDetails: string[] = []; for(const hookItem of hook) { @@ -193,16 +195,16 @@ export default abstract class AbstractComponent extends AbstractInitializable { let newTransformedPlay: PlayObject; let err: Error; try { - newTransformedPlay = await this.transformManager.handleStage(hookItem, transformedPlay); + newTransformedPlay = await this.transformManager.handleStage(hookItem, transformedPlay, asyncId); } catch (e) { err = e; } if(err !== undefined) { if(onFailure === 'continue') { - this.logger.warn(new Error('A transform encountered an error but continuing due to onFailure: continue', {cause: err})); + logger.warn(new Error(`A transform encountered an error but continuing due to onFailure: continue`, {cause: err})); } else { - this.logger.error(new Error('Transform encountered an error', {cause: err})); + logger.error(new Error(`Transform encountered an error`, {cause: err})); if(!failureReturnPartial) { // rewind to original play so we don't return partial transform transformedPlay = play; @@ -218,7 +220,7 @@ export default abstract class AbstractComponent extends AbstractInitializable { transformedPlay = newTransformedPlay; if(err === undefined && onSuccess === 'stop') { - this.logger.debug('Stopping transform due to onSuccess: stop'); + logger.debug(`${nanoid} Stopping transform due to onSuccess: stop`); break; } } @@ -232,12 +234,12 @@ export default abstract class AbstractComponent extends AbstractInitializable { } else { transformStatements.push(`=> ${transformDetails[transformDetails.length - 1]}`); } - this.logger.debug({labels: [...labels, hookType]}, `Transform Pipeline:\n${transformStatements.join('\n')}`); + logger.debug({labels: [hookType]}, `Transform Pipeline:\n${transformStatements.join('\n')}`); } } return transformedPlay; } catch (e) { - getLogger().warn(new Error(`Unexpected error occurred, returning original play.`, {cause: e})); + logger.warn(new Error(`Unexpected error occurred, returning original play.`, {cause: e})); return play; } } diff --git a/src/backend/common/transforms/AbstractTransformer.ts b/src/backend/common/transforms/AbstractTransformer.ts index 82f422f2..fff470e4 100644 --- a/src/backend/common/transforms/AbstractTransformer.ts +++ b/src/backend/common/transforms/AbstractTransformer.ts @@ -1,6 +1,5 @@ import { childLogger, Logger } from "@foxxmd/logging"; import { PlayObject, TransformerCommon, TransformerCommonConfig } from "../../../core/Atomic.js"; -import { getRoot } from "../../ioc.js"; import { isStageTyped, testWhenConditions } from "../../utils/PlayTransformUtils.js"; import AbstractInitializable from "../AbstractInitializable.js"; import { StageConfig } from "../infrastructure/Transform.js"; @@ -8,8 +7,8 @@ import { cacheFunctions, parseToRegexOrLiteralSearch, testMaybeRegex, searchAnd import { Cacheable } from "cacheable"; import { hashObject } from "../../utils/StringUtils.js"; import { playContentInvariantTransform } from "../../utils/PlayComparisonUtils.js"; -import e from "express"; import { isSimpleError } from "../errors/MSErrors.js"; +import { capitalize } from "../../../core/StringUtils.js"; export interface TransformerOptions { logger: Logger @@ -38,11 +37,15 @@ export default abstract class AbstractTransformer { - const cacheKey = `${this.configHash}-${hashObject(data)}-${hashObject(playContentInvariantTransform(play))}` try { const cachedTransform = await this.cache.get(cacheKey); if(cachedTransform !== undefined) { - this.logger.debug('Cache hit'); + this.logger.debug('Transform cache hit'); return cachedTransform; } } catch (e) { - this.logger.warn(new Error('Could not fetch cache key', {cause: e})); + this.logger.warn(new Error(`Could not fetch cache key ${cacheKey}`, {cause: e})); } if (data.when !== undefined) { if (!testWhenConditions(data.when, play, { testMaybeRegex: this.regex.testMaybeRegex })) { - this.logger.debug('When condition not met, returning original Play'); + this.logger.debug('Returning original Play because because when condition not met'); await this.cache.set(cacheKey, play, '15s'); return play; } @@ -79,9 +81,9 @@ export default abstract class AbstractTransformer { const clean = str.trim().toLocaleLowerCase(); @@ -115,7 +111,7 @@ export default class MusicbrainzTransformer extends AtomicPartsTransformer 0) { - this.logger.debug(`${buildTrackString(play)} - Missing desired MBIDs for ${missing.join(', ')}`); + this.logger.debug(`Missing desired MBIDs for: ${missing.join(', ')}`); } else if(forceSearch) { - this.logger.debug(`${buildTrackString(play)} - No desired MBIDs are missing but forceSearch = true`); + this.logger.debug(`No desired MBIDs are missing but forceSearch = true`); } else { throw new SimpleError('No desired MBIDs are missing'); } @@ -170,9 +166,11 @@ export default class MusicbrainzTransformer extends AtomicPartsTransformer { if(transformData === undefined) { - throw new SimpleError('No match returned from Musicbrainz API'); + throw new SimpleError('No matches returned from Musicbrainz API'); } const { @@ -192,6 +190,8 @@ export default class MusicbrainzTransformer extends AtomicPartsTransformer { @@ -251,8 +251,5 @@ export default class MusicbrainzTransformer extends AtomicPartsTransformer { return; } - protected getIdentifier(): string { - return 'Musicbrainz Transformer'; - } } \ No newline at end of file diff --git a/src/backend/common/transforms/NativeTransformer.ts b/src/backend/common/transforms/NativeTransformer.ts index 7b86fafd..e99e6c0c 100644 --- a/src/backend/common/transforms/NativeTransformer.ts +++ b/src/backend/common/transforms/NativeTransformer.ts @@ -234,8 +234,5 @@ export default class NativeTransformer extends AtomicPartsTransformer { return; } - protected getIdentifier(): string { - return 'Native Transformer'; - } } \ No newline at end of file diff --git a/src/backend/common/transforms/TransformerManager.ts b/src/backend/common/transforms/TransformerManager.ts index 0de6410e..bfe01515 100644 --- a/src/backend/common/transforms/TransformerManager.ts +++ b/src/backend/common/transforms/TransformerManager.ts @@ -7,11 +7,9 @@ import { PlayObject } from "../../../core/Atomic.js"; import { isStageTyped } from "../../utils/PlayTransformUtils.js"; import { MSCache } from "../Cache.js"; import NativeTransformer from "./NativeTransformer.js"; -import { MusicbrainzApiClient } from "../vendor/musicbrainz/MusicbrainzApiClient.js"; -import { MUSICBRAINZ_URL, MusicbrainzApiConfigData } from "../infrastructure/Atomic.js"; -import { normalizeWebAddress } from "../../utils/NetworkUtils.js"; -import { MusicBrainzApi } from "musicbrainz-api"; import MusicbrainzTransformer, { MusicbrainzTransformerConfig } from "./MusicbrainzTransformer.js"; +import { AsyncLocalStorage } from 'node:async_hooks'; +import { nanoid } from "nanoid"; export default class TransformerManager { @@ -19,11 +17,13 @@ export default class TransformerManager { protected parentLogger: Logger; protected transformers: Map = new Map(); protected cache: MSCache; + protected asyncStore: AsyncLocalStorage; public constructor(logger: Logger, cache: MSCache) { this.logger = childLogger(logger, 'Transformer Manager'); this.parentLogger = logger; this.cache = cache; + this.asyncStore = new AsyncLocalStorage(); } public register(config: TransformerCommonConfig): void { @@ -41,16 +41,18 @@ export default class TransformerManager { this.logger.verbose(`Registering ${config.type} transformer with name '${tName}'`); + const tLogger = childLogger(this.parentLogger, ['Transformer', () => this.asyncStore.getStore() ?? undefined]); + let t: AbstractTransformer; switch (config.type) { case 'user': - t = new UserTransformer({ name: tName, ...config }, {logger: this.parentLogger, regexCache: this.cache.regexCache, cache: this.cache.cacheTransform}); + t = new UserTransformer({ name: tName, ...config }, {logger: tLogger, regexCache: this.cache.regexCache, cache: this.cache.cacheTransform}); break; case 'native': - t = new NativeTransformer({ name: tName, ...config }, {logger: this.parentLogger, regexCache: this.cache.regexCache, cache: this.cache.cacheTransform}); + t = new NativeTransformer({ name: tName, ...config }, {logger: tLogger, regexCache: this.cache.regexCache, cache: this.cache.cacheTransform}); break; case 'musicbrainz': - t = new MusicbrainzTransformer({ name: tName, ...config as MusicbrainzTransformerConfig }, {logger: this.parentLogger, regexCache: this.cache.regexCache, cache: this.cache.cacheTransform}); + t = new MusicbrainzTransformer({ name: tName, ...config as MusicbrainzTransformerConfig }, {logger: tLogger, regexCache: this.cache.regexCache, cache: this.cache.cacheTransform}); break; default: throw new Error(`No transformer of type '${config.type}' exists.`); @@ -104,7 +106,7 @@ export default class TransformerManager { return t.parseConfig(data); } - public async handleStage(data: StageConfig, play: PlayObject): Promise { + public async handleStage(data: StageConfig, play: PlayObject, asyncId: string = nanoid(6)): Promise { const list = this.transformers.get(data.type); if (list === undefined || list.length === 0) { throw new Error(`No transformer of type '${data.type}' is registered.`); @@ -127,7 +129,9 @@ export default class TransformerManager { } try { - return await t.handle(data, play); + return this.asyncStore.run(asyncId, async () => { + return await t.handle(data, play); + }); } catch (e) { throw new Error('Stage processing failed', {cause: e}); } diff --git a/src/backend/common/transforms/UserTransformer.ts b/src/backend/common/transforms/UserTransformer.ts index 1b177554..9fe161c0 100644 --- a/src/backend/common/transforms/UserTransformer.ts +++ b/src/backend/common/transforms/UserTransformer.ts @@ -96,8 +96,5 @@ export default class UserTransformer extends AtomicPartsTransformer { return; } - protected getIdentifier(): string { - return 'User Transformer'; - } } \ No newline at end of file diff --git a/src/backend/common/vendor/musicbrainz/MusicbrainzApiClient.ts b/src/backend/common/vendor/musicbrainz/MusicbrainzApiClient.ts index 54f5ae4c..54621637 100644 --- a/src/backend/common/vendor/musicbrainz/MusicbrainzApiClient.ts +++ b/src/backend/common/vendor/musicbrainz/MusicbrainzApiClient.ts @@ -87,7 +87,7 @@ export class MusicbrainzApiClient extends AbstractApiClient { } - this.logger.debug(`Starting search for ${buildTrackString(play)}`); + this.logger.debug(`Starting search`); const res = await this.callApi((mb) => { const query: Record = { recording: play.data.track diff --git a/src/backend/tests/ytm/ytm.test.ts b/src/backend/tests/ytm/ytm.test.ts index 79946207..f11ac815 100644 --- a/src/backend/tests/ytm/ytm.test.ts +++ b/src/backend/tests/ytm/ytm.test.ts @@ -211,7 +211,7 @@ describe('Handles interim tracks', function () { const interimPlays = [generatePlay({duration: 40}, { comment: 'Today' }), generatePlay({duration: 200}, { comment: 'Today' })] const prependedPlays = [firstPlay, ...interimPlays, ...plays]; const prependResult = source.parseRecentAgainstResponse(prependedPlays); - expect(prependResult.plays).length(2); + expect(prependResult.plays).length(3); expect(prependResult.plays[prependResult.plays.length - 1].data.track).eq(firstPlay.data.track) }); }); \ No newline at end of file -- 2.51.2