fix: improved tracing of resolver, for better troubleshooting of reso…

…lving issues in production

src/__tests__/basic.spec.ts

@@ -1,6 +1,7 @@
 /* eslint-disable jest/no-standalone-expect */
 
 import { EventType, ResolvedTimelineObject, TimelineObjectInstance, getResolvedState, resolveTimeline } from '..'
+
 import { baseInstances } from '../resolver/lib/instance'
 import { describeVariants } from './testlib'
 
@@ -1695,6 +1696,7 @@ describeVariants(
 				resolvedKeyframeCount: 0,
 				resolvingObjectCount: 0,
 				resolvingCount: 0,
+				resolveTrace: [],
 			})
 		})
 		test('Class state overrides', () => {

src/__tests__/index.spec.ts

@@ -8,6 +8,7 @@ import {
 	getResolvedState,
 	applyKeyframeContent,
 } from '../index'
+import { ResolveError } from '../resolver/lib/Error'
 import { baseInstances } from '../resolver/lib/instance'
 import { clone } from '../resolver/lib/lib'
 
@@ -879,4 +880,68 @@ describe('index', () => {
 
 		expect(state1.layers['layerA']).toEqual(state1NoCache.layers['layerA'])
 	})
+	test('traceResolving', () => {
+		const timeline: TimelineObject<any>[] = [
+			{
+				id: 'A',
+				layer: 'L',
+				enable: { start: 100, duration: 1 },
+				content: {},
+				priority: 0,
+			},
+		]
+
+		const resolved = resolveTimeline(timeline, {
+			cache: {},
+			time: 0,
+			traceResolving: true,
+		})
+
+		// Note: The exact content of the trace isn't that important, since it's for troubleshooting purposes
+		expect(resolved.statistics.resolveTrace).toMatchObject([
+			'init',
+			'resolveTimeline start',
+			'timeline object count 1',
+			'objects: 1',
+			'using cache',
+			'cache: init',
+			'cache: canUseIncomingCache: false',
+			'cache: cached objects: []',
+			'cache: object "A" is new',
+			'Resolver: Step 1a',
+			'Resolver: Resolve object "A"',
+			'Resolver: object "A" resolved.instances: [{"id":"@A_0","start":100,"end":101,"references":[]}]',
+			'Resolver: object "A" directReferences: []',
+			'Resolver: Step 1b',
+			'Resolver: Resolve conflicts for layers: ["L"]',
+			'LayerState: Resolve conflicts for layer "L", objects: A',
+			'Resolver: Step 2',
+			'resolveTimeline done!',
+		])
+	})
+	test('thrown errors should be ResolveError', () => {
+		const timeline: TimelineObject<any>[] = [
+			{
+				id: 'A',
+				layer: 'L',
+				enable: { start: 'badexpression((' },
+				content: {},
+				priority: 0,
+			},
+		]
+
+		{
+			let error: any = null
+			try {
+				resolveTimeline(timeline, {
+					time: 0,
+					traceResolving: true,
+				})
+			} catch (e) {
+				error = e
+			}
+			expect(error).toBeInstanceOf(ResolveError)
+			expect(error.resolvedTimeline).toBeTruthy()
+		}
+	})
 })

src/api/resolvedTimeline.ts

@@ -48,6 +48,9 @@ export interface ResolvedTimeline<TContent extends Content = Content> {
 		 * (is affected when using cache)
 		 */
 		resolvingCount: number
+
+		/** If traceResolving option is enabled, will contain a trace of the steps the resolver did while resolving */
+		resolveTrace: string[]
 	}
 	/** Is set if there was an error during Resolving and options.dontThrowOnError is set. */
 	error?: Error

src/api/resolver.ts

