From a13b4f6eac488f880ab0c87de4ccca75963266e3 Mon Sep 17 00:00:00 2001 From: Johan Nyman Date: Fri, 22 Sep 2023 11:05:33 +0200 Subject: [PATCH 01/17] fix: restart deep-scanning if ffpmeg doesn't output progress. There was an issue where ffmpeg didn't output any progress reports for certain files. My findings show that it helps if we don't do the scene detection. --- .../src/worker/lib/expectationHandler.ts | 4 +- shared/packages/worker/src/worker/worker.ts | 6 ++- .../worker/workers/linuxWorker/linuxWorker.ts | 2 +- .../expectationWindowsHandler.ts | 4 +- .../expectationHandlers/lib/scan.ts | 4 ++ .../expectationHandlers/packageDeepScan.ts | 38 ++++++++++++++++++- .../workers/windowsWorker/windowsWorker.ts | 4 +- shared/packages/worker/src/workerAgent.ts | 2 +- 8 files changed, 56 insertions(+), 8 deletions(-) diff --git a/shared/packages/worker/src/worker/lib/expectationHandler.ts b/shared/packages/worker/src/worker/lib/expectationHandler.ts index 539c6861..c9c9ccc2 100644 --- a/shared/packages/worker/src/worker/lib/expectationHandler.ts +++ b/shared/packages/worker/src/worker/lib/expectationHandler.ts @@ -57,7 +57,9 @@ export interface ExpectationHandler { workOnExpectation: ( exp: Expectation.Any, genericWorker: GenericWorker, - specificWorker: any + specificWorker: any, + /** An FYI, the work will be considered timed out if there are no progression reports within this interval*/ + progressTimeout: number ) => Promise /** * "Make an expectation un-fullfilled" diff --git a/shared/packages/worker/src/worker/worker.ts b/shared/packages/worker/src/worker/worker.ts index d8b14316..8482910a 100644 --- a/shared/packages/worker/src/worker/worker.ts +++ b/shared/packages/worker/src/worker/worker.ts @@ -85,7 +85,11 @@ export abstract class GenericWorker { * Start working on fullfilling an expectation. * @returns a WorkInProgress, upon beginning of the work. WorkInProgress then handles signalling of the work progress. */ - abstract workOnExpectation(exp: Expectation.Any): Promise + abstract workOnExpectation( + exp: Expectation.Any, + /** An FYI, the work will be considered timed out if there are no progression reports within this interval*/ + progressTimeout: number + ): Promise /** * "Make an expectation un-fullfilled" * This is called when an expectation has been removed. diff --git a/shared/packages/worker/src/worker/workers/linuxWorker/linuxWorker.ts b/shared/packages/worker/src/worker/workers/linuxWorker/linuxWorker.ts index 691028dc..7823aef0 100644 --- a/shared/packages/worker/src/worker/workers/linuxWorker/linuxWorker.ts +++ b/shared/packages/worker/src/worker/workers/linuxWorker/linuxWorker.ts @@ -52,7 +52,7 @@ export class LinuxWorker extends GenericWorker { ): Promise { throw new Error(`Not implemented yet`) } - async workOnExpectation(_exp: Expectation.Any): Promise { + async workOnExpectation(_exp: Expectation.Any, _progressTimeout: number): Promise { throw new Error(`Not implemented yet`) } async removeExpectation(_exp: Expectation.Any): Promise { diff --git a/shared/packages/worker/src/worker/workers/windowsWorker/expectationHandlers/expectationWindowsHandler.ts b/shared/packages/worker/src/worker/workers/windowsWorker/expectationHandlers/expectationWindowsHandler.ts index 67b47084..802bc32e 100644 --- a/shared/packages/worker/src/worker/workers/windowsWorker/expectationHandlers/expectationWindowsHandler.ts +++ b/shared/packages/worker/src/worker/workers/windowsWorker/expectationHandlers/expectationWindowsHandler.ts @@ -36,7 +36,9 @@ export interface ExpectationWindowsHandler extends ExpectationHandler { workOnExpectation: ( exp: Expectation.Any, genericWorker: GenericWorker, - windowsWorker: WindowsWorker + windowsWorker: WindowsWorker, + /** An FYI, the work will be considered timed out if there are no progression reports within this interval*/ + progressTimeout: number ) => Promise removeExpectation: ( exp: Expectation.Any, diff --git a/shared/packages/worker/src/worker/workers/windowsWorker/expectationHandlers/lib/scan.ts b/shared/packages/worker/src/worker/workers/windowsWorker/expectationHandlers/lib/scan.ts index 93a2f033..ec97c04d 100644 --- a/shared/packages/worker/src/worker/workers/windowsWorker/expectationHandlers/lib/scan.ts +++ b/shared/packages/worker/src/worker/workers/windowsWorker/expectationHandlers/lib/scan.ts @@ -239,6 +239,7 @@ export function scanMoreInfo( freezes: ScanAnomaly[] blacks: ScanAnomaly[] }>(async (resolve, reject, onCancel) => { + let cancelled = false let filterString = '' if (targetVersion.blackDetection) { if (targetVersion.blackDuration && targetVersion.blackDuration?.endsWith('s')) { @@ -287,6 +288,7 @@ export function scanMoreInfo( } } onCancel(() => { + cancelled = true killFFMpeg() reject('Cancelled') }) @@ -309,6 +311,7 @@ export function scanMoreInfo( let previousStringData = '' let fileDuration: number | undefined = undefined ffMpegProcess.stderr.on('data', (data: any) => { + if (cancelled) return const stringData = data.toString() if (typeof stringData !== 'string') { @@ -413,6 +416,7 @@ export function scanMoreInfo( } const onClose = (code: number | null) => { + if (cancelled) return if (ffMpegProcess) { ffMpegProcess = undefined if (code === 0) { diff --git a/shared/packages/worker/src/worker/workers/windowsWorker/expectationHandlers/packageDeepScan.ts b/shared/packages/worker/src/worker/workers/windowsWorker/expectationHandlers/packageDeepScan.ts index b857c061..582fc5a8 100644 --- a/shared/packages/worker/src/worker/workers/windowsWorker/expectationHandlers/packageDeepScan.ts +++ b/shared/packages/worker/src/worker/workers/windowsWorker/expectationHandlers/packageDeepScan.ts @@ -123,7 +123,12 @@ export const PackageDeepScan: ExpectationWindowsHandler = { return { fulfilled: true } } }, - workOnExpectation: async (exp: Expectation.Any, worker: GenericWorker): Promise => { + workOnExpectation: async ( + exp: Expectation.Any, + worker: GenericWorker, + _: WindowsWorker, + progressTimeout: number + ): Promise => { if (!isPackageDeepScan(exp)) throw new Error(`Wrong exp.type: "${exp.type}"`) // Scan the source media file and upload the results to Core const startTime = Date.now() @@ -184,16 +189,47 @@ export const PackageDeepScan: ExpectationWindowsHandler = { let resultFreezes: ScanAnomaly[] = [] let resultScenes: number[] = [] if (hasVideoStream) { + let hasGottenProgress = false + let isDone = false currentProcess = scanMoreInfo( sourceHandle, ffProbeScan, exp.endRequirement.version, (progress) => { + hasGottenProgress = true workInProgress._reportProgress(sourceVersionHash, 0.21 + 0.77 * progress) }, worker.logger.category('scanMoreInfo') ) + + setTimeout(() => { + if (!isDone && currentProcess && !hasGottenProgress) { + // If we haven't gotten any progress yet, we probably won't get any. + + // 2023-09-20: There seems to be some bug in the FFMpeg scan where it won't output any progress + // if the scene detection is on. + // Let's abort and try again without scene detection: + + currentProcess.cancel() + + currentProcess = scanMoreInfo( + sourceHandle, + ffProbeScan, + { + ...exp.endRequirement.version, + scenes: false, // no scene detection + }, + (progress) => { + hasGottenProgress = true + workInProgress._reportProgress(sourceVersionHash, 0.21 + 0.77 * progress) + }, + worker.logger.category('scanMoreInfo') + ) + } + }, progressTimeout * 0.5) + const result = await currentProcess + isDone = true resultBlacks = result.blacks resultFreezes = result.freezes resultScenes = result.scenes diff --git a/shared/packages/worker/src/worker/workers/windowsWorker/windowsWorker.ts b/shared/packages/worker/src/worker/workers/windowsWorker/windowsWorker.ts index 61e510f1..081e6cb1 100644 --- a/shared/packages/worker/src/worker/workers/windowsWorker/windowsWorker.ts +++ b/shared/packages/worker/src/worker/workers/windowsWorker/windowsWorker.ts @@ -91,8 +91,8 @@ export class WindowsWorker extends GenericWorker { ): Promise { return this.getExpectationHandler(exp).isExpectationFullfilled(exp, wasFullfilled, this, this) } - async workOnExpectation(exp: Expectation.Any): Promise { - return this.getExpectationHandler(exp).workOnExpectation(exp, this, this) + async workOnExpectation(exp: Expectation.Any, progressTimeout: number): Promise { + return this.getExpectationHandler(exp).workOnExpectation(exp, this, this, progressTimeout) } async removeExpectation(exp: Expectation.Any): Promise { return this.getExpectationHandler(exp).removeExpectation(exp, this, this) diff --git a/shared/packages/worker/src/workerAgent.ts b/shared/packages/worker/src/workerAgent.ts index afd58dc6..85ad3fe8 100644 --- a/shared/packages/worker/src/workerAgent.ts +++ b/shared/packages/worker/src/workerAgent.ts @@ -492,7 +492,7 @@ export class WorkerAgent { ) try { - const workInProgress = await this._worker.workOnExpectation(exp) + const workInProgress = await this._worker.workOnExpectation(exp, timeout) currentJob.workInProgress = workInProgress From c7a8b063362344f0c2acc63b44be80269bd571fc Mon Sep 17 00:00:00 2001 From: Johan Nyman Date: Wed, 27 Sep 2023 14:57:02 +0200 Subject: [PATCH 02/17] fix: rewrite the retrying of ffmpeg --- .../expectationHandlers/packageDeepScan.ts | 108 ++++++++++++------ 1 file changed, 71 insertions(+), 37 deletions(-) diff --git a/shared/packages/worker/src/worker/workers/windowsWorker/expectationHandlers/packageDeepScan.ts b/shared/packages/worker/src/worker/workers/windowsWorker/expectationHandlers/packageDeepScan.ts index 582fc5a8..21c103b6 100644 --- a/shared/packages/worker/src/worker/workers/windowsWorker/expectationHandlers/packageDeepScan.ts +++ b/shared/packages/worker/src/worker/workers/windowsWorker/expectationHandlers/packageDeepScan.ts @@ -190,46 +190,80 @@ export const PackageDeepScan: ExpectationWindowsHandler = { let resultScenes: number[] = [] if (hasVideoStream) { let hasGottenProgress = false - let isDone = false - currentProcess = scanMoreInfo( - sourceHandle, - ffProbeScan, - exp.endRequirement.version, - (progress) => { - hasGottenProgress = true - workInProgress._reportProgress(sourceVersionHash, 0.21 + 0.77 * progress) - }, - worker.logger.category('scanMoreInfo') - ) - setTimeout(() => { - if (!isDone && currentProcess && !hasGottenProgress) { - // If we haven't gotten any progress yet, we probably won't get any. - - // 2023-09-20: There seems to be some bug in the FFMpeg scan where it won't output any progress - // if the scene detection is on. - // Let's abort and try again without scene detection: - - currentProcess.cancel() - - currentProcess = scanMoreInfo( - sourceHandle, - ffProbeScan, - { - ...exp.endRequirement.version, - scenes: false, // no scene detection - }, - (progress) => { - hasGottenProgress = true - workInProgress._reportProgress(sourceVersionHash, 0.21 + 0.77 * progress) - }, - worker.logger.category('scanMoreInfo') - ) - } - }, progressTimeout * 0.5) + currentProcess = new CancelablePromise<{ + scenes: number[] + freezes: ScanAnomaly[] + blacks: ScanAnomaly[] + }>(async (resolve, reject, onCancel) => { + let isDone = false + let ignoreNextCancelError = false + + const scanMoreInfoProcess = scanMoreInfo( + sourceHandle, + ffProbeScan, + exp.endRequirement.version, + (progress) => { + hasGottenProgress = true + workInProgress._reportProgress(sourceVersionHash, 0.21 + 0.77 * progress) + }, + worker.logger.category('scanMoreInfo') + ) + onCancel(() => { + scanMoreInfoProcess.cancel() + }) + + scanMoreInfoProcess.then( + (result) => { + isDone = true + resolve(result) + }, + (error) => { + if (`${error}`.match(/cancelled/i) && ignoreNextCancelError) { + // ignore this + ignoreNextCancelError = false + } else { + reject(error) + } + } + ) + + // Guard against an edge case where we don't get any progress reports: + setTimeout(() => { + if (!isDone && currentProcess && !hasGottenProgress) { + // If we haven't gotten any progress yet, we probably won't get any. + + // 2023-09-20: There seems to be some bug in the FFMpeg scan where it won't output any progress + // if the scene detection is on. + // Let's abort and try again without scene detection: + + ignoreNextCancelError = true + currentProcess.cancel() + + const scanMoreInfoProcessSecondTry = scanMoreInfo( + sourceHandle, + ffProbeScan, + { + ...exp.endRequirement.version, + scenes: false, // no scene detection + }, + (progress) => { + hasGottenProgress = true + workInProgress._reportProgress(sourceVersionHash, 0.21 + 0.77 * progress) + }, + worker.logger.category('scanMoreInfo') + ) + + scanMoreInfoProcessSecondTry.then( + (result) => resolve(result), + (error) => reject(error) + ) + } + }, progressTimeout * 0.5) + }) const result = await currentProcess - isDone = true + resultBlacks = result.blacks resultFreezes = result.freezes resultScenes = result.scenes From 521342fe53eda6d625a4734c8487945fafa300ef Mon Sep 17 00:00:00 2001 From: Johan Nyman Date: Wed, 27 Sep 2023 15:09:21 +0200 Subject: [PATCH 03/17] chore: make test more roboust --- tests/internal-tests/src/__tests__/issues.spec.ts | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/tests/internal-tests/src/__tests__/issues.spec.ts b/tests/internal-tests/src/__tests__/issues.spec.ts index b12834cc..6837ebe3 100644 --- a/tests/internal-tests/src/__tests__/issues.spec.ts +++ b/tests/internal-tests/src/__tests__/issues.spec.ts @@ -131,7 +131,9 @@ describe('Handle unhappy paths', () => { statusInfo: { // status: expect.stringMatching(/fulfilled/), statusReason: { - tech: expect.stringMatching(/timeout.*checkPackageContainerWriteAccess.*Accessor.*/i), + tech: expect.stringMatching( + /timeout.*(checkPackageContainerWriteAccess|checkPackageReadAccess).*Accessor.*/i + ), }, }, }) From 06115f376a6ff9fb6a30c3a7842818c991a99950 Mon Sep 17 00:00:00 2001 From: Johan Nyman Date: Wed, 27 Sep 2023 16:04:05 +0200 Subject: [PATCH 04/17] chore: improve unit test error logging in waitUntil() --- tests/internal-tests/src/__tests__/lib/lib.ts | 18 +++++++++++++++++- 1 file changed, 17 insertions(+), 1 deletion(-) diff --git a/tests/internal-tests/src/__tests__/lib/lib.ts b/tests/internal-tests/src/__tests__/lib/lib.ts index 8baf41fe..6156e5bf 100644 --- a/tests/internal-tests/src/__tests__/lib/lib.ts +++ b/tests/internal-tests/src/__tests__/lib/lib.ts @@ -7,6 +7,8 @@ export function waitTime(ms: number): Promise { * Useful in unit-tests as a way to wait until a predicate is fulfilled. */ export async function waitUntil(expectFcn: () => void, maxWaitTime: number): Promise { + const previousErrors: string[] = [] + const startTime = Date.now() while (true) { await waitTime(100) @@ -14,8 +16,22 @@ export async function waitUntil(expectFcn: () => void, maxWaitTime: number): Pro expectFcn() return } catch (err) { + const errorStr = `${err}` + if (previousErrors.length) { + const previousError = previousErrors[previousErrors.length - 1] + if (errorStr !== previousError) { + previousErrors.push(errorStr) + } + } else { + previousErrors.push(errorStr) + } + let waitedTime = Date.now() - startTime - if (waitedTime > maxWaitTime) throw err + if (waitedTime > maxWaitTime) { + console.log(`Previous errors: \n${previousErrors.join('\n')}`) + + throw err + } // else ignore error and try again later } } From c64403191df1f957e9f95a7476f7e096a6ed1da3 Mon Sep 17 00:00:00 2001 From: Johan Nyman Date: Wed, 27 Sep 2023 16:13:17 +0200 Subject: [PATCH 05/17] wip --- tests/internal-tests/src/__mocks__/fs.ts | 1 + 1 file changed, 1 insertion(+) diff --git a/tests/internal-tests/src/__mocks__/fs.ts b/tests/internal-tests/src/__mocks__/fs.ts index 36bb4a3f..4fa4fe5f 100644 --- a/tests/internal-tests/src/__mocks__/fs.ts +++ b/tests/internal-tests/src/__mocks__/fs.ts @@ -324,6 +324,7 @@ export function access(path: string, mode: number | undefined, callback: (error: const mockFile = getMock(path) // if (DEBUG_LOG) console.log('fs.access', path, mode) fsMockEmitter.emit('access', path, mode) + if (FS_ACCESS_DELAY > 0) console.log('FS_ACCESS_DELAY', FS_ACCESS_DELAY) setTimeout(() => { try { if (mode === constants.R_OK && !mockFile.accessRead) { From 75add61479caabc629255dcb647db55eb955c038 Mon Sep 17 00:00:00 2001 From: Johan Nyman Date: Fri, 29 Sep 2023 09:00:38 +0200 Subject: [PATCH 06/17] chore: doc --- shared/packages/worker/src/worker/lib/expectationHandler.ts | 6 ++++-- 1 file changed, 4 insertions(+), 2 deletions(-) diff --git a/shared/packages/worker/src/worker/lib/expectationHandler.ts b/shared/packages/worker/src/worker/lib/expectationHandler.ts index c9c9ccc2..1b330e02 100644 --- a/shared/packages/worker/src/worker/lib/expectationHandler.ts +++ b/shared/packages/worker/src/worker/lib/expectationHandler.ts @@ -51,8 +51,10 @@ export interface ExpectationHandler { specificWorker: any ) => Promise /** - * Start working on fullfilling an expectation. - * @returns a WorkInProgress, upon beginning of the work. WorkInProgress then handles signalling of the work progress. + * Start working on fulfilling an expectation. + * The function returns a WorkInProgress, which then handles the actual work asynchronously. + * The returned WorkInProgress is expected to emit 'progress'-events at some interval, to indicate that the work is progressing + * (otherwise the work will be considered timed out and will be cancelled). */ workOnExpectation: ( exp: Expectation.Any, From 40fb8020aaf4a8f08696dfa324769cac773fbaa6 Mon Sep 17 00:00:00 2001 From: Johan Nyman Date: Fri, 6 Oct 2023 07:15:48 +0200 Subject: [PATCH 07/17] chore: improve HelpfulEventEmitter so it can check for more mandatory events, other than "error" --- .../packages/api/src/HelpfulEventEmitter.ts | 38 ++++++++++++++----- 1 file changed, 29 insertions(+), 9 deletions(-) diff --git a/shared/packages/api/src/HelpfulEventEmitter.ts b/shared/packages/api/src/HelpfulEventEmitter.ts index 50e2a078..56060659 100644 --- a/shared/packages/api/src/HelpfulEventEmitter.ts +++ b/shared/packages/api/src/HelpfulEventEmitter.ts @@ -3,24 +3,44 @@ import EventEmitter from 'events' /** An EventEmitter which does a check that you've remembered to listen to the 'error' event */ export class HelpfulEventEmitter extends EventEmitter { + private _listenersToCheck: string[] = ['error'] + constructor() { super() // Ensure that the error event is listened for: const orgError = new Error('No error event listener registered') setTimeout(() => { - if (!this.listenerCount('error')) { - // If no error event listener is registered, log a warning to let the developer - // know that they should do so: - console.error('WARNING: No error event listener registered') - console.error(`Stack: ${orgError.stack}`) + for (const event of this._listenersToCheck) { + if (!this.listenerCount(event)) { + // If no event listener is registered, log a warning to let the developer + // know that they should do so: + console.error(`WARNING: No "${event}" event listener registered`) + console.error(`Stack: ${orgError.stack}`) - // If we're running in Jest, it's better to make it a little more obvious that something is wrong: - if (process.env.JEST_WORKER_ID !== undefined) { - // Since no error listener is registered, this'll cause the process to exit and tests to fail: - this.emit('error', orgError) + // If we're running in Jest, it's better to make it a little more obvious that something is wrong: + if (process.env.JEST_WORKER_ID !== undefined) { + // Since no error listener is registered, this'll cause the process to exit and tests to fail: + this.emit('error', orgError) + } } } + + // If we're running in Jest, it's better to make it a little more obvious that something is wrong: + if (process.env.JEST_WORKER_ID !== undefined && !this.listenerCount('error')) { + // Since no error listener is registered, this'll cause the process to exit and tests to fail: + this.emit('error', orgError) + } }, 1) } + + /** + * To be called in constructor. + * Add an event that the HelpfulEventEmitter should check that it is being listened to + */ + protected addHelpfulEventCheck(event: string): void { + if (this._listenersToCheck.includes(event)) throw new Error(`Event "${event}" already added`) + + this._listenersToCheck.push(event) + } } From 60922e403c60739c5360b61d932b526b98c70ef3 Mon Sep 17 00:00:00 2001 From: Johan Nyman Date: Fri, 6 Oct 2023 07:20:40 +0200 Subject: [PATCH 08/17] fix: replace chokidar file monitor with ParcelWatcher There was an issue in production when watching many files (over 9000), where chokidar choked on the initial watch and subsequently caused the whole worker to be sluggish --- .../packages/generic/package.json | 2 +- .../packages/generic/src/connector.ts | 28 +-- .../nrk/packageContainerExpectations.ts | 5 +- .../packages/api/src/packageContainerApi.ts | 8 +- shared/packages/worker/package.json | 2 +- .../src/worker/accessorHandlers/fileShare.ts | 2 +- .../accessorHandlers/lib/FileHandler.ts | 131 +++++------- .../accessorHandlers/lib/FileWatcher.ts | 200 ++++++++++++++++++ .../worker/accessorHandlers/localFolder.ts | 2 +- shared/packages/worker/src/workerAgent.ts | 1 + yarn.lock | 136 ++++++++---- 11 files changed, 370 insertions(+), 147 deletions(-) create mode 100644 shared/packages/worker/src/worker/accessorHandlers/lib/FileWatcher.ts diff --git a/apps/package-manager/packages/generic/package.json b/apps/package-manager/packages/generic/package.json index 83b8ff38..b1accff0 100644 --- a/apps/package-manager/packages/generic/package.json +++ b/apps/package-manager/packages/generic/package.json @@ -16,7 +16,7 @@ "@sofie-package-manager/api": "1.42.1", "@sofie-package-manager/expectation-manager": "1.42.1", "@sofie-package-manager/worker": "1.42.1", - "chokidar": "^3.5.1", + "@parcel/watcher": "^2.3.0", "data-store": "^4.0.3", "deep-extend": "^0.6.0", "fast-clone": "^1.5.13", diff --git a/apps/package-manager/packages/generic/src/connector.ts b/apps/package-manager/packages/generic/src/connector.ts index b9f36372..b5ec7ee7 100644 --- a/apps/package-manager/packages/generic/src/connector.ts +++ b/apps/package-manager/packages/generic/src/connector.ts @@ -11,7 +11,6 @@ import { import { ExpectationManager, ExpectationManagerServerOptions } from '@sofie-package-manager/expectation-manager' import { CoreHandler, CoreConfig } from './coreHandler' import { PackageContainers, PackageManagerHandler } from './packageManager' -import chokidar from 'chokidar' import fs from 'fs' import { promisify } from 'util' import path from 'path' @@ -213,24 +212,6 @@ export class Connector { 'utf-8' ) } - - const watcher = chokidar.watch(fileName, { persistent: true }) - - this.logger.info(`Watching file "${fileName}"`) - - watcher - .on('add', () => { - triggerReloadInput() - }) - .on('change', () => { - triggerReloadInput() - }) - .on('unlink', () => { - triggerReloadInput() - }) - .on('error', (error) => { - this.logger.error(`Error emitter in Filewatcher: ${stringifyError(error)}`) - }) const triggerReloadInput = () => { setTimeout(() => { reloadInput().catch((error) => { @@ -238,6 +219,15 @@ export class Connector { }) }, 100) } + + this.logger.info(`Watching file "${fileName}"`) + fs.watchFile(fileName, { persistent: true }, (currStats, prevStats) => { + if (currStats.mtimeMs !== prevStats.mtimeMs) { + triggerReloadInput() + } + }) + triggerReloadInput() + const reloadInput = async () => { this.logger.info(`Change detected in ${fileName}`) // Check that the file exists: diff --git a/apps/package-manager/packages/generic/src/generateExpectations/nrk/packageContainerExpectations.ts b/apps/package-manager/packages/generic/src/generateExpectations/nrk/packageContainerExpectations.ts index af7c2ab1..1b328695 100644 --- a/apps/package-manager/packages/generic/src/generateExpectations/nrk/packageContainerExpectations.ts +++ b/apps/package-manager/packages/generic/src/generateExpectations/nrk/packageContainerExpectations.ts @@ -24,7 +24,7 @@ export function getPackageContainerExpectations( packages: { label: 'Monitor Packages on source', targetLayers: ['target0'], - ignore: '.bat', + ignore: ['.bat'], // ignore: '', }, }, @@ -43,9 +43,6 @@ export function getPackageContainerExpectations( packages: { label: 'Monitor for Smartbull', targetLayers: ['source-smartbull'], // not used, since the layers of the original smartbull-package are used - usePolling: 2000, - awaitWriteFinishStabilityThreshold: 2000, - warningLimit: 3000, // We seem to get performance issues at around 9000 (when polling network drives), so 3000 should give us an early warning }, }, } diff --git a/shared/packages/api/src/packageContainerApi.ts b/shared/packages/api/src/packageContainerApi.ts index 559f3ae4..6bd73019 100644 --- a/shared/packages/api/src/packageContainerApi.ts +++ b/shared/packages/api/src/packageContainerApi.ts @@ -25,12 +25,12 @@ export interface PackageContainerExpectation extends PackageContainer { /** Monitor the packages of a PackageContainer */ packages?: { label: string - /** If set, ignore any files matching this. (Regular expression). */ - ignore?: string + /** If set, ignore any files matching any of the patterns (Glob pattern). */ + ignore?: string[] /** If set, the monitoring will be using polling, at the given interval [ms] */ - usePolling?: number | null - /** If set, will set the awaitWriteFinish.StabilityThreshold of chokidar */ + // usePolling?: number | null + /** If set, will wait for the file being unchanged for the specified duration before considering it [ms] */ awaitWriteFinishStabilityThreshold?: number | null /** If set, the monitor will warn if the monitored number of packages is greater than this */ warningLimit?: number diff --git a/shared/packages/worker/package.json b/shared/packages/worker/package.json index d1804c28..84a2839f 100644 --- a/shared/packages/worker/package.json +++ b/shared/packages/worker/package.json @@ -18,10 +18,10 @@ "@types/tmp": "~0.2.2" }, "dependencies": { + "@parcel/watcher": "^2.3.0", "@sofie-package-manager/api": "1.42.1", "abort-controller": "^3.0.0", "atem-connection": "^3.2.0", - "chokidar": "^3.5.1", "deep-diff": "^1.0.2", "form-data": "^4.0.0", "mkdirp": "^1.0.4", diff --git a/shared/packages/worker/src/worker/accessorHandlers/fileShare.ts b/shared/packages/worker/src/worker/accessorHandlers/fileShare.ts index 3ee26e24..bb6fa600 100644 --- a/shared/packages/worker/src/worker/accessorHandlers/fileShare.ts +++ b/shared/packages/worker/src/worker/accessorHandlers/fileShare.ts @@ -357,7 +357,7 @@ export class FileShareAccessorHandle extends GenericFileAccessorHandle for (const monitorId of monitorIds) { if (monitorId === 'packages') { // setup file monitor: - resultingMonitors[monitorId] = this.setupPackagesMonitor(packageContainerExp) + resultingMonitors[monitorId] = await this.setupPackagesMonitor(packageContainerExp) } else { // Assert that cronjob is of type "never", to ensure that all types of monitors are handled: assertNever(monitorId) diff --git a/shared/packages/worker/src/worker/accessorHandlers/lib/FileHandler.ts b/shared/packages/worker/src/worker/accessorHandlers/lib/FileHandler.ts index 854b7fec..2c699bc7 100644 --- a/shared/packages/worker/src/worker/accessorHandlers/lib/FileHandler.ts +++ b/shared/packages/worker/src/worker/accessorHandlers/lib/FileHandler.ts @@ -14,12 +14,13 @@ import { Reason, stringifyError, } from '@sofie-package-manager/api' -import chokidar from 'chokidar' + import { GenericWorker } from '../../worker' import { GenericAccessorHandle } from '../genericHandle' import { MonitorInProgress } from '../../lib/monitorInProgress' import { removeBasePath } from './pathJoin' +import { FileEvent, FileWatcher, IFileWatcher } from './FileWatcher' export const LocalFolderAccessorHandleType = 'localFolder' export const FileShareAccessorHandleType = 'fileShare' @@ -150,7 +151,7 @@ export abstract class GenericFileAccessorHandle extends GenericAccesso return this.getFullPath(filePath) + '_metadata.json' } - setupPackagesMonitor(packageContainerExp: PackageContainerExpectation): MonitorInProgress { + async setupPackagesMonitor(packageContainerExp: PackageContainerExpectation): Promise { const options = packageContainerExp.monitors.packages if (!options) throw new Error('Options not set (this should never happen)') @@ -160,32 +161,23 @@ export abstract class GenericFileAccessorHandle extends GenericAccesso }, async () => { // Called on stop - await watcher.close() + await watcher.stop() } ) + // Set up a temporary error listener, to catch any errors during setup: + monitorInProgress.on('error', (internalError: any) => { + this.worker.logger.error(`setupPackagesMonitor.monitorInProgress: ${JSON.stringify(internalError)}`) + monitorInProgress._setStatus(StatusCategory.SETUP, StatusCode.BAD, { + user: 'Internal error', + tech: `MonitorInProgress error: ${stringifyError(internalError)}`, + }) + }) - monitorInProgress._setStatus('setup', StatusCode.UNKNOWN, { + monitorInProgress._setStatus(StatusCategory.SETUP, StatusCode.UNKNOWN, { user: 'Setting up file watcher...', tech: `Setting up file watcher...`, }) - const chokidarOptions: chokidar.WatchOptions = { - ignored: options.ignore ? new RegExp(options.ignore) : undefined, - persistent: true, - } - if (options.usePolling) { - chokidarOptions.usePolling = true - chokidarOptions.interval = options.usePolling - chokidarOptions.binaryInterval = options.usePolling - } - if (options.awaitWriteFinishStabilityThreshold) { - chokidarOptions.awaitWriteFinish = { - stabilityThreshold: options.awaitWriteFinishStabilityThreshold, - pollInterval: options.awaitWriteFinishStabilityThreshold, - } - } - const watcher = chokidar.watch(this.folderPath, chokidarOptions) - const monitorId = `${this.worker.agentAPI.config.workerId}_${this.worker.uniqueId}_${Date.now()}` const seenFiles = new Map() @@ -220,7 +212,7 @@ export abstract class GenericFileAccessorHandle extends GenericAccesso version = this.convertStatToVersion(stat) seenFiles.set(filePath, version) - monitorInProgress._unsetStatus(fullPath) + monitorInProgress._unsetStatus(StatusCategory.FILE + fullPath) } catch (err) { version = null this.worker.logger.error( @@ -229,7 +221,7 @@ export abstract class GenericFileAccessorHandle extends GenericAccesso )}` ) - monitorInProgress._setStatus(fullPath, StatusCode.BAD, { + monitorInProgress._setStatus(StatusCategory.FILE + fullPath, StatusCode.BAD, { user: 'Error when accessing watched file', tech: `Error: ${stringifyError(err)}`, }) @@ -287,12 +279,12 @@ export abstract class GenericFileAccessorHandle extends GenericAccesso }) if (options.warningLimit && seenFiles.size > options.warningLimit) { - monitorInProgress._setStatus('warningLimit', StatusCode.WARNING_MAJOR, { + monitorInProgress._setStatus(StatusCategory.WARNING_LIMIT, StatusCode.WARNING_MAJOR, { user: 'Warning: Too many files for monitor', tech: `There are ${seenFiles.size} files in the folder, which might cause performance issues. Reduce the number of files to below ${options.warningLimit} to get rid of this warning.`, }) } else { - monitorInProgress._unsetStatus('warningLimit') + monitorInProgress._unsetStatus(StatusCategory.WARNING_LIMIT) } // Finally @@ -306,63 +298,45 @@ export abstract class GenericFileAccessorHandle extends GenericAccesso }, 1000) // Wait just a little bit, to avoid doing multiple updates } - /** Get the local filepath from the fullPath */ - const getFilePath = (fullPath: string): string | undefined => { - return path.relative(this.folderPath, fullPath) - } - watcher - .on('add', (fullPath) => { - const localPath = getFilePath(fullPath) - if (localPath) { - seenFiles.set(localPath, null) - triggerSendUpdate() - } + const watcher: IFileWatcher = new FileWatcher(this.folderPath, { + ignore: options.ignore, + awaitWriteFinishStabilityThreshold: options.awaitWriteFinishStabilityThreshold, + }) + watcher.on('error', (errString: string) => { + this.worker.logger.error(`GenericFileAccessorHandle.setupPackagesMonitor: watcher.error: ${errString}}`) + monitorInProgress._setStatus(StatusCategory.WATCHER, StatusCode.BAD, { + user: 'There was an unexpected error in the file watcher', + tech: `FileWatcher error: ${stringifyError(errString)}`, }) - .on('change', (fullPath) => { - const localPath = getFilePath(fullPath) + }) + watcher.on('fileEvent', (fileEvent: FileEvent) => { + const localPath = watcher.getLocalFilePath(fileEvent.path) + + if (fileEvent.type === 'create' || fileEvent.type === 'update') { if (localPath) { seenFiles.set(localPath, null) // This will cause triggerSendUpdate() to update the version triggerSendUpdate() } - }) - .on('unlink', (fullPath) => { - // We don't trust chokidar, so we'll check it ourselves first.. - // (We've seen an issue where removing a single file from a folder causes chokidar to emit unlink for ALL the files) - fsAccess(fullPath, fs.constants.R_OK) - .then(() => { - // The file seems to exist, even though chokidar says it doesn't. - // Ignore the event, then - }) - .catch(() => { - // The file truly doesn't exist + } else if (fileEvent.type === 'delete') { + // Reset any BAD status related to this file: + monitorInProgress._unsetStatus(StatusCategory.FILE + fileEvent.path) - monitorInProgress._unsetStatus(fullPath) + if (localPath) { + seenFiles.delete(localPath) + triggerSendUpdate() + } + } else { + assertNever(fileEvent.type) + } + }) - const localPath = getFilePath(fullPath) - if (localPath) { - seenFiles.delete(localPath) - triggerSendUpdate() - } - }) - }) - .on('error', (err) => { - this.worker.logger.error( - `GenericFileAccessorHandle.setupPackagesMonitor: watcher.error: Unexpected error event: ${stringifyError( - err - )}` - ) - monitorInProgress._setStatus('watcher', StatusCode.BAD, { - user: 'Error in file watcher', - tech: `chokidar error: ${stringifyError(err)}`, - }) - }) - .on('ready', () => { - monitorInProgress._setStatus('setup', StatusCode.GOOD, { - user: 'File watcher is set up', - tech: `File watcher is set up`, - }) - triggerSendUpdate() - }) + // Watch for events: + await watcher.init() + triggerSendUpdate() + monitorInProgress._setStatus(StatusCategory.SETUP, StatusCode.GOOD, { + user: 'File watcher is set up', + tech: `File watcher is set up`, + }) return monitorInProgress } @@ -467,3 +441,10 @@ interface DelayPackageRemovalEntry { /** Unix timestamp for when it's clear to remove the file */ removeTime: number } + +enum StatusCategory { + SETUP = 'setup', + WARNING_LIMIT = 'warningLimit', + WATCHER = 'watcher', + FILE = 'file_', +} diff --git a/shared/packages/worker/src/worker/accessorHandlers/lib/FileWatcher.ts b/shared/packages/worker/src/worker/accessorHandlers/lib/FileWatcher.ts new file mode 100644 index 00000000..56451749 --- /dev/null +++ b/shared/packages/worker/src/worker/accessorHandlers/lib/FileWatcher.ts @@ -0,0 +1,200 @@ +import fs from 'fs' +import path from 'path' +import ParcelWatcher from '@parcel/watcher' +import { HelpfulEventEmitter, assertNever, stringifyError } from '@sofie-package-manager/api' + +export interface FileWatcherEvents { + /** Emitted whenever there is an error */ + error: (error: string) => void + + /** Emitted whenever a file is created, updated or deleted */ + fileEvent: (event: FileEvent) => void +} +export interface IFileWatcher { + on(event: U, listener: FileWatcherEvents[U]): this + emit(event: U, ...args: Parameters): boolean + + /** Start the file watcher */ + init: () => Promise + /** Stop the file watcher */ + stop: () => Promise + /** Get the local filepath from the fullPath */ + getLocalFilePath: (fullPath: string) => string | undefined +} + +/** + * The FileWatcher watches a folder for changes to files. + * It will emit events for files being created, updated or deleted. + */ +export class FileWatcher extends HelpfulEventEmitter implements IFileWatcher { + private initialized = false + private delayEmitNewFileTimeoutMap = new Map() + private watcher: ParcelWatcher.AsyncSubscription | undefined = undefined + + constructor(private folderPath: string, private options: Options) { + super() + this.addHelpfulEventCheck('fileEvent') + } + /** + * Initialize the FileWatcher. + * While this promise is resolving, the FileWatcher will emit the initial list of files + * + */ + async init(): Promise { + if (this.initialized) throw new Error('Already initialized') + this.initialized = true + + // Get the initial list of files: + const filePaths = await this.initListAllFiles(this.folderPath) + this.onFileEvents( + undefined, + filePaths.map((filePath) => ({ type: 'create', path: filePath })) + ) + + // Watch for events: + this.watcher = await ParcelWatcher.subscribe(this.folderPath, this.onFileEvents, this.options) + } + async stop(): Promise { + if (this.watcher) { + await this.watcher.unsubscribe() + delete this.watcher + } + } + /** Get the local filepath from the fullPath */ + public getLocalFilePath(fullPath: string): string | undefined { + return path.relative(this.folderPath, fullPath) + } + + private onFileEvents = (error: any | undefined, events: ParcelWatcher.Event[]) => { + if (error) { + this.emit('error', `Unexpected error event: ${stringifyError(error)}`) + } + + if (events) { + for (const event of events) { + if (event.type === 'create' || event.type === 'update') { + this.onFileCreatedUpdated(event) + } else if (event.type === 'delete') { + this.onFileCreatedDeleted(event) + } else { + assertNever(event.type) + } + } + } + } + /** Called whenever a file is created or updated */ + private onFileCreatedUpdated(event: ParcelWatcher.Event) { + const fullPath = event.path + + if (this.options.awaitWriteFinishStabilityThreshold) { + const waitTime = this.options.awaitWriteFinishStabilityThreshold + // Delay the emit, to avoid emitting multiple times for the same file while it's updating + + fs.stat(fullPath, (error, stats) => { + if (error) { + if (error.code === 'ENOENT') { + // File doesn't exist anymore, so don't emit + return + } else { + this.emit('error', `Error in fs.stat ${stringifyError(error)}`) + } + } else { + this.checkIfFileIsStable(event, stats.size, waitTime) + } + }) + } else { + this.emit('fileEvent', event) + } + } + /** Called whenever a file is deleted */ + private onFileCreatedDeleted(event: ParcelWatcher.Event) { + const fullPath = event.path + + // We don't trust the watcher completely, so we'll check it ourselves first.. + // (We've seen an issue where removing a single file from a folder causes chokidar to emit unlink for ALL the files) + fs.access(fullPath, fs.constants.R_OK, (err) => { + if (err) { + // The file truly doesn't exist + this.delayEmitNewFileTimeoutMap.delete(fullPath) + + const localPath = this.getLocalFilePath(fullPath) + if (localPath) { + this.emit('fileEvent', event) + } + } else { + // The file seems to exist, even though chokidar says it doesn't. + // Ignore the event, then + } + }) + } + + /** + * List all files recursively in a directory. + * This is done initially, to get an initial list of files. + */ + private async initListAllFiles(folderPath: string): Promise { + const fileList: string[] = [] + + const files = await fs.promises.readdir(folderPath, { withFileTypes: true }) + + for (const file of files) { + const fullPath = path.join(folderPath, file.name) + if (file.isDirectory()) { + const innerFileList = await this.initListAllFiles(fullPath) + for (const innerFile of innerFileList) { + fileList.push(innerFile) + } + } else { + fileList.push(fullPath) + } + } + + return fileList + } + + /** + * Checks if the file is stable, ie hasn't changed its size since last check. + * This is useful to avoid emitting multiple times for the same file while it's updating. + */ + private checkIfFileIsStable(event: ParcelWatcher.Event, previousSize: number, waitTime: number) { + const fullPath = event.path + + const previousTimeout = this.delayEmitNewFileTimeoutMap.get(fullPath) + if (previousTimeout) clearTimeout(previousTimeout) + + this.delayEmitNewFileTimeoutMap.set( + fullPath, + setTimeout(() => { + this.delayEmitNewFileTimeoutMap.delete(fullPath) + + fs.stat(fullPath, (error, stats) => { + if (error) { + if (error.code === 'ENOENT') { + // File doesn't exist anymore, so don't emit + return + } else { + this.emit('error', `Error in fs.stat ${stringifyError(error)}`) + } + } else { + if (stats.size !== previousSize) { + // Try again later: + this.checkIfFileIsStable(event, stats.size, waitTime) + } else { + this.emit('fileEvent', event) + } + } + }) + }, waitTime) + ) + } +} + +export interface Options { + ignore?: string[] + /** If set, will wait for the file being unchanged for the specified duration before considering it [ms] */ + awaitWriteFinishStabilityThreshold?: number | null +} +export interface FileEvent { + type: 'create' | 'update' | 'delete' + path: string +} diff --git a/shared/packages/worker/src/worker/accessorHandlers/localFolder.ts b/shared/packages/worker/src/worker/accessorHandlers/localFolder.ts index 14dbf7d8..6cbf7461 100644 --- a/shared/packages/worker/src/worker/accessorHandlers/localFolder.ts +++ b/shared/packages/worker/src/worker/accessorHandlers/localFolder.ts @@ -305,7 +305,7 @@ export class LocalFolderAccessorHandle extends GenericFileAccessorHand for (const monitorId of monitorIds) { if (monitorId === 'packages') { // setup file monitor: - resultingMonitors[monitorId] = this.setupPackagesMonitor(packageContainerExp) + resultingMonitors[monitorId] = await this.setupPackagesMonitor(packageContainerExp) } else { // Assert that cronjob is of type "never", to ensure that all types of monitors are handled: assertNever(monitorId) diff --git a/shared/packages/worker/src/workerAgent.ts b/shared/packages/worker/src/workerAgent.ts index 85ad3fe8..accc7d84 100644 --- a/shared/packages/worker/src/workerAgent.ts +++ b/shared/packages/worker/src/workerAgent.ts @@ -603,6 +603,7 @@ export class WorkerAgent { this.activeMonitors[packageContainer.id][monitorId] = monitorInProgress returnMonitors[monitorId] = monitorInProgress.properties + monitorInProgress.removeAllListeners('error') // Replace any temporary listeners monitorInProgress.on('error', (internalError: unknown) => { this.logger.error( `WorkerAgent.methods.setupPackageContainerMonitors: ${JSON.stringify(internalError)}` diff --git a/yarn.lock b/yarn.lock index 32f4d9a3..581717cd 100644 --- a/yarn.lock +++ b/yarn.lock @@ -1189,6 +1189,66 @@ dependencies: "@octokit/openapi-types" "^17.1.0" +"@parcel/watcher-android-arm64@2.3.0": + version "2.3.0" + resolved "https://registry.yarnpkg.com/@parcel/watcher-android-arm64/-/watcher-android-arm64-2.3.0.tgz#d82e74bb564ebd4d8a88791d273a3d2bd61e27ab" + integrity sha512-f4o9eA3dgk0XRT3XhB0UWpWpLnKgrh1IwNJKJ7UJek7eTYccQ8LR7XUWFKqw6aEq5KUNlCcGvSzKqSX/vtWVVA== + +"@parcel/watcher-darwin-arm64@2.3.0": + version "2.3.0" + resolved "https://registry.yarnpkg.com/@parcel/watcher-darwin-arm64/-/watcher-darwin-arm64-2.3.0.tgz#c9cd03f8f233d512fcfc873d5b4e23f1569a82ad" + integrity sha512-mKY+oijI4ahBMc/GygVGvEdOq0L4DxhYgwQqYAz/7yPzuGi79oXrZG52WdpGA1wLBPrYb0T8uBaGFo7I6rvSKw== + +"@parcel/watcher-darwin-x64@2.3.0": + version "2.3.0" + resolved "https://registry.yarnpkg.com/@parcel/watcher-darwin-x64/-/watcher-darwin-x64-2.3.0.tgz#83c902994a2a49b9e1ab5050dba24876fdc2c219" + integrity sha512-20oBj8LcEOnLE3mgpy6zuOq8AplPu9NcSSSfyVKgfOhNAc4eF4ob3ldj0xWjGGbOF7Dcy1Tvm6ytvgdjlfUeow== + +"@parcel/watcher-freebsd-x64@2.3.0": + version "2.3.0" + resolved "https://registry.yarnpkg.com/@parcel/watcher-freebsd-x64/-/watcher-freebsd-x64-2.3.0.tgz#7a0f4593a887e2752b706aff2dae509aef430cf6" + integrity sha512-7LftKlaHunueAEiojhCn+Ef2CTXWsLgTl4hq0pkhkTBFI3ssj2bJXmH2L67mKpiAD5dz66JYk4zS66qzdnIOgw== + +"@parcel/watcher-linux-arm-glibc@2.3.0": + version "2.3.0" + resolved "https://registry.yarnpkg.com/@parcel/watcher-linux-arm-glibc/-/watcher-linux-arm-glibc-2.3.0.tgz#3fc90c3ebe67de3648ed2f138068722f9b1d47da" + integrity sha512-1apPw5cD2xBv1XIHPUlq0cO6iAaEUQ3BcY0ysSyD9Kuyw4MoWm1DV+W9mneWI+1g6OeP6dhikiFE6BlU+AToTQ== + +"@parcel/watcher-linux-arm64-glibc@2.3.0": + version "2.3.0" + resolved "https://registry.yarnpkg.com/@parcel/watcher-linux-arm64-glibc/-/watcher-linux-arm64-glibc-2.3.0.tgz#f7bbbf2497d85fd11e4c9e9c26ace8f10ea9bcbc" + integrity sha512-mQ0gBSQEiq1k/MMkgcSB0Ic47UORZBmWoAWlMrTW6nbAGoLZP+h7AtUM7H3oDu34TBFFvjy4JCGP43JlylkTQA== + +"@parcel/watcher-linux-arm64-musl@2.3.0": + version "2.3.0" + resolved "https://registry.yarnpkg.com/@parcel/watcher-linux-arm64-musl/-/watcher-linux-arm64-musl-2.3.0.tgz#de131a9fcbe1fa0854e9cbf4c55bed3b35bcff43" + integrity sha512-LXZAExpepJew0Gp8ZkJ+xDZaTQjLHv48h0p0Vw2VMFQ8A+RKrAvpFuPVCVwKJCr5SE+zvaG+Etg56qXvTDIedw== + +"@parcel/watcher-linux-x64-glibc@2.3.0": + version "2.3.0" + resolved "https://registry.yarnpkg.com/@parcel/watcher-linux-x64-glibc/-/watcher-linux-x64-glibc-2.3.0.tgz#193dd1c798003cdb5a1e59470ff26300f418a943" + integrity sha512-P7Wo91lKSeSgMTtG7CnBS6WrA5otr1K7shhSjKHNePVmfBHDoAOHYRXgUmhiNfbcGk0uMCHVcdbfxtuiZCHVow== + +"@parcel/watcher-linux-x64-musl@2.3.0": + version "2.3.0" + resolved "https://registry.yarnpkg.com/@parcel/watcher-linux-x64-musl/-/watcher-linux-x64-musl-2.3.0.tgz#6dbdb86d96e955ab0fe4a4b60734ec0025a689dd" + integrity sha512-+kiRE1JIq8QdxzwoYY+wzBs9YbJ34guBweTK8nlzLKimn5EQ2b2FSC+tAOpq302BuIMjyuUGvBiUhEcLIGMQ5g== + +"@parcel/watcher-win32-arm64@2.3.0": + version "2.3.0" + resolved "https://registry.yarnpkg.com/@parcel/watcher-win32-arm64/-/watcher-win32-arm64-2.3.0.tgz#59da26a431da946e6c74fa6b0f30b120ea6650b6" + integrity sha512-35gXCnaz1AqIXpG42evcoP2+sNL62gZTMZne3IackM+6QlfMcJLy3DrjuL6Iks7Czpd3j4xRBzez3ADCj1l7Aw== + +"@parcel/watcher-win32-ia32@2.3.0": + version "2.3.0" + resolved "https://registry.yarnpkg.com/@parcel/watcher-win32-ia32/-/watcher-win32-ia32-2.3.0.tgz#3ee6a18b08929cd3b788e8cc9547fd9a540c013a" + integrity sha512-FJS/IBQHhRpZ6PiCjFt1UAcPr0YmCLHRbTc00IBTrelEjlmmgIVLeOx4MSXzx2HFEy5Jo5YdhGpxCuqCyDJ5ow== + +"@parcel/watcher-win32-x64@2.3.0": + version "2.3.0" + resolved "https://registry.yarnpkg.com/@parcel/watcher-win32-x64/-/watcher-win32-x64-2.3.0.tgz#14e7246289861acc589fd608de39fe5d8b4bb0a7" + integrity sha512-dLx+0XRdMnVI62kU3wbXvbIRhLck4aE28bIGKbRGS7BJNt54IIj9+c/Dkqb+7DJEbHUZAX1bwaoM8PqVlHJmCA== + "@parcel/watcher@2.0.4": version "2.0.4" resolved "https://registry.yarnpkg.com/@parcel/watcher/-/watcher-2.0.4.tgz#f300fef4cc38008ff4b8c29d92588eced3ce014b" @@ -1197,6 +1257,29 @@ node-addon-api "^3.2.1" node-gyp-build "^4.3.0" +"@parcel/watcher@^2.3.0": + version "2.3.0" + resolved "https://registry.yarnpkg.com/@parcel/watcher/-/watcher-2.3.0.tgz#803517abbc3981a1a1221791d9f59dc0590d50f9" + integrity sha512-pW7QaFiL11O0BphO+bq3MgqeX/INAk9jgBldVDYjlQPO4VddoZnF22TcF9onMhnLVHuNqBJeRf+Fj7eezi/+rQ== + dependencies: + detect-libc "^1.0.3" + is-glob "^4.0.3" + micromatch "^4.0.5" + node-addon-api "^7.0.0" + optionalDependencies: + "@parcel/watcher-android-arm64" "2.3.0" + "@parcel/watcher-darwin-arm64" "2.3.0" + "@parcel/watcher-darwin-x64" "2.3.0" + "@parcel/watcher-freebsd-x64" "2.3.0" + "@parcel/watcher-linux-arm-glibc" "2.3.0" + "@parcel/watcher-linux-arm64-glibc" "2.3.0" + "@parcel/watcher-linux-arm64-musl" "2.3.0" + "@parcel/watcher-linux-x64-glibc" "2.3.0" + "@parcel/watcher-linux-x64-musl" "2.3.0" + "@parcel/watcher-win32-arm64" "2.3.0" + "@parcel/watcher-win32-ia32" "2.3.0" + "@parcel/watcher-win32-x64" "2.3.0" + "@pkgjs/parseargs@^0.11.0": version "0.11.0" resolved "https://registry.yarnpkg.com/@pkgjs/parseargs/-/parseargs-0.11.0.tgz#a77ea742fab25775145434eb1d2328cf5013ac33" @@ -1976,7 +2059,7 @@ ansi-styles@^6.1.0: resolved "https://registry.yarnpkg.com/ansi-styles/-/ansi-styles-6.2.1.tgz#0e62320cf99c21afff3b3012192546aacbfb05c5" integrity sha512-bN798gFfQX+viw3R7yrGWRqnrN2oRkEkUjjl4JNn4E8GxxbjtG3FbrEIIY3l8/hrwUwIeCZvi4QuOTP4MErVug== -anymatch@^3.0.3, anymatch@~3.1.2: +anymatch@^3.0.3: version "3.1.2" resolved "https://registry.yarnpkg.com/anymatch/-/anymatch-3.1.2.tgz#c0557c096af32f106198f4f4e2a383537e378716" integrity sha512-P43ePfOAIupkguHUycrc4qJ9kz8ZiuOUijaETwX7THt0Y/GNK7v0aa8rY816xWjZ7rJdA5XdMcpVFTKMq+RvWg== @@ -2284,11 +2367,6 @@ bin-links@^4.0.1: read-cmd-shim "^4.0.0" write-file-atomic "^5.0.0" -binary-extensions@^2.0.0: - version "2.2.0" - resolved "https://registry.yarnpkg.com/binary-extensions/-/binary-extensions-2.2.0.tgz#75f502eeaf9ffde42fc98829645be4ea76bd9e2d" - integrity sha512-jDctJ/IVQbZoJykoeHbhXpOlNBqGNcwXJKJog42E5HDPUwQTSdjCHdihjj0DlnheQ7blbT6dHOafNAiS8ooQKA== - bitdepth@^7.0.2: version "7.0.2" resolved "https://registry.yarnpkg.com/bitdepth/-/bitdepth-7.0.2.tgz#d9290de0e4b44ce5fc0c29f813c8f49fbdfa2eeb" @@ -2342,7 +2420,7 @@ braces@^2.3.1: split-string "^3.0.2" to-regex "^3.0.1" -braces@^3.0.2, braces@~3.0.2: +braces@^3.0.2: version "3.0.2" resolved "https://registry.yarnpkg.com/braces/-/braces-3.0.2.tgz#3454e1a462ee8d599e236df336cd9ea4f8afe107" integrity sha512-b8um+L1RzM3WDSzvhm6gIz1yfTbBt6YTlcEKAvsmqCZZFw46z626lVj9j1yEPW33H5H+lBQpZMP1k8l+78Ha0A== @@ -2680,21 +2758,6 @@ cherow@1.6.9: resolved "https://registry.yarnpkg.com/cherow/-/cherow-1.6.9.tgz#7c5e34fce297f152a6f7853dcc9fe2f9e1b36ab8" integrity sha512-pmmkpIQRcnDA7EawKcg9+ncSZNTYfXqDx+K3oqqYvpZlqVBChjTomTfw+hePnkqYR3Y013818c0R1Q5P/7PGrQ== -chokidar@^3.5.1: - version "3.5.3" - resolved "https://registry.yarnpkg.com/chokidar/-/chokidar-3.5.3.tgz#1cf37c8707b932bd1af1ae22c0432e2acd1903bd" - integrity sha512-Dr3sfKRP6oTcjf2JmUmFJfeVMvXBdegxB0iVQ5eb2V10uFJUCAS8OByZdVAyVb8xXNz3GjjTgj9kLWsZTqE6kw== - dependencies: - anymatch "~3.1.2" - braces "~3.0.2" - glob-parent "~5.1.2" - is-binary-path "~2.1.0" - is-glob "~4.0.1" - normalize-path "~3.0.0" - readdirp "~3.6.0" - optionalDependencies: - fsevents "~2.3.2" - chownr@^1.1.1: version "1.1.4" resolved "https://registry.yarnpkg.com/chownr/-/chownr-1.1.4.tgz#6fc9d7b42d32a583596337666e7d08084da2cc6b" @@ -4373,7 +4436,7 @@ fs.realpath@^1.0.0: resolved "https://registry.yarnpkg.com/fs.realpath/-/fs.realpath-1.0.0.tgz#1504ad2523158caa40db4a2787cb01411994ea4f" integrity sha512-OO0pH2lK6a0hZnAdau5ItzHPI6pUlvI7jMVnxUQRtw4owF2wk8lOSabtGDCTP4Ggrg2MbGnWO9X8K1t4+fGMDw== -fsevents@^2.3.2, fsevents@~2.3.2: +fsevents@^2.3.2: version "2.3.2" resolved "https://registry.yarnpkg.com/fsevents/-/fsevents-2.3.2.tgz#8a526f78b8fdf4623b709e0b975c52c24c02fd1a" integrity sha512-xiqMQR4xAeHTuB9uWm+fFRcIOgKBMiOBP+eXiyT7jsgVCq1bkVygt00oASowB7EdtpOHaaPgKt812P9ab+DDKA== @@ -4574,7 +4637,7 @@ github-from-package@0.0.0: resolved "https://registry.yarnpkg.com/github-from-package/-/github-from-package-0.0.0.tgz#97fb5d96bfde8973313f20e8288ef9a167fa64ce" integrity sha512-SyHy3T1v2NUXn29OsWdxmK6RwHD+vkj3v8en8AOBZ1wBQ/hCAQ5bAQTD02kW4W9tUp/3Qh6J8r9EvntiyCmOOw== -glob-parent@5.1.2, glob-parent@^5.1.2, glob-parent@~5.1.2: +glob-parent@5.1.2, glob-parent@^5.1.2: version "5.1.2" resolved "https://registry.yarnpkg.com/glob-parent/-/glob-parent-5.1.2.tgz#869832c58034fe68a4093c17dc15e8340d8401c4" integrity sha512-AOIgSQCepiJYwP3ARnGx+5VnTu2HBYdzbGP45eLw1vr3zB3vZLeyed1sC9hnbcOc9/SrMyM5RPQrkGz4aS9Zow== @@ -5243,13 +5306,6 @@ is-arrayish@^0.3.1: resolved "https://registry.yarnpkg.com/is-arrayish/-/is-arrayish-0.3.2.tgz#4574a2ae56f7ab206896fb431eaeed066fdf8f03" integrity sha512-eVRqCvVlZbuw3GrM63ovNSNAeA1K16kaR/LRY/92w0zxQ5/1YzwblUX652i4Xs9RwAGjW9d9y6X88t8OaAJfWQ== -is-binary-path@~2.1.0: - version "2.1.0" - resolved "https://registry.yarnpkg.com/is-binary-path/-/is-binary-path-2.1.0.tgz#ea1f7f3b80f064236e83470f86c09c254fb45b09" - integrity sha512-ZMERYes6pDydyuGidse7OsHxtbI7WVeUEozgR/g7rd0xUimYNlvZRE/K2MgZTjWy725IfelLeVcEM97mmtRGXw== - dependencies: - binary-extensions "^2.0.0" - is-buffer@^1.1.5: version "1.1.6" resolved "https://registry.yarnpkg.com/is-buffer/-/is-buffer-1.1.6.tgz#efaa2ea9daa0d7ab2ea13a97b2b8ad51fefbe8be" @@ -5366,7 +5422,7 @@ is-glob@^3.1.0: dependencies: is-extglob "^2.1.0" -is-glob@^4.0.0, is-glob@^4.0.1, is-glob@^4.0.3, is-glob@~4.0.1: +is-glob@^4.0.0, is-glob@^4.0.1, is-glob@^4.0.3: version "4.0.3" resolved "https://registry.yarnpkg.com/is-glob/-/is-glob-4.0.3.tgz#64f61e42cbbb2eec2071a9dac0b28ba1e65d5084" integrity sha512-xelSayHH36ZgE7ZWhli7pW34hNbNl8Ojv5KVmkJD4hBdD3th8Tfk9vYasLM+mXWOZhFkgZfxhLSnrwRr4elSSg== @@ -7150,6 +7206,11 @@ node-addon-api@^5.0.0: resolved "https://registry.yarnpkg.com/node-addon-api/-/node-addon-api-5.1.0.tgz#49da1ca055e109a23d537e9de43c09cca21eb762" integrity sha512-eh0GgfEkpnoWDq+VY8OyvYhFEzBk6jIYbRKdIlyTiAXIVJ8PyBaKb0rp7oDtoddbdoHWhq8wwr+XZ81F1rpNdA== +node-addon-api@^7.0.0: + version "7.0.0" + resolved "https://registry.yarnpkg.com/node-addon-api/-/node-addon-api-7.0.0.tgz#8136add2f510997b3b94814f4af1cce0b0e3962e" + integrity sha512-vgbBJTS4m5/KkE16t5Ly0WW9hz46swAstv0hYYwMtbG7AznRhNyfLRe8HZAiWIpcHzoO7HxhLuBQj9rJ/Ho0ZA== + node-fetch@2.6.7: version "2.6.7" resolved "https://registry.yarnpkg.com/node-fetch/-/node-fetch-2.6.7.tgz#24de9fba827e3b4ae44dc8b20256a379160052ad" @@ -7257,7 +7318,7 @@ normalize-package-data@^5.0.0: semver "^7.3.5" validate-npm-package-license "^3.0.4" -normalize-path@^3.0.0, normalize-path@~3.0.0: +normalize-path@^3.0.0: version "3.0.0" resolved "https://registry.yarnpkg.com/normalize-path/-/normalize-path-3.0.0.tgz#0dcd69ff23a1c9b11fd0978316644a0388216a65" integrity sha512-6eZs5Ls3WtCisHWp9S2GUy8dqkpGi4BVSz3GaqiE6ezub0512ESztXUwUB6C6IKbQkY2Pnb/mD4WYojCRwcwLA== @@ -8015,7 +8076,7 @@ picocolors@^1.0.0: resolved "https://registry.yarnpkg.com/picocolors/-/picocolors-1.0.0.tgz#cb5bdc74ff3f51892236eaf79d68bc44564ab81c" integrity sha512-1fygroTLlHu66zi26VoTDv8yRgm0Fccecssto+MhsZ0D/DGW2sm8E8AjW7NU5VVTRt5GxbeZ5qBuJr+HyLYkjQ== -picomatch@^2.0.4, picomatch@^2.2.1, picomatch@^2.2.3, picomatch@^2.3.1: +picomatch@^2.0.4, picomatch@^2.2.3, picomatch@^2.3.1: version "2.3.1" resolved "https://registry.yarnpkg.com/picomatch/-/picomatch-2.3.1.tgz#3ba3833733646d9d3e4995946c1365a67fb07a42" integrity sha512-JU3teHTNjmE2VCGFzuY8EXzCDVwEqB2a8fsIvwaStHhAWJEeVd1o1QD80CU6+ZdEXXSLbSsuLwJjkCBWqRQUVA== @@ -8541,13 +8602,6 @@ readdir-scoped-modules@^1.0.0: graceful-fs "^4.1.2" once "^1.3.0" -readdirp@~3.6.0: - version "3.6.0" - resolved "https://registry.yarnpkg.com/readdirp/-/readdirp-3.6.0.tgz#74a370bd857116e245b29cc97340cd431a02a6c7" - integrity sha512-hOS089on8RduqdbhvQ5Z37A0ESjsqz6qnRcffsMU3495FuTdqSm+7bhJ29JvIOsBDEEnan5DPu9t3To9VRlMzA== - dependencies: - picomatch "^2.2.1" - rechoir@^0.6.2: version "0.6.2" resolved "https://registry.yarnpkg.com/rechoir/-/rechoir-0.6.2.tgz#85204b54dba82d5742e28c96756ef43af50e3384" From 52043c03fd924f33c88e7e4771826e8e2ff435e5 Mon Sep 17 00:00:00 2001 From: Johan Nyman Date: Fri, 6 Oct 2023 07:21:57 +0200 Subject: [PATCH 09/17] fix: improve debug logging, add CLI argument: --logLevel=debug --- .../packages/generic/src/appContainer.ts | 2 +- .../packages/generic/src/packageManager.ts | 57 +++++++++++++++---- apps/single-app/app/src/singleApp.ts | 15 ++++- shared/packages/api/src/config.ts | 12 +++- shared/packages/api/src/logger.ts | 3 + .../src/evaluationRunner/evaluationRunner.ts | 4 ++ tests/internal-tests/src/__mocks__/fs.ts | 1 - 7 files changed, 79 insertions(+), 15 deletions(-) diff --git a/apps/appcontainer-node/packages/generic/src/appContainer.ts b/apps/appcontainer-node/packages/generic/src/appContainer.ts index c3cf16ca..ab61f577 100644 --- a/apps/appcontainer-node/packages/generic/src/appContainer.ts +++ b/apps/appcontainer-node/packages/generic/src/appContainer.ts @@ -217,7 +217,7 @@ export class AppContainer { this.initWorkForceApiPromise = { resolve, reject } }) - this.logger.info(`Initialized"`) + this.logger.info(`Initialized`) } /** Return the API-methods that the AppContainer exposes to the WorkerAgent */ private getWorkerAgentAPI(clientId: string): AppContainerWorkerAgent.AppContainer { diff --git a/apps/package-manager/packages/generic/src/packageManager.ts b/apps/package-manager/packages/generic/src/packageManager.ts index 0ff79964..f4667778 100644 --- a/apps/package-manager/packages/generic/src/packageManager.ts +++ b/apps/package-manager/packages/generic/src/packageManager.ts @@ -190,8 +190,11 @@ export class PackageManagerHandler { this._triggerUpdatedExpectedPackagesTimeout = setTimeout(() => { this._triggerUpdatedExpectedPackagesTimeout = null - const expectedPackages: ExpectedPackageWrap[] = [] const packageContainers: PackageContainers = {} + const expectedPackageSources: { + sourceName: string + expectedPackages: ExpectedPackageWrap[] + }[] = [] let activePlaylist: ActivePlaylist = { _id: '', @@ -202,10 +205,17 @@ export class PackageManagerHandler { // Add from external data: { + const expectedPackagesExternal: ExpectedPackageWrap[] = [] for (const expectedPackage of this.externalData.expectedPackages) { - expectedPackages.push(expectedPackage) + expectedPackagesExternal.push(expectedPackage) } Object.assign(packageContainers, this.externalData.packageContainers) + if (expectedPackagesExternal.length > 0) { + expectedPackageSources.push({ + sourceName: 'external', + expectedPackages: expectedPackagesExternal, + }) + } } if (!this.coreHandler.notUsingCore) { @@ -222,6 +232,7 @@ export class PackageManagerHandler { // Add from Core collections: { + const expectedPackagesCore: ExpectedPackageWrap[] = [] const expectedPackageObjs = objs.filter((o) => o.type === 'expected_packages') if (!expectedPackageObjs.length) { @@ -232,7 +243,7 @@ export class PackageManagerHandler { for (const expectedPackageObj of expectedPackageObjs) { for (const expectedPackage of expectedPackageObj.expectedPackages) { // Note: There might be duplicates of packages here, to be deduplicated later - expectedPackages.push(expectedPackage) + expectedPackagesCore.push(expectedPackage) } } @@ -243,19 +254,26 @@ export class PackageManagerHandler { return } Object.assign(packageContainers, packageContainerObj.packageContainers as PackageContainers) + if (expectedPackagesCore.length > 0) { + expectedPackageSources.push({ + sourceName: 'core', + expectedPackages: expectedPackagesCore, + }) + } } } // Add from Monitors: { - for (const monitorExpectedPackages of Object.values(this.monitoredPackages)) { - for (const expectedPackage of monitorExpectedPackages) { - expectedPackages.push(expectedPackage) - } + for (const [monitorId, monitorExpectedPackages] of Object.entries(this.monitoredPackages)) { + expectedPackageSources.push({ + sourceName: `monitor_${monitorId}`, + expectedPackages: monitorExpectedPackages, + }) } } - this.handleExpectedPackages(packageContainers, activePlaylist, activeRundowns, expectedPackages) + this.handleExpectedPackages(packageContainers, activePlaylist, activeRundowns, expectedPackageSources) }, 300) } @@ -264,8 +282,18 @@ export class PackageManagerHandler { activePlaylist: ActivePlaylist, activeRundowns: ActiveRundown[], - expectedPackages: ExpectedPackageWrap[] + expectedPackageSources: { + sourceName: string + expectedPackages: ExpectedPackageWrap[] + }[] ) { + const expectedPackages: ExpectedPackageWrap[] = [] + for (const expectedPackageSource of expectedPackageSources) { + for (const exp of expectedPackageSource.expectedPackages) { + expectedPackages.push(exp) + } + } + // Step 0: Save local cache: this.expectedPackageCache = {} this.packageContainersCache = packageContainers @@ -281,7 +309,12 @@ export class PackageManagerHandler { } } - this.logger.debug(`Has ${expectedPackages.length} expectedPackages`) + this.logger.debug( + `Has ${expectedPackages.length} expectedPackages (${expectedPackageSources + .map((s) => `${s.sourceName}: ${s.expectedPackages.length}`) + .join(', ')})` + ) + this.logger.silly(JSON.stringify(expectedPackages, null, 2)) // this.logger.debug(JSON.stringify(expectedPackages, null, 2)) this.dataSnapshot.expectedPackages = expectedPackages @@ -298,15 +331,19 @@ export class PackageManagerHandler { this.settings ) this.logger.debug(`Has ${Object.keys(expectations).length} expectations`) + this.logger.silly(JSON.stringify(expectations, null, 2)) // this.logger.debug(JSON.stringify(expectations, null, 2)) this.dataSnapshot.expectations = expectations + this.logger.debug(`Has ${Object.keys(this.packageContainersCache).length} packageContainers`) + this.logger.silly(JSON.stringify(this.packageContainersCache, null, 2)) const packageContainerExpectations = this.expectationGeneratorApi.getPackageContainerExpectations( this.expectationManager.managerId, this.packageContainersCache, activePlaylist ) this.logger.debug(`Has ${Object.keys(packageContainerExpectations).length} packageContainerExpectations`) + this.logger.silly(JSON.stringify(packageContainerExpectations, null, 2)) this.dataSnapshot.packageContainerExpectations = packageContainerExpectations this.dataSnapshot.updated = Date.now() diff --git a/apps/single-app/app/src/singleApp.ts b/apps/single-app/app/src/singleApp.ts index ddc5dff3..b83b3063 100644 --- a/apps/single-app/app/src/singleApp.ts +++ b/apps/single-app/app/src/singleApp.ts @@ -3,13 +3,26 @@ import * as QuantelHTTPTransformerProxy from '@quantel-http-transformer-proxy/ge import * as PackageManager from '@package-manager/generic' import * as Workforce from '@sofie-package-manager/workforce' import * as AppConatainerNode from '@appcontainer-node/generic' -import { getSingleAppConfig, ProcessHandler, setupLogger, initializeLogger } from '@sofie-package-manager/api' +import { + getSingleAppConfig, + ProcessHandler, + setupLogger, + initializeLogger, + setLogLevel, + isLogLevel, +} from '@sofie-package-manager/api' export async function startSingleApp(): Promise { const config = await getSingleAppConfig() initializeLogger(config) const logger = setupLogger(config, 'single-app') const baseLogger = setupLogger(config, '') + + const logLevel = config.process.logLevel + if (logLevel && isLogLevel(logLevel)) { + logger.info(`Setting log level to ${logLevel}`) + setLogLevel(logLevel) + } // Override some of the arguments, as they arent used in the single-app config.packageManager.port = 0 // 0 = Set the packageManager port to whatever is available config.packageManager.accessUrl = 'ws:127.0.0.1' diff --git a/shared/packages/api/src/config.ts b/shared/packages/api/src/config.ts index 90ecab4a..c142f8a8 100644 --- a/shared/packages/api/src/config.ts +++ b/shared/packages/api/src/config.ts @@ -11,6 +11,7 @@ import { AppContainerConfig } from './appContainer' /** Generic CLI-argument-definitions for any process */ const processOptions = defineArguments({ logPath: { type: 'string', describe: 'Set to write logs to this file' }, + logLevel: { type: 'string', describe: 'Set default log level. (Might be overwritten by Sofie Core)' }, unsafeSSL: { type: 'boolean', @@ -274,15 +275,22 @@ const quantelHTTPTransformerProxyConfigArguments = defineArguments({ export interface ProcessConfig { logPath: string | undefined - /** Will cause the Node applocation to blindly accept all certificates. Not recommenced unless in local, controlled networks. */ + logLevel: string | undefined + /** Will cause the Node app to blindly accept all certificates. Not recommenced unless in local, controlled networks. */ unsafeSSL: boolean /** Paths to certificates to load, for SSL-connections */ certificates: string[] } -function getProcessConfig(argv: { logPath: string | undefined; unsafeSSL: boolean; certificates: string | undefined }) { +function getProcessConfig(argv: { + logPath: string | undefined + logLevel: string | undefined + unsafeSSL: boolean + certificates: string | undefined +}) { const certs: string[] = (argv.certificates || process.env.CERTIFICATES || '').split(';') || [] return { logPath: argv.logPath, + logLevel: argv.logLevel, unsafeSSL: argv.unsafeSSL, certificates: _.compact(certs), } diff --git a/shared/packages/api/src/logger.ts b/shared/packages/api/src/logger.ts index 9daca243..e1ac9c28 100644 --- a/shared/packages/api/src/logger.ts +++ b/shared/packages/api/src/logger.ts @@ -20,6 +20,9 @@ export enum LogLevel { DEBUG = 'debug', SILLY = 'silly', } +export function isLogLevel(logLevel: string): logLevel is LogLevel { + return ['error', 'warn', 'info', 'verbose', 'debug', 'silly'].includes(logLevel) +} export const DEFAULT_LOG_LEVEL = LogLevel.VERBOSE diff --git a/shared/packages/expectationManager/src/evaluationRunner/evaluationRunner.ts b/shared/packages/expectationManager/src/evaluationRunner/evaluationRunner.ts index 39f4f4a6..2939e63f 100644 --- a/shared/packages/expectationManager/src/evaluationRunner/evaluationRunner.ts +++ b/shared/packages/expectationManager/src/evaluationRunner/evaluationRunner.ts @@ -628,6 +628,10 @@ export class EvaluationRunner { if (monitorSetup.success) { trackedPackageContainer.monitorIsSetup = true for (const [monitorId, monitor] of Object.entries(monitorSetup.monitors)) { + this.logger.debug( + `Set up monitor "${monitor.label}" (${monitorId}) for PackageContainer ${trackedPackageContainer.id}` + ) + if (trackedPackageContainer.status.monitors[monitorId]) { // In case there no monitor status has been emitted yet: this.tracker.trackedPackageContainerAPI.updateTrackedPackageContainerMonitorStatus( diff --git a/tests/internal-tests/src/__mocks__/fs.ts b/tests/internal-tests/src/__mocks__/fs.ts index 4fa4fe5f..36bb4a3f 100644 --- a/tests/internal-tests/src/__mocks__/fs.ts +++ b/tests/internal-tests/src/__mocks__/fs.ts @@ -324,7 +324,6 @@ export function access(path: string, mode: number | undefined, callback: (error: const mockFile = getMock(path) // if (DEBUG_LOG) console.log('fs.access', path, mode) fsMockEmitter.emit('access', path, mode) - if (FS_ACCESS_DELAY > 0) console.log('FS_ACCESS_DELAY', FS_ACCESS_DELAY) setTimeout(() => { try { if (mode === constants.R_OK && !mockFile.accessRead) { From a5c35f25e13c1916a1c963734e644f859a3cb453 Mon Sep 17 00:00:00 2001 From: Johan Nyman Date: Wed, 11 Oct 2023 12:44:58 +0200 Subject: [PATCH 10/17] chore: refactor build scripts --- scripts/build-win32.mjs | 13 ++++++--- scripts/prepare-for-build32.js | 50 ++++++++++++++++++---------------- 2 files changed, 36 insertions(+), 27 deletions(-) diff --git a/scripts/build-win32.mjs b/scripts/build-win32.mjs index 7977f57c..444960b9 100644 --- a/scripts/build-win32.mjs +++ b/scripts/build-win32.mjs @@ -93,18 +93,23 @@ if (!executableName) { const extraArgs = [] + const assets = [] + if (packageJson.name === '@single-app/app') { + assets.push(path.join(basePath, './node_modules/@sofie-automation/server-core-integration/package.json')) + assets.push(path.join(basePath, './package.json')) + } + + if (assets.length > 0) { extraArgs.push( '--assets', - [ - path.join(basePath, './node_modules/@sofie-automation/server-core-integration/package.json'), - path.join(basePath, './package.json'), - ].join(',') + assets.join(',') ) } await pkg.exec([ path.join(basePath, './dist/index.js'), + // '--debug', '--targets', 'node16-win-x64', '--output', diff --git a/scripts/prepare-for-build32.js b/scripts/prepare-for-build32.js index a28e07f5..5d5feca1 100644 --- a/scripts/prepare-for-build32.js +++ b/scripts/prepare-for-build32.js @@ -2,6 +2,7 @@ const promisify = require('util').promisify const cp = require('child_process') const path = require('path') +const os = require('os') // const nexe = require('nexe') const exec = promisify(cp.exec) @@ -23,37 +24,40 @@ const packageJson = require(path.join(basePath, '/package.json')) // } ;(async () => { - log(`Collecting dependencies for ${packageJson.name}...`) - // List all Lerna packages: - const list = await exec('yarn lerna list -a --json') - const str = list.stdout - .replace(/^yarn run .*$/gm, '') - .replace(/^\$.*$/gm, '') - .replace(/^Done in.*$/gm, '') + // Collecting dependencies + { + log(`Collecting dependencies for ${packageJson.name}...`) + // List all Lerna packages: + const list = await exec('yarn lerna list -a --json') + const str = list.stdout + .replace(/^yarn run .*$/gm, '') + .replace(/^\$.*$/gm, '') + .replace(/^Done in.*$/gm, '') - const packages = JSON.parse(str) + const packages = JSON.parse(str) - await mkdirp(path.join(basePath, 'node_modules')) + await mkdirp(path.join(basePath, 'node_modules')) - // Copy the packages into node_modules: - const copiedFolders = [] - let ps = [] - for (const package0 of packages) { - if (package0.name.match(/boilerplate/)) continue - if (package0.name.match(packageJson.name)) continue + // Copy the packages into node_modules: - const target = path.resolve(path.join(basePath, 'tmp_packages_for_build', package0.name)) - log(` Copying: ${package0.name} to ${target}`) + const copiedFolders = [] + let ps = [] + for (const package0 of packages) { + if (package0.name.match(/boilerplate/)) continue + if (package0.name.match(packageJson.name)) continue - // log(` ${package0.location} -> ${target}`) - ps.push(fseCopy(package0.location, target)) + const target = path.resolve(path.join(basePath, 'tmp_packages_for_build', package0.name)) + log(` Copying: ${package0.name} to ${target}`) - copiedFolders.push(target) - } + // log(` ${package0.location} -> ${target}`) + ps.push(fseCopy(package0.location, target)) - await Promise.all(ps) - ps = [] + copiedFolders.push(target) + } + await Promise.all(ps) + ps = [] + } log(`...done!`) })().catch(log) From 3f1fd7da092dee2d217f2e8c879a74c49e85441e Mon Sep 17 00:00:00 2001 From: Johan Nyman Date: Wed, 11 Oct 2023 15:04:43 +0200 Subject: [PATCH 11/17] fix: hack to make pkg include @parcel/watcher native dependencies --- scripts/cleanup-after-build32.mjs | 5 ++++- scripts/prepare-for-build32.js | 21 +++++++++++++++++++++ scripts/reset.js | 2 +- 3 files changed, 26 insertions(+), 2 deletions(-) diff --git a/scripts/cleanup-after-build32.mjs b/scripts/cleanup-after-build32.mjs index 17102f5e..a2c3fadc 100644 --- a/scripts/cleanup-after-build32.mjs +++ b/scripts/cleanup-after-build32.mjs @@ -7,7 +7,7 @@ import { promisify } from 'util' const glob = promisify(glob0) -const basePath = process.cwd() +const basePath = '.' console.log(`Cleaning up...`) @@ -21,7 +21,10 @@ console.log(`Remove unused files...`) const copiedFiles = [ ...(await glob(`${basePath}/apps/*/app/node_modules/@*/app/*`)), ...(await glob(`${basePath}/apps/*/app/node_modules/@*/generic/*`)), + ...(await glob(`${basePath}/node_modules/@parcel/watcher/build/**/*`)), ] + +console.log('copiedFiles', copiedFiles) for (const file of copiedFiles) { console.log(`Removing file: "${file}"`) ps.push(fse.rm(file, { recursive: true })) diff --git a/scripts/prepare-for-build32.js b/scripts/prepare-for-build32.js index 5d5feca1..0f030a1c 100644 --- a/scripts/prepare-for-build32.js +++ b/scripts/prepare-for-build32.js @@ -58,6 +58,27 @@ const packageJson = require(path.join(basePath, '/package.json')) await Promise.all(ps) ps = [] } + + // Hack to make pkg include the native dependency @parcel/watcher: + { + log(`Hacking @parcel/watcher...`) + + /* + This hack exploits the line @parcel/watcher/index.js:21 : + binding = require('./build/Release/watcher.node'); + By copying the native module into that location, pkg will include it in the build. + */ + const arch = os.arch() + const platform = os.platform() + const prebuildType = process.argv[2] || `${platform}-${arch}` + + const source = path.join(basePath, `node_modules/@parcel/watcher-${prebuildType}`) // @parcel/watcher-win32-x64 + const target = path.join(basePath, 'node_modules/@parcel/watcher/build/Release') + + log(` Copying: ${source} to ${target}`) + await fse.copy(source, target) + } + log(`...done!`) })().catch(log) diff --git a/scripts/reset.js b/scripts/reset.js index 7c0a4cc6..5ff0d0df 100644 --- a/scripts/reset.js +++ b/scripts/reset.js @@ -7,7 +7,7 @@ const rimraf = promisify(require('rimraf')) Removing all /node_modules and /dist folders */ -const basePath = process.cwd() +const basePath = '.' ;(async () => { log('Gathering files to remove...') From 72f371c84aec555dd72de2723043d888e3be00b2 Mon Sep 17 00:00:00 2001 From: Johan Nyman Date: Fri, 6 Oct 2023 07:23:12 +0200 Subject: [PATCH 12/17] chore: doc --- README.md | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/README.md b/README.md index 689440a8..234455f1 100644 --- a/README.md +++ b/README.md @@ -88,7 +88,7 @@ Other useful commands: yarn start:single-app # Start the single-app in local-only mode, using packages from expectedPackages.json -yarn start:single-app -- -- --watchFiles=true --noCore=true +yarn start:single-app -- -- --watchFiles=true --noCore=true --logLevel=debug From 07443a774b71112020ca0bc31e8f9bf3a7d41c94 Mon Sep 17 00:00:00 2001 From: Johan Nyman Date: Thu, 12 Oct 2023 08:27:08 +0200 Subject: [PATCH 13/17] chore: refactor: rename --- .../src/internalManager/internalManager.ts | 8 +++--- ...tusMonitor.ts => managerStatusWatchdog.ts} | 26 +++++++++---------- 2 files changed, 17 insertions(+), 17 deletions(-) rename shared/packages/expectationManager/src/internalManager/lib/{managerStatusMonitor.ts => managerStatusWatchdog.ts} (70%) diff --git a/shared/packages/expectationManager/src/internalManager/internalManager.ts b/shared/packages/expectationManager/src/internalManager/internalManager.ts index f6ed20b9..6f78d911 100644 --- a/shared/packages/expectationManager/src/internalManager/internalManager.ts +++ b/shared/packages/expectationManager/src/internalManager/internalManager.ts @@ -13,7 +13,7 @@ import { WorkerAgentAPI } from '../workerAgentApi' import { getDefaultConstants } from '../lib/constants' import { ExpectationTracker } from '../expectationTracker/expectationTracker' import { TrackedWorkerAgents } from './lib/trackedWorkerAgents' -import { ManagerStatusMonitor } from './lib/managerStatusMonitor' +import { ManagerStatusWatchdog } from './lib/managerStatusWatchdog' import { ExpectationManagerCallbacks, ExpectationManagerOptions, @@ -38,7 +38,7 @@ export class InternalManager { public statuses: ManagerStatusReporter private enableChaosMonkey = false - private managerMonitor: ManagerStatusMonitor + private managerWatchdog: ManagerStatusWatchdog public statusReport: StatusReportCache @@ -74,7 +74,7 @@ export class InternalManager { this.tracker.on('error', (err) => this.logger.error(`ExpectationTracker error" ${stringifyError(err)}`)) this.workerAgents = new TrackedWorkerAgents(this.logger, this.tracker) this.statuses = new ManagerStatusReporter(this.callbacks) - this.managerMonitor = new ManagerStatusMonitor(this.logger, this.tracker, this.statuses) + this.managerWatchdog = new ManagerStatusWatchdog(this.logger, this.tracker, this.statuses) this.statusReport = new StatusReportCache(this) this.enableChaosMonkey = options?.chaosMonkey ?? false @@ -102,7 +102,7 @@ export class InternalManager { this.tracker.terminate() this.expectationManagerServer.terminate() this.workforceConnection.terminate() - this.managerMonitor.terminate() + this.managerWatchdog.terminate() } /** USED IN TESTS ONLY. Quickly reset the tracked work of the expectationManager. */ resetWork(): void { diff --git a/shared/packages/expectationManager/src/internalManager/lib/managerStatusMonitor.ts b/shared/packages/expectationManager/src/internalManager/lib/managerStatusWatchdog.ts similarity index 70% rename from shared/packages/expectationManager/src/internalManager/lib/managerStatusMonitor.ts rename to shared/packages/expectationManager/src/internalManager/lib/managerStatusWatchdog.ts index 647b7a05..5e80f345 100644 --- a/shared/packages/expectationManager/src/internalManager/lib/managerStatusMonitor.ts +++ b/shared/packages/expectationManager/src/internalManager/lib/managerStatusWatchdog.ts @@ -3,11 +3,11 @@ import { ExpectationTracker } from '../../expectationTracker/expectationTracker' import { ManagerStatusReporter } from './managerStatusReporter' /** Monitors the status of the ExpectationTracker and alerts if there's a problem */ -export class ManagerStatusMonitor { - private statusMonitorInterval: NodeJS.Timeout | null = null +export class ManagerStatusWatchdog { + private checkStatusInterval: NodeJS.Timeout | null = null /** Timestamp, used to determine how long the work-queue has been stuck */ - private monitorStatusWaiting: number | null = null + private stuckTimestamp: number | null = null private logger: LoggerInstance constructor( @@ -17,32 +17,32 @@ export class ManagerStatusMonitor { ) { this.logger = logger.category('StatusMonitor') - this.statusMonitorInterval = setInterval(() => { - this._monitorStatus() + this.checkStatusInterval = setInterval(() => { + this._checkStatus() }, 60 * 1000) } public terminate(): void { - if (this.statusMonitorInterval) { - clearInterval(this.statusMonitorInterval) - this.statusMonitorInterval = null + if (this.checkStatusInterval) { + clearInterval(this.checkStatusInterval) + this.checkStatusInterval = null } } - private _monitorStatus() { + private _checkStatus() { // If the work-queue is long (>10 items) and nothing has progressed for the past 10 minutes. const waitingExpectationCount = this.tracker.scaler.getWaitingExpectationCount() if (waitingExpectationCount > 10) { - if (!this.monitorStatusWaiting) { - this.monitorStatusWaiting = Date.now() + if (!this.stuckTimestamp) { + this.stuckTimestamp = Date.now() } } else { - this.monitorStatusWaiting = null + this.stuckTimestamp = null } - const stuckDuration: number = this.monitorStatusWaiting ? Date.now() - this.monitorStatusWaiting : 0 + const stuckDuration: number = this.stuckTimestamp ? Date.now() - this.stuckTimestamp : 0 if (stuckDuration > 10 * 60 * 1000) { this.logger.error(`_monitorStatus: Work Queue is Stuck for ${stuckDuration / 1000 / 60} minutes`) this.managerStatuses.update('work-queue-stuck', { From e31d5a7f11775f41929dbb77f13f8c8990fe9a00 Mon Sep 17 00:00:00 2001 From: Johan Nyman Date: Thu, 12 Oct 2023 08:27:35 +0200 Subject: [PATCH 14/17] chore: fix test --- tests/internal-tests/src/__tests__/lib/setupEnv.ts | 2 ++ 1 file changed, 2 insertions(+) diff --git a/tests/internal-tests/src/__tests__/lib/setupEnv.ts b/tests/internal-tests/src/__tests__/lib/setupEnv.ts index a476cbe9..ef897932 100644 --- a/tests/internal-tests/src/__tests__/lib/setupEnv.ts +++ b/tests/internal-tests/src/__tests__/lib/setupEnv.ts @@ -36,6 +36,7 @@ const defaultTestConfig: SingleAppConfig = { logPath: '', unsafeSSL: false, certificates: [], + logLevel: LogLevel.INFO, }, workforce: { port: null, @@ -192,6 +193,7 @@ export async function prepareTestEnviromnent(debugLogging: boolean): Promise Date: Thu, 12 Oct 2023 08:29:54 +0200 Subject: [PATCH 15/17] chore: remove noop code --- .../packages/generic/src/packageManager.ts | 15 +-------------- 1 file changed, 1 insertion(+), 14 deletions(-) diff --git a/apps/package-manager/packages/generic/src/packageManager.ts b/apps/package-manager/packages/generic/src/packageManager.ts index f4667778..c49fd11b 100644 --- a/apps/package-manager/packages/generic/src/packageManager.ts +++ b/apps/package-manager/packages/generic/src/packageManager.ts @@ -42,7 +42,6 @@ export class PackageManagerHandler { public expectationManager: ExpectationManager - private expectedPackageCache: { [id: string]: ExpectedPackageWrap } = {} public packageContainersCache: PackageContainers = {} private externalData: { packageContainers: PackageContainers; expectedPackages: ExpectedPackageWrap[] } = { @@ -295,19 +294,7 @@ export class PackageManagerHandler { } // Step 0: Save local cache: - this.expectedPackageCache = {} this.packageContainersCache = packageContainers - for (const exp of expectedPackages) { - // Note: There might be duplicates in expectedPackages - - const existing = this.expectedPackageCache[exp.expectedPackage._id] - if ( - !existing || - existing.priority > exp.priority // If the existing priority is lower (ie higher), replace it - ) { - this.expectedPackageCache[exp.expectedPackage._id] = exp - } - } this.logger.debug( `Has ${expectedPackages.length} expectedPackages (${expectedPackageSources @@ -401,7 +388,7 @@ export class PackageManagerHandler { return this.expectationManager.debugKillApp(appId) } - /** Ensures that the packageContainerExpectations containes the mandatory expectations */ + /** Ensures that the packageContainerExpectations contains the mandatory expectations */ private ensureMandatoryPackageContainerExpectations(packageContainerExpectations: { [id: string]: PackageContainerExpectation }): void { From 7d546d93c000cbc2f3db41c5bb79c8123934dfce Mon Sep 17 00:00:00 2001 From: Johan Nyman Date: Thu, 12 Oct 2023 08:42:05 +0200 Subject: [PATCH 16/17] chore: logging --- apps/package-manager/packages/generic/src/packageManager.ts | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/apps/package-manager/packages/generic/src/packageManager.ts b/apps/package-manager/packages/generic/src/packageManager.ts index c49fd11b..247b631c 100644 --- a/apps/package-manager/packages/generic/src/packageManager.ts +++ b/apps/package-manager/packages/generic/src/packageManager.ts @@ -189,6 +189,8 @@ export class PackageManagerHandler { this._triggerUpdatedExpectedPackagesTimeout = setTimeout(() => { this._triggerUpdatedExpectedPackagesTimeout = null + const startTime = Date.now() + const packageContainers: PackageContainers = {} const expectedPackageSources: { sourceName: string @@ -273,6 +275,8 @@ export class PackageManagerHandler { } this.handleExpectedPackages(packageContainers, activePlaylist, activeRundowns, expectedPackageSources) + + this.logger.debug(`Took ${Date.now() - startTime}ms to handle updated expectedPackages`) }, 300) } From 7dd68f6468813eae6f1377b5e5aba78090a82885 Mon Sep 17 00:00:00 2001 From: Johan Nyman Date: Thu, 12 Oct 2023 08:43:13 +0200 Subject: [PATCH 17/17] chore: refactor: store expectedPackages from monitors per-container first --- .../packages/generic/src/packageManager.ts | 23 +++++++++++-------- 1 file changed, 14 insertions(+), 9 deletions(-) diff --git a/apps/package-manager/packages/generic/src/packageManager.ts b/apps/package-manager/packages/generic/src/packageManager.ts index 247b631c..b9eb5141 100644 --- a/apps/package-manager/packages/generic/src/packageManager.ts +++ b/apps/package-manager/packages/generic/src/packageManager.ts @@ -50,7 +50,9 @@ export class PackageManagerHandler { } private _triggerUpdatedExpectedPackagesTimeout: NodeJS.Timeout | null = null public monitoredPackages: { - [monitorId: string]: ResultingExpectedPackage[] + [containerId: string]: { + [monitorId: string]: ResultingExpectedPackage[] + } } = {} settings: PackageManagerSettings = { delayRemoval: 0, @@ -266,11 +268,13 @@ export class PackageManagerHandler { // Add from Monitors: { - for (const [monitorId, monitorExpectedPackages] of Object.entries(this.monitoredPackages)) { - expectedPackageSources.push({ - sourceName: `monitor_${monitorId}`, - expectedPackages: monitorExpectedPackages, - }) + for (const monitors of Object.values(this.monitoredPackages)) { + for (const [monitorId, monitorExpectedPackages] of Object.entries(monitors)) { + expectedPackageSources.push({ + sourceName: `monitor_${monitorId}`, + expectedPackages: monitorExpectedPackages, + }) + } } } @@ -640,7 +644,7 @@ class ExpectationManagerCallbacksHandler implements ExpectationManagerCallbacks ) } case 'reportFromMonitorPackages': - this.reportMonitoredPackages(...message.arguments) + this.onReportMonitoredPackages(...message.arguments) break default: @@ -953,7 +957,7 @@ class ExpectationManagerCallbacksHandler implements ExpectationManagerCallbacks .catch((e) => this.logger.error(`Error in updateCoreStatus : ${stringifyError(e)}`)) } - private reportMonitoredPackages(_containerId: string, monitorId: string, expectedPackages: ExpectedPackage.Any[]) { + private onReportMonitoredPackages(containerId: string, monitorId: string, expectedPackages: ExpectedPackage.Any[]) { const expectedPackagesWraps: ExpectedPackageWrap[] = [] for (const expectedPackage of expectedPackages) { @@ -967,7 +971,8 @@ class ExpectationManagerCallbacksHandler implements ExpectationManagerCallbacks `reportMonitoredPackages: ${expectedPackages.length} packages, ${expectedPackagesWraps.length} wraps` ) - this.packageManager.monitoredPackages[monitorId] = expectedPackagesWraps + if (!this.packageManager.monitoredPackages[containerId]) this.packageManager.monitoredPackages[containerId] = {} + this.packageManager.monitoredPackages[containerId][monitorId] = expectedPackagesWraps this.packageManager.triggerUpdatedExpectedPackages() }