Merge branch 'master' into develop

# Conflicts:
#	shared/packages/worker/src/worker/accessorHandlers/genericHandle.ts
#	shared/packages/worker/src/worker/workers/windowsWorker/expectationHandlers/lib.ts
#	tests/internal-tests/src/__mocks__/fs.ts
#	tests/internal-tests/src/__tests__/issues.spec.ts
#	tests/internal-tests/src/__tests__/lib/setupEnv.ts

apps/package-manager/packages/generic/src/generateExpectations/nrk/packageContainerExpectations.ts

@@ -52,6 +52,7 @@ export function getPackageContainerExpectations(
 						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
 					},
 				},
 			}

shared/packages/api/src/logger.ts

@@ -61,7 +61,8 @@ export function setupLogger(
 	category: string,
 	categoryLabel?: string,
 	handleProcess = false,
-	initialLogLevel?: LogLevel
+	initialLogLevel?: LogLevel,
+	filterFcn?: (level: string, ...args: any[]) => boolean
 ): LoggerInstance {
 	if (!loggerContainer) throw new Error('Logging has not been set up! initializeLogger() must be called first.')
 
@@ -141,9 +142,31 @@ export function setupLogger(
 			`${category ? `${category}.` : ''}${subCategory}`,
 			subLabel && `${categoryLabel}>${subLabel}`,
 			undefined,
-			initialLogLevel
+			initialLogLevel,
+			filterFcn
 		)
 	}
+	if (filterFcn) {
+		for (const methodName of [
+			'error',
+			'warn',
+			'help',
+			'data',
+			'info',
+			'debug',
+			'prompt',
+			'http',
+			'verbose',
+			'input',
+			'silly',
+		]) {
+			const orgMethod = (loggerInstance as any)[methodName]
+			;(loggerInstance as any)[methodName] = (...args: any[]) => {
+				if (filterFcn(methodName, ...args)) orgMethod.call(loggerInstance, ...args)
+			}
+		}
+	}
+
 	allLoggers.set(category, loggerInstance)
 	return loggerInstance
 }

shared/packages/api/src/packageContainerApi.ts