@@ -37,6 +37,12 @@ export interface ResolveOptions {
 	 */
 	debug?: boolean
 
+	/**
+	 * If true, will store traces of the resolving into resolvedTimeline.statistics.resolveTrace.
+	 * This decreases performance slightly.
+	 */
+	traceResolving?: boolean
+
 	/**
 	 * Skip timeline validation.
 	 * This improves performance slightly, but will not catch errors in the input timeline so use with caution.
@@ -46,7 +52,7 @@ export interface ResolveOptions {
 	/** Skip generating statistics, this improves performance slightly. */
 	skipStatistics?: boolean
 
-	/** Don't throw when an error (such as circular dependency) occurs. The Error will instead be written to resolvedTimeline.error */
+	/** Don't throw when a timeline-error (such as circular dependency) occurs. The Error will instead be written to resolvedTimeline.error */
 	dontThrowOnError?: boolean
 }
 export interface ResolverCache<TContent extends Content = Content> {

src/resolver/CacheHandler.ts

@@ -25,14 +25,19 @@ export class CacheHandler {
 			this.canUseIncomingCache = true
 		}
 
+		if (this.resolvedTimeline.traceResolving) {
+			this.resolvedTimeline.addResolveTrace(`cache: init`)
+			this.resolvedTimeline.addResolveTrace(`cache: canUseIncomingCache: ${this.canUseIncomingCache}`)
+			this.resolvedTimeline.addResolveTrace(
+				`cache: cached objects: ${JSON.stringify(Object.keys(cache.objects))}`
+			)
+		}
+
 		// cache.canBeUsed will be set in this.persistData()
 		cache.canBeUsed = false
 
 		this.cache = cache as ResolverCache
 	}
-	private debug(...args: any[]) {
-		if (this.resolvedTimeline.options.debug) console.log(...args)
-	}
 	public determineChangedObjects(): void {
 		const toc = tic('  cache.determineChangedObjects')
 		// Go through all new objects, and determine whether they have changed:
@@ -45,8 +50,15 @@ export class CacheHandler {
 			const newHash = hashTimelineObject(obj)
 			allNewObjects[obj.id] = true
 
-			if (!oldHash) this.debug(`Cache: Object "${obj.id}" is new`)
-			else if (oldHash !== newHash) this.debug(`Cache: Object "${obj.id}" has changed`)
+			if (!oldHash) {
+				if (this.resolvedTimeline.traceResolving) {
+					this.resolvedTimeline.addResolveTrace(`cache: object "${obj.id}" is new`)
+				}
+			} else if (oldHash !== newHash) {
+				if (this.resolvedTimeline.traceResolving) {
+					this.resolvedTimeline.addResolveTrace(`cache: object "${obj.id}" has changed`)
+				}
+			}
 			if (
 				// Object is new:
 				!oldHash ||
@@ -61,16 +73,20 @@ export class CacheHandler {
 			} else {
 				// No timing-affecting changes detected
 				/* istanbul ignore if */
-				if (!oldHash) this.debug(`Cache: Object "${obj.id}" is similar`)
+				if (!oldHash) {
+					if (this.resolvedTimeline.traceResolving) {
+						this.resolvedTimeline.addResolveTrace(`cache: object "${obj.id}" is similar`)
+					}
+				}
 
 				// Even though the timeline-properties hasn't changed,
 				// the content (and other properties) might have:
 				const oldObj = this.cache.objects[obj.id]
 
 				/* istanbul ignore if */
 				if (!oldObj) {
-					console.error('oldHash', oldHash)
-					console.error('ids', Object.keys(this.cache.objects))
+					console.error(`oldHash: "${oldHash}"`)
+					console.error(`ids: ${JSON.stringify(Object.keys(this.cache.objects))}`)
 					throw new Error(`Internal Error: obj "${obj.id}" not found in cache, even though hashes match!`)
 				}
 
@@ -149,15 +165,28 @@ export class CacheHandler {
 			for (const reference of changedTracker.listChanged()) {
 				invalidator.invalidateObjectsWithReference(reference)
 			}
+			if (this.resolvedTimeline.traceResolving) {
+				this.resolvedTimeline.addResolveTrace(
+					`cache: changed references: ${JSON.stringify(Array.from(changedTracker.listChanged()))}`
+				)
+				this.resolvedTimeline.addResolveTrace(
+					`cache: invalidated objects: ${JSON.stringify(Array.from(invalidator.getInValidObjectIds()))}`
+				)
+				this.resolvedTimeline.addResolveTrace(
+					`cache: unchanged objects: ${JSON.stringify(invalidator.getValidObjects().map((o) => o.id))}`
+				)
+			}
 
 			// At this point, the objects that are left in validObjects are still valid (ie has not changed or is affected by any others).
 			// We can reuse the old resolving for those:
 			for (const obj of invalidator.getValidObjects()) {
-				if (!this.cache.objects[obj.id])
+				if (!this.cache.objects[obj.id]) {
 					/* istanbul ignore next */
 					throw new Error(
-						`Something went wrong: "${obj.id}" does not exist in cache.resolvedTimeline.objects`
+						`Internal Error: Something went wrong: "${obj.id}" does not exist in cache.resolvedTimeline.objects`
 					)
+				}
+
 				this.resolvedTimeline.objectsMap.set(obj.id, this.cache.objects[obj.id])
 			}
 		}
@@ -210,21 +239,26 @@ function getAllReferencesThisObjectAffects(newObj: ResolvedTimelineObject): Refe
 	}
 	return references
 }
+/**
+ * Keeps track of which timeline object have been changed
+ */
 class ChangedTracker {
 	private changedReferences = new Set<Reference>()
 
+	/**
+	 * Mark an object as "has changed".
+	 * Will store all references that are affected by this object.
+	 */
 	public addChangedObject(obj: ResolvedTimelineObject) {
-		const references = getAllReferencesThisObjectAffects(obj)
-		for (const ref of references) {
+		for (const ref of getAllReferencesThisObjectAffects(obj)) {
 			this.changedReferences.add(ref)
 		}
-		if (objHasLayer(obj)) {
-			this.changedReferences.add(`$${obj.layer}`)
-		}
 	}
+	/** Returns true if a reference has changed */
 	public isChanged(ref: Reference): boolean {
 		return this.changedReferences.has(ref)
 	}
+	/** Returns a list of all changed references */
 	public listChanged(): IterableIterator<Reference> {
 		return this.changedReferences.keys()
 	}
@@ -236,6 +270,7 @@ class Invalidator {
 	/** All references that depend on another reference (ie objects, class or layers): */
 	private affectReferenceMap: { [ref: Reference]: Reference[] } = {}
 	private validObjects: ResolvedTimelineObjects = {}
+	private inValidObjectIds: string[] = []
 	/** Map of which objects can be affected by any other object, per layer */
 	private objectLayerMap: { [layer: string]: string[] } = {}
 
@@ -245,6 +280,9 @@ class Invalidator {
 	public getValidObjects(): ResolvedTimelineObject[] {
 		return Object.values<ResolvedTimelineObject>(this.validObjects)
 	}
+	public getInValidObjectIds(): string[] {
+		return this.inValidObjectIds
+	}
 	public addObjectOnLayer(layer: string, obj: ResolvedTimelineObject) {
 		if (!this.objectLayerMap[layer]) this.objectLayerMap[layer] = []
 		this.objectLayerMap[layer].push(obj.id)
@@ -263,6 +301,7 @@ class Invalidator {
 			const objId = getRefObjectId(reference)
 			if (this.validObjects[objId]) {
 				delete this.validObjects[objId]
+				this.inValidObjectIds.push(objId)
 			}
 		}
 		if (isLayerReference(reference)) {

src/resolver/LayerStateHandler.ts

@@ -26,9 +26,6 @@ export class LayerStateHandler {
 		this.objectsOnLayer = []
 		this.objectIdsOnLayer = this.resolvedTimeline.getLayerObjects(layer)
 	}
-	private debug(...args: any[]) {
-		if (this.resolvedTimeline.options.debug) console.log(...args)
-	}
 
 	/** Resolve conflicts between objects on the layer. */
 	public resolveConflicts(): void {
@@ -45,6 +42,12 @@ export class LayerStateHandler {
 		for (const objId of this.objectIdsOnLayer) {
 			this.objectsOnLayer.push(this.resolvedTimeline.getObject(objId))
 		}
+		if (this.resolvedTimeline.traceResolving)
+			this.resolvedTimeline.addResolveTrace(
+				`LayerState: Resolve conflicts for layer "${this.layer}", objects: ${this.objectsOnLayer
+					.map((o) => o.id)
+					.join(', ')}`
+			)
 
 		// Fast-path: if there's only one object on the layer, it can't conflict with anything
 		if (this.objectsOnLayer.length === 1) {
@@ -59,8 +62,6 @@ export class LayerStateHandler {
 			return
 		}
 
-		this.debug(`======= resolveConflicts "${this.layer}" (${this.objectsOnLayer.length} objects)`)
-
 		// Sort to make sure parent groups are evaluated before their children:
 		this.objectsOnLayer.sort(compareObjectsOnLayer)
 
@@ -109,7 +110,7 @@ export class LayerStateHandler {
 
 		// Iterate through all points-of-interest times:
 		for (const time of times) {
-			this.debug(`-------------- time: ${time}`)
+			const traceConflicts: string[] = []
 
 			/** A set of identifiers for which instance-events have been check at this point in time. Used to avoid looking at the same object twice. */
 			const checkedThisTime = new Set<string>()
@@ -169,10 +170,10 @@ export class LayerStateHandler {
 							// Cap the old instance, so it'll end at this point in time:
 							this.instance.setInstanceEndTime(prevObjInstance.instance, time)
 
-							this.debug(`${prevObjInstance.id} stop`)
-
 							// Update activeObjIds:
 							delete activeObjIds[prevObjInstance.id]
+
+							if (this.resolvedTimeline.traceResolving) traceConflicts.push(`${prevObjInstance.id} stop`)
 						}
 					}
 
@@ -181,8 +182,6 @@ export class LayerStateHandler {
 
 						const currentObj = instanceOnTopOfLayer.obj
 
-						this.debug(`${currentObj.id} play`)
-
 						const newInstance: TimelineObjectInstance = {
 							...instanceOnTopOfLayer.instance,
 							// We're setting new start & end times so they match up with the state:
@@ -212,12 +211,20 @@ export class LayerStateHandler {
 
 						// Update activeObjIds:
 						activeObjIds[newObjInstance.id] = newObjInstance
+
+						if (this.resolvedTimeline.traceResolving) traceConflicts.push(`${newObjInstance.id} start`)
 					} else if (removeOld) {
 						// Remove from current state:
 						currentState = undefined
+
+						if (this.resolvedTimeline.traceResolving) traceConflicts.push(`-nothing-`)
 					}
 				}
 			}
+			if (this.resolvedTimeline.traceResolving)
+				this.resolvedTimeline.addResolveTrace(
+					`LayerState: Layer "${this.layer}": time: ${time}: ${traceConflicts.join(', ')}`
+				)
 		}
 		// At this point, the instances of all objects are calculated,
 		// taking into account priorities, clashes etc.
@@ -247,8 +254,6 @@ export class LayerStateHandler {
 			}
 		}
 
-		this.debug('==== resolveConflicts done')
-
 		toc()
 	}
 	/** Add an instance and event to a certain point-in-time */
@@ -259,7 +264,6 @@ export class LayerStateHandler {
 		instance: TimelineObjectInstance
 	) {
 		// Note on order: Ending events come before starting events
-		this.debug('addPointInTime', time, instanceEvent, instance)
 
 		if (!this.pointsInTime[time + '']) this.pointsInTime[time + ''] = []
 		this.pointsInTime[time + ''].push({ obj, instance, instanceEvent })