Merge pull request #207 from nrkno/fix/pm-stuck-on-error

fix: state machine improvements and error handling (SOFIE-3751)

Author: nytamin

apps/appcontainer-node/packages/generic/src/appContainer.ts

@@ -40,6 +40,7 @@ import {
 
 import { WorkforceAPI } from './workforceApi'
 import { WorkerAgentAPI } from './workerAgentApi'
+import { ExpectedPackageStatusAPI } from '@sofie-automation/shared-lib/dist/package-manager/package'
 
 /** Mimimum time between app restarts */
 const RESTART_COOLDOWN = 60 * 1000 // ms
@@ -413,6 +414,10 @@ export class AppContainer {
 			this.logger.debug(`Available apps: ${Array.from(this.availableApps.keys()).join(', ')}`)
 		}
 
+		let lastNotSupportReason: ExpectedPackageStatusAPI.Reason = {
+			user: 'No apps available',
+			tech: 'No apps available',
+		}
 		for (const [appType, availableApp] of this.availableApps.entries()) {
 			const runningApp = await this.getRunningOrSpawnScalingApp(appType)
 
@@ -424,6 +429,11 @@ export class AppContainer {
 						appType: appType,
 						cost: availableApp.cost,
 					}
+				} else {
+					lastNotSupportReason = result.reason
+					this.logger.silly(
+						`App "${appType}": Does not support the expectation, reason: "${result.reason.tech}", cost: "${availableApp.cost}"`
+					)
 				}
 			} else {
 				this.logger.warn(`appType "${appType}" not available`)
@@ -432,8 +442,8 @@ export class AppContainer {
 		return {
 			success: false,
 			reason: {
-				user: `No worker supports this expectation`,
-				tech: `No worker supports this expectation`,
+				user: `No worker supports this expectation (reason: ${lastNotSupportReason?.user})`,
+				tech: `No worker supports this expectation (one reason: ${lastNotSupportReason?.tech})`,
 			},
 		}
 	}

scripts/prepare-for-tests.mjs

@@ -13,6 +13,8 @@ import path from 'path'
 import cp from 'child_process'
 import fetch from 'node-fetch'
 
+console.log(`Preparing for tests...`)
+
 const targetVersions = JSON.parse(await fs.readFile('./tests/ffmpegReleases.json'))
 
 const toPosix = (str) => str.split(path.sep).join(path.posix.sep)
@@ -33,12 +35,14 @@ async function pathExists(path) {
 
 const platformInfo = `${process.platform}-${process.arch}`
 const platformVersions = targetVersions[platformInfo]
+let didDoAnything = false
 
 if (platformVersions) {
 	for (const version of platformVersions) {
 		const versionPath = path.join(ffmpegRootDir, version.id)
 		const dirStat = await pathExists(versionPath)
 		if (!dirStat) {
+			didDoAnything = true
 			console.log(`Fetching ${version.url}`)
 			// Download it
 
@@ -81,3 +85,9 @@ if (platformVersions) {
 } else {
 	throw new Error(`No FFMpeg binaries have been defined for "${platformInfo}" yet`)
 }
+
+if (!didDoAnything) {
+	console.log(`Nothing to prepare!`)
+} else {
+	console.log(`Preparations done!`)
+}

shared/packages/api/src/worker.ts

@@ -31,7 +31,6 @@ export type ReturnTypeIsExpectationReadyToStartWorkingOn =
 			 */
 			sourceExists?: boolean
 			isPlaceholder?: boolean
-			isWaitingForAnother?: boolean
 			reason: Reason
 	  }
 export type ReturnTypeIsExpectationFulfilled =

shared/packages/expectationManager/src/evaluationRunner/evaluateExpectationStates/fulfilled.ts

@@ -19,6 +19,7 @@ export async function evaluateExpectationStateFulfilled({
 	assertState(trackedExp, ExpectedPackageStatusAPI.WorkStatusState.FULFILLED)
 	// TODO: Some monitor that is able to invalidate if it isn't fulfilled anymore?
 
+	// We don't want to check too often if it's still fulfilled:
 	if (timeSinceLastEvaluation > tracker.getFulfilledWaitTime()) {
 		await manager.workerAgents.assignWorkerToSession(trackedExp)
 		if (trackedExp.session.assignedWorker) {

shared/packages/expectationManager/src/evaluationRunner/evaluateExpectationStates/waiting.ts

@@ -23,63 +23,70 @@ export async function evaluateExpectationStateWaiting({
 
 	if (trackedExp.session.assignedWorker) {
 		try {
+			// First check if the Expectation depends on the fulfilled-status of another Expectation:
+			const isWaitingForOther = tracker.trackedExpectationAPI.isExpectationWaitingForOther(trackedExp)
+
+			if (isWaitingForOther) {
+				// Not ready to start because it's waiting for another expectation to be fulfilled first
+				// Stay here in WAITING state:
+				tracker.trackedExpectationAPI.updateTrackedExpectationStatus(trackedExp, {
+					reason: {
+						user: `Waiting for "${isWaitingForOther.exp.statusReport.label}"`,
+						tech: `Waiting for "${isWaitingForOther.exp.statusReport.label}"`,
+					},
+				})
+
+				return
+			}
+
 			// First, check if it is already fulfilled:
 			const fulfilled = await trackedExp.session.assignedWorker.worker.isExpectationFulfilled(
 				trackedExp.exp,
 				false
 			)
 			if (fulfilled.fulfilled) {
 				// The expectation is already fulfilled:
+
 				tracker.trackedExpectationAPI.updateTrackedExpectationStatus(trackedExp, {
 					state: ExpectedPackageStatusAPI.WorkStatusState.FULFILLED,
 				})
 				if (tracker.trackedExpectationAPI.onExpectationFulfilled(trackedExp)) {
 					// Something was triggered, run again ASAP:
 					trackedExp.session.triggerOtherExpectationsAgain = true
 				}
-			} else {
-				const readyToStart = await tracker.trackedExpectationAPI.isExpectationReadyToStartWorkingOn(
-					trackedExp.session.assignedWorker.worker,
-					trackedExp
-				)
+				return
+			}
+			const readyToStart = await tracker.trackedExpectationAPI.isExpectationReadyToStartWorkingOn(
+				trackedExp.session.assignedWorker.worker,
+				trackedExp
+			)
 
-				const newStatus: Partial<TrackedExpectation['status']> = {}
-				{
-					const sourceExists = readyToStart.ready || readyToStart.sourceExists
-					if (sourceExists !== undefined) newStatus.sourceExists = sourceExists
-				}
-				{
-					const isPlaceholder = readyToStart.ready ? false : readyToStart.isPlaceholder
-					if (isPlaceholder !== undefined) newStatus.sourceIsPlaceholder = isPlaceholder
-				}
+			const newStatus: Partial<TrackedExpectation['status']> = {}
+			{
+				const sourceExists = readyToStart.ready || readyToStart.sourceExists
+				if (sourceExists !== undefined) newStatus.sourceExists = sourceExists
+			}
+			{
+				const isPlaceholder = readyToStart.ready ? false : readyToStart.isPlaceholder
+				if (isPlaceholder !== undefined) newStatus.sourceIsPlaceholder = isPlaceholder
+			}
 
-				if (readyToStart.ready) {
-					tracker.trackedExpectationAPI.updateTrackedExpectationStatus(trackedExp, {
-						state: ExpectedPackageStatusAPI.WorkStatusState.READY,
-						reason: {
-							user: 'About to start working..',
-							tech: `About to start, was not fulfilled: ${fulfilled.reason.tech}`,
-						},
-						status: newStatus,
-					})
-				} else {
-					// Not ready to start
-					if (readyToStart.isWaitingForAnother) {
-						// Not ready to start because it's waiting for another expectation to be fulfilled first
-						// Stay here in WAITING state:
-						tracker.trackedExpectationAPI.updateTrackedExpectationStatus(trackedExp, {
-							reason: readyToStart.reason,
-							status: newStatus,
-						})
-					} else {
-						// Not ready to start because of some other reason (e.g. the source doesn't exist)
-						// Stay here in WAITING state:
-						tracker.trackedExpectationAPI.updateTrackedExpectationStatus(trackedExp, {
-							reason: readyToStart.reason,
-							status: newStatus,
-						})
-					}
-				}
+			if (readyToStart.ready) {
+				tracker.trackedExpectationAPI.updateTrackedExpectationStatus(trackedExp, {
+					state: ExpectedPackageStatusAPI.WorkStatusState.READY,
+					reason: {
+						user: 'About to start working..',
+						tech: `About to start, was not fulfilled: ${fulfilled.reason.tech}`,
+					},
+					status: newStatus,
+				})
+			} else {
+				// Not ready to start because of some reason (e.g. the source doesn't exist)
+				// Stay here in WAITING state:
+				tracker.trackedExpectationAPI.updateTrackedExpectationStatus(trackedExp, {
+					reason: readyToStart.reason,
+					status: newStatus,
+				})
 			}
 		} catch (error) {
 			// There was an error, clearly it's not ready to start

shared/packages/expectationManager/src/expectationTracker/lib/trackedExpectationAPI.ts

@@ -110,20 +110,6 @@ export class TrackedExpectationAPI {
 		workerAgent: WorkerAgentAPI,
 		trackedExp: TrackedExpectation
 	): Promise<ReturnTypeIsExpectationReadyToStartWorkingOn> {
-		// First check if the Expectation depends on the fulfilled-status of another Expectation:
-		const waitingFor = this.isExpectationWaitingForOther(trackedExp)
-
-		if (waitingFor) {
-			return {
-				ready: false,
-				reason: {
-					user: `Waiting for "${waitingFor.exp.statusReport.label}"`,
-					tech: `Waiting for "${waitingFor.exp.statusReport.label}"`,
-				},
-				isWaitingForAnother: true,
-			}
-		}
-
 		return workerAgent.isExpectationReadyToStartWorkingOn(trackedExp.exp)
 	}
 	/** Checks if the expectation is waiting for another expectation, and returns the awaited Expectation, otherwise null */

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

@@ -155,15 +155,31 @@ export class QuantelAccessorHandle<Metadata> extends GenericAccessorHandle<Metad
 
 		const clipSummary = await this.searchForLatestClip(quantel)
 
+		const content = this.getContent()
+
 		if (!clipSummary) {
-			const content = this.getContent()
 			return {
 				success: false,
 				packageExists: false,
 				reason: { user: `Clip not found`, tech: `Clip "${content.guid || content.title}" not found` },
 			}
 		}
 
+		// Verify that the clip does exist:
+		const clipData = await quantel.getClip(clipSummary.ClipID)
+		if (!clipData) {
+			return {
+				success: false,
+				packageExists: false,
+				reason: {
+					user: `Clip not found`,
+					tech: `Clip id ${clipSummary.ClipID} not found in this zone (although "${
+						content.guid || content.title
+					}" was found)`,
+				},
+			}
+		}
+
 		if (!parseInt(clipSummary.Frames, 10)) {
 			return {
 				success: false,
@@ -279,6 +295,7 @@ export class QuantelAccessorHandle<Metadata> extends GenericAccessorHandle<Metad
 				// Verify that the clip is of the right version:
 				const clipData = await quantel.getClip(readInfo.clipId)
 				if (!clipData) throw new Error(`Clip id ${readInfo.clipId} not found`)
+
 				if (clipData.Created !== readInfo.version.created)
 					throw new Error(
 						`Clip id ${readInfo.clipId} property "Created" doesn't match (${clipData.Created} vs ${readInfo.version.created})`