@@ -29,10 +29,12 @@ export interface PackageContainerExpectation extends PackageContainer {
 			/** If set, ignore any files matching this. (Regular expression). */
 			ignore?: string
 
-			/** If set, the monitoring will be using polling */
+			/** 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 */
 			awaitWriteFinishStabilityThreshold?: number | null
+			/** If set, the monitor will warn if the monitored number of packages is greater than this */
+			warningLimit?: number
 
 			/** What layers to set on the resulting ExpectedPackage */
 			targetLayers: string[]

shared/packages/worker/src/worker/accessorHandlers/genericHandle.ts

@@ -6,6 +6,8 @@ import {
 	HelpfulEventEmitter,
 	AccessorId,
 	MonitorId,
+	promiseTimeout,
+	INNER_ACTION_TIMEOUT,
 } from '@sofie-package-manager/api'
 import { GenericWorker } from '../worker'
 import { MonitorInProgress } from '../lib/monitorInProgress'
@@ -20,7 +22,49 @@ export abstract class GenericAccessorHandle<Metadata> {
 		protected _accessor: AccessorOnPackage.Any,
 		protected _content: unknown,
 		public readonly type: string
-	) {}
+	) {
+		// Wrap all accessor methods which return promises into promiseTimeout.
+		// This is to get a finer grained logging, in case of a timeout:
+
+		/** List of all methods */
+		const methodsToWrap: Array<keyof GenericAccessorHandle<Metadata>> = [
+			'checkPackageReadAccess',
+			'tryPackageRead',
+			'checkPackageContainerWriteAccess',
+			'getPackageActualVersion',
+			'removePackage',
+			'fetchMetadata',
+			'updateMetadata',
+			'removeMetadata',
+			'getPackageReadStream',
+			'putPackageStream',
+			'getPackageReadInfo',
+			'putPackageInfo',
+			'prepareForOperation',
+			'finalizePackage',
+			'runCronJob',
+			'setupPackageContainerMonitors',
+		]
+
+		for (const methodName of methodsToWrap) {
+			const originalMethod = this[methodName] as (...args: any[]) => Promise<unknown>
+
+			;(this as any)[methodName] = async function (...args: any[]) {
+				return promiseTimeout(
+					originalMethod.call(this, ...args),
+					INNER_ACTION_TIMEOUT,
+					(duration) =>
+						`Timeout after ${duration} ms in ${methodName} for Accessor "${
+							this.accessorId
+						}". Context: ${JSON.stringify({
+							type: type,
+							accessor: this._accessor,
+							content: this._content,
+						})}`
+				)
+			}
+		}
+	}
 
 	/**
 	 * A string that can identify the package.

shared/packages/worker/src/worker/accessorHandlers/lib/FileHandler.ts

@@ -168,7 +168,7 @@ export abstract class GenericFileAccessorHandle<Metadata> extends GenericAccesso
 			}
 		)
 
-		monitorInProgress._reportStatus(StatusCode.UNKNOWN, {
+		monitorInProgress._setStatus('setup', StatusCode.UNKNOWN, {
 			user: 'Setting up file watcher...',
 			tech: `Setting up file watcher...`,
 		})
@@ -179,8 +179,8 @@ export abstract class GenericFileAccessorHandle<Metadata> extends GenericAccesso
 		}
 		if (options.usePolling) {
 			chokidarOptions.usePolling = true
-			chokidarOptions.interval = 2000
-			chokidarOptions.binaryInterval = 2000
+			chokidarOptions.interval = options.usePolling
+			chokidarOptions.binaryInterval = options.usePolling
 		}
 		if (options.awaitWriteFinishStabilityThreshold) {
 			chokidarOptions.awaitWriteFinish = {
@@ -220,20 +220,22 @@ export abstract class GenericFileAccessorHandle<Metadata> extends GenericAccesso
 					for (let [filePath, version] of seenFiles.entries()) {
 						// Update the version
 						if (!version) {
+							const fullPath = path.join(this.folderPath, filePath)
 							try {
-								const fullPath = path.join(this.folderPath, filePath)
 								const stat = await fsStat(fullPath)
 								version = this.convertStatToVersion(stat)
 								seenFiles.set(filePath, version)
+
+								monitorInProgress._unsetStatus(fullPath)
 							} catch (err) {
 								version = null
 								this.worker.logger.error(
-									`GenericFileAccessorHandle.setupPackagesMonitor: Unexpected Exception cautght: ${stringifyError(
+									`GenericFileAccessorHandle.setupPackagesMonitor: Unexpected Exception caught: ${stringifyError(
 										err
 									)}`
 								)
 
-								monitorInProgress._reportStatus(StatusCode.BAD, {
+								monitorInProgress._setStatus(fullPath, StatusCode.BAD, {
 									user: 'Error when accessing watched file',
 									tech: `Error: ${stringifyError(err)}`,
 								})
@@ -290,6 +292,16 @@ export abstract class GenericFileAccessorHandle<Metadata> extends GenericAccesso
 						arguments: [packageContainerExp.id, monitorId, packages],
 					})
 
+					if (options.warningLimit && seenFiles.size > options.warningLimit) {
+						monitorInProgress._setStatus('warningLimit', 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')
+					}
+
+					// Finally
 					triggerSendUpdateIsRunning = false
 					if (triggerSendUpdateRunAgain) triggerSendUpdate()
 				})().catch((err) => {
@@ -330,6 +342,8 @@ export abstract class GenericFileAccessorHandle<Metadata> extends GenericAccesso
 					.catch(() => {
 						// The file truly doesn't exist
 
+						monitorInProgress._unsetStatus(fullPath)
+
 						const localPath = getFilePath(fullPath)
 						if (localPath) {
 							seenFiles.delete(localPath)
@@ -343,16 +357,17 @@ export abstract class GenericFileAccessorHandle<Metadata> extends GenericAccesso
 						err
 					)}`
 				)
-				monitorInProgress._reportStatus(StatusCode.BAD, {
+				monitorInProgress._setStatus('watcher', StatusCode.BAD, {
 					user: 'Error in file watcher',
 					tech: `chokidar error: ${stringifyError(err)}`,
 				})
 			})
 			.on('ready', () => {
-				monitorInProgress._reportStatus(StatusCode.GOOD, {
+				monitorInProgress._setStatus('setup', StatusCode.GOOD, {
 					user: 'File watcher is set up',
 					tech: `File watcher is set up`,
 				})
+				triggerSendUpdate()
 			})
 
 		return monitorInProgress

shared/packages/worker/src/worker/lib/monitorInProgress.ts

@@ -12,29 +12,61 @@ export declare interface IMonitorInProgress {
 	stop: () => Promise<void>
 }
 export class MonitorInProgress extends HelpfulEventEmitter implements IMonitorInProgress {
+	private statuses: Map<string, { status: StatusCode; reason: Reason }> = new Map()
+	private lastReportedStatus: { status: StatusCode; reason: Reason } | undefined = undefined
 	constructor(public properties: MonitorProperties, private _onStop: () => Promise<void>) {
 		super()
 	}
 	async stop(): Promise<void> {
 		return this._onStop()
 	}
 
-	// eslint-disable-next-line @typescript-eslint/explicit-module-boundary-types
-	_reportStatus(status: StatusCode, reason: Reason): void {
-		this.emit('status', status, reason)
+	_setStatus(internalId: string, status: StatusCode, reason: Reason): void {
+		this.statuses.set(internalId, { status, reason })
+
+		this._reportStatus()
+	}
+	_unsetStatus(internalId: string): void {
+		this.statuses.delete(internalId)
+
+		this._reportStatus()
+	}
+	private _reportStatus(): void {
+		// Emit the worst status:
+		let worstStatus: { status: StatusCode; reason: Reason } | undefined = undefined
+		for (const status of this.statuses.values()) {
+			if (!worstStatus || worstStatus.status < status.status) {
+				worstStatus = status
+			}
+		}
+
+		if (!worstStatus)
+			worstStatus = {
+				status: StatusCode.UNKNOWN,
+				reason: {
+					user: 'Not yet initialized',
+					tech: 'Not yet initialized',
+				},
+			}
+
+		if (this.lastReportedStatus?.status !== worstStatus.status) {
+			this.lastReportedStatus = worstStatus
+
+			this.emit('status', worstStatus.status, worstStatus.reason)
+		}
 	}
 	/** Convenience function which calls the function that sets up the monitor */
 	setup(fcn: () => Promise<void> | void): MonitorInProgress {
 		setTimeout(() => {
 			try {
 				Promise.resolve(fcn()).catch((err) => {
-					this._reportStatus(StatusCode.BAD, {
+					this._setStatus('setup', StatusCode.BAD, {
 						user: 'Internal error when setting up monitor',
 						tech: `Error: ${stringifyError(err)}`,
 					})
 				})
 			} catch (err) {
-				this._reportStatus(StatusCode.BAD, {
+				this._setStatus('setup', StatusCode.BAD, {
 					user: 'Internal error when setting up monitor',
 					tech: `Error: ${stringifyError(err)}`,
 				})