chore: add test for slow file operations

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
 }

tests/internal-tests/src/__mocks__/fs.ts

@@ -311,23 +311,34 @@ export function stat(path: string, callback: (error: any, result?: any) => void)
 fs.stat = stat
 
 export function access(path: string, mode: number | undefined, callback: (error: any, result?: any) => void): void {
+	if (mode === undefined)
+		throw new Error(
+			`Mock fs.access: Don't use mode===undefined in Package Manager (or perhaps the mock fs constants aren't setup correctly?)`
+		)
 	path = fixPath(path)
-	if (DEBUG_LOG) console.log('fs.access', path, mode)
+	const mockFile = getMock(path)
+	// if (DEBUG_LOG) console.log('fs.access', path, mode)
 	fsMockEmitter.emit('access', path, mode)
-	try {
-		const mockFile = getMock(path)
-		if (mode === fsConstants.R_OK && !mockFile.accessRead) {
-			return callback({ someError: 'Mock: read access denied ' })
-		} else if (mode === fsConstants.W_OK && !mockFile.accessWrite) {
-			return callback({ someError: 'Mock: write access denied ' })
-		} else {
-			return callback(undefined, null)
+	setTimeout(() => {
+		try {
+			if (mode === constants.R_OK && !mockFile.accessRead) {
+				return callback({ someError: 'Mock: read access denied ' })
+			} else if (mode === constants.W_OK && !mockFile.accessWrite) {
+				return callback({ someError: 'Mock: write access denied ' })
+			} else {
+				return callback(undefined, null)
+			}
+		} catch (err) {
+			callback(err)
 		}
-	} catch (err) {
-		callback(err)
-	}
+	}, FS_ACCESS_DELAY)
 }
 fs.access = access
+let FS_ACCESS_DELAY = 0
+export function __mockSetAccessDelay(delay: number): void {
+	FS_ACCESS_DELAY = delay
+}
+fs.__mockSetAccessDelay = __mockSetAccessDelay
 
 export function unlink(path: string, callback: (error: any, result?: any) => void): void {
 	path = fixPath(path)

tests/internal-tests/src/__tests__/issues.spec.ts

@@ -55,6 +55,10 @@ describe('Handle unhappy paths', () => {
 	beforeEach(() => {
 		fs.__mockReset()
 		env.reset()
+		fs.__mockSetAccessDelay(0) // Reset any access delay
+	})
+	afterEach(() => {
+		fs.__mockSetAccessDelay(0) // Reset any access delay
 	})
 
 	test('Wait for non-existing local file', async () => {
@@ -102,6 +106,39 @@ describe('Handle unhappy paths', () => {
 			size: 1234,
 		})
 	})
+	test('Slow responding file operations', async () => {
+		fs.__mockSetDirectory('/sources/source0/')
+		fs.__mockSetDirectory('/targets/target0')
+		fs.__mockSetFile('/sources/source0/file0Source.mp4', 1234)
+		fs.__mockSetAccessDelay(INNER_ACTION_TIMEOUT + 100) // Simulate a slow file operation
+
+		env.setLogFilterFunction((level, ...args) => {
+			const str = args.join(',')
+			// Suppress some logged warnings:
+			if (level === 'warn' && str.includes('checkPackageContainerWriteAccess')) return false
+			return true
+		})
+
+		addCopyFileExpectation(
+			env,
+			'copy0',
+			[getLocalSource('source0', 'file0Source.mp4')],
+			[getLocalTarget('target0', 'file0Target.mp4')]
+		)
+
+		await waitUntil(() => {
+			// Expect the Expectation to be waiting:
+			expect(env.expectationStatuses['copy0']).toMatchObject({
+				actualVersionHash: null,
+				statusInfo: {
+					// status: expect.stringMatching(/fulfilled/),
+					statusReason: {
+						tech: expect.stringMatching(/timeout.*checkPackageContainerWriteAccess.*Accessor.*/i),
+					},
+				},
+			})
+		}, INNER_ACTION_TIMEOUT + 100)
+	})
 	test.skip('Wait for non-existing network-shared, file', async () => {
 		// To be written
 

tests/internal-tests/src/__tests__/lib/setupEnv.ts

@@ -98,10 +98,11 @@ export async function setupExpectationManager(
 	debugLogging: boolean,
 	workerCount: number = 1,
 	callbacks: ExpectationManagerCallbacks,
-	options?: ExpectationManagerOptions
+	options: ExpectationManagerOptions,
+	logFilterFunction: (level: string, ...args: any[]) => boolean
 ) {
 	const logLevel = debugLogging ? LogLevel.DEBUG : LogLevel.WARN
-	const logger = setupLogger(config, '', undefined, undefined, logLevel)
+	const logger = setupLogger(config, '', undefined, undefined, logLevel, logFilterFunction)
 
 	const expectationManager = new ExpectationManager(
 		logger,
@@ -195,6 +196,14 @@ export async function prepareTestEnviromnent(debugLogging: boolean): Promise<Tes
 	}
 	initializeLogger(config)
 
+	let logFilterFunctionInner: (level: string, ...args: any[]) => boolean = () => {
+		return true // Default behavior: no filtering
+	}
+	let logFilterFunction = (level: string, ...args: any[]) => logFilterFunctionInner(level, ...args)
+	const setLogFilterFunction = (filter: (level: string, ...args: any[]) => boolean) => {
+		logFilterFunctionInner = filter
+	}
+
 	const em = await setupExpectationManager(
 		config,
 		debugLogging,
@@ -275,7 +284,8 @@ export async function prepareTestEnviromnent(debugLogging: boolean): Promise<Tes
 				WORK_TIMEOUT_TIME: WORK_TIMEOUT_TIME - 300,
 				ERROR_WAIT_TIME: ERROR_WAIT_TIME - 300,
 			},
-		}
+		},
+		logFilterFunction
 	)
 
 	return {
@@ -293,6 +303,7 @@ export async function prepareTestEnviromnent(debugLogging: boolean): Promise<Tes
 			if (debugLogging) {
 				console.log('RESET ENVIRONMENT')
 			}
+			setLogFilterFunction(() => true)
 			em.expectationManager.resetWork()
 			Object.keys(expectationStatuses).forEach((id) => delete expectationStatuses[id])
 			Object.keys(containerStatuses).forEach((id) => delete containerStatuses[id])
@@ -305,6 +316,7 @@ export async function prepareTestEnviromnent(debugLogging: boolean): Promise<Tes
 		},
 		addWorker: em.addWorker,
 		removeWorker: em.removeWorker,
+		setLogFilterFunction: setLogFilterFunction,
 	}
 }
 export interface TestEnviromnent {
@@ -322,6 +334,7 @@ export interface TestEnviromnent {
 	terminate: () => void
 	addWorker: () => Promise<string>
 	removeWorker: (id: string) => Promise<void>
+	setLogFilterFunction: (filter: (level: string, ...args: any[]) => boolean) => void
 }
 
 export interface ExpectationStatuses {