Improve construction error handling (#1532)

When component initialization fails due to an error in a dependency, we previously did not report the error in the
dependency because this could lead to duplicate stack traces.

The downside is that if the process crashes before the root cause is reported then it goes unreported.  This commonly
happens with unhandled exceptions.  And even if reported, the error message would potentially be in a separate location
in the log that you'd need to hunt for.

This commit makes it so we attach the original cause to "dependency initialization" errors.  To avoid redundant traces
it includes logic to track which errors have had their trace logged.  For tertiary reporting of the error we then omit
the stack trace so the only duplication is of the message.

Also includes a few additional tests and a fix for late addition of behaviors with async initialization logic.

Co-authored-by: Ingo Fischer <[email protected]>

packages/general/src/log/Diagnostic.ts

@@ -7,6 +7,8 @@
 import type { Lifecycle } from "../util/Lifecycle.js";
 import { LogLevel } from "./LogLevel.js";
 
+let errorCollector: undefined | ((error: {}) => boolean);
+
 /**
  * Logged values may implement this interface to customize presentation.
  *
@@ -74,6 +76,57 @@ export namespace Diagnostic {
         Via = "via",
     }
 
+    export interface Context {
+        run<T>(fn: () => T): T;
+    }
+
+    /**
+     * Diagnostic context provides contextual information that affects formatting.
+     */
+    export function Context(): Context {
+        let errorsCollected: undefined | {}[];
+        const errorsReported = new WeakSet<{}>();
+
+        const thisErrorCollector = (error: {}) => {
+            // Indicate to caller this error is already reported
+            if (errorsReported.has(error)) {
+                return true;
+            }
+
+            // Collect the error so it can be marked as reported if a contextual operation succeeds
+            if (errorsCollected) {
+                errorsCollected.push(error);
+            } else {
+                errorsCollected = [error];
+            }
+
+            // Indicate to caller this error is as yet unreported
+            return false;
+        };
+
+        return {
+            run(fn) {
+                const originalErrorCollector = errorCollector;
+                try {
+                    errorCollector = thisErrorCollector;
+
+                    const result = fn();
+
+                    if (errorsCollected) {
+                        for (const error of errorsCollected) {
+                            errorsReported.add(error);
+                        }
+                        errorsCollected = undefined;
+                    }
+
+                    return result;
+                } finally {
+                    errorCollector = originalErrorCollector;
+                }
+            },
+        };
+    }
+
     export const presentation = Symbol("presentation");
     export const value = Symbol("value");
 
@@ -282,7 +335,7 @@ function formatError(error: any, options: { messagePrefix?: string; parentStack?
     const { messagePrefix, parentStack } = options;
 
     const messageAndStack = messageAndStackFor(error, parentStack);
-    const { stack, stackLines } = messageAndStack;
+    let { stack, stackLines } = messageAndStack;
 
     let { message } = messageAndStack;
     if (messagePrefix) {
@@ -296,12 +349,20 @@ function formatError(error: any, options: { messagePrefix?: string; parentStack?
         ({ cause, errors } = error);
     }
 
+    // Report the error to context.  If return value is true, stack is already reported in this context so omit
+    if (errorCollector?.(error)) {
+        stack = stackLines = undefined;
+    }
+
     if (stack === undefined && cause === undefined && errors === undefined) {
         return message;
     }
 
     const list: Array<string | Diagnostic> = [message];
-    if (stack !== undefined) {
+    if (stack === undefined) {
+        // Ensure line break in case of no stack
+        list.push(Diagnostic(Diagnostic.Presentation.List, []));
+    } else {
         list.push(Diagnostic(Diagnostic.Presentation.List, stack));
     }
 

packages/general/src/log/Logger.ts

@@ -67,6 +67,7 @@ type LoggerDefinition = {
     log: (level: LogLevel, formattedLog: string) => void;
     defaultLogLevel: LogLevel;
     logLevels: { [facility: string]: LogLevel };
+    context?: Diagnostic.Context;
 };
 
 /**
@@ -96,6 +97,7 @@ type LoggerDefinition = {
 export class Logger {
     static logger: Array<LoggerDefinition>;
     static nestingLevel: number;
+    readonly #name: string;
 
     /** Add additional logger to the list of loggers including the default configuration. */
     public static addLogger(
@@ -439,20 +441,31 @@ export class Logger {
         }
     }
 
-    constructor(private readonly name: string) {}
+    constructor(name: string) {
+        this.#name = name;
+    }
 
-    debug = (...values: any[]) => this.log(LogLevel.DEBUG, values);
-    info = (...values: any[]) => this.log(LogLevel.INFO, values);
-    notice = (...values: any[]) => this.log(LogLevel.NOTICE, values);
-    warn = (...values: any[]) => this.log(LogLevel.WARN, values);
-    error = (...values: any[]) => this.log(LogLevel.ERROR, values);
-    fatal = (...values: any[]) => this.log(LogLevel.FATAL, values);
+    debug = (...values: any[]) => this.#log(LogLevel.DEBUG, values);
+    info = (...values: any[]) => this.#log(LogLevel.INFO, values);
+    notice = (...values: any[]) => this.#log(LogLevel.NOTICE, values);
+    warn = (...values: any[]) => this.#log(LogLevel.WARN, values);
+    error = (...values: any[]) => this.#log(LogLevel.ERROR, values);
+    fatal = (...values: any[]) => this.#log(LogLevel.FATAL, values);
+
+    #log(level: LogLevel, values: any[]) {
+        for (const logger of Logger.logger) {
+            if (level < (logger.logLevels[this.#name] ?? logger.defaultLogLevel)) {
+                return;
+            }
 
-    private log(level: LogLevel, values: any[]) {
-        Logger.logger.forEach(logger => {
-            if (level < (logger.logLevels[this.name] ?? logger.defaultLogLevel)) return;
-            logger.log(level, logger.logFormatter(Time.now(), level, this.name, nestingPrefix(), values));
-        });
+            if (!logger.context) {
+                logger.context = Diagnostic.Context();
+            }
+
+            logger.context.run(() =>
+                logger.log(level, logger.logFormatter(Time.now(), level, this.#name, nestingPrefix(), values)),
+            );
+        }
     }
 }
 

packages/general/src/util/Construction.ts

@@ -233,6 +233,7 @@ export function Construction<const T extends Constructable>(
     let closedReject: undefined | ((error: any) => void);
 
     let error: undefined | Error;
+    let errorForDependencies: undefined | CrashedDependencyError;
     let primaryCauseHandled = false;
     let status = Lifecycle.Status.Inactive;
     let change: Observable<[status: Lifecycle.Status, subject: T]> | undefined;
@@ -473,12 +474,12 @@ export function Construction<const T extends Constructable>(
                 case Lifecycle.Status.Inactive:
                     awaiterPromise = closedPromise = undefined;
                     primaryCauseHandled = false;
-                    error = undefined;
+                    error = errorForDependencies = undefined;
                     break;
 
                 case Lifecycle.Status.Active:
                     awaiterPromise = closedPromise = undefined;
-                    error = undefined;
+                    error = errorForDependencies = undefined;
                     break;
 
                 default:
@@ -590,16 +591,21 @@ export function Construction<const T extends Constructable>(
             return error;
         }
 
+        if (errorForDependencies) {
+            return errorForDependencies;
+        }
+
         let what;
         if (subject.toString === Object.prototype.toString) {
             what = subject.constructor.name;
         } else {
             what = subject.toString();
         }
 
-        const crashError = new CrashedDependencyError(what, "unavailable due to initialization error");
-        crashError.subject = subject;
-        return crashError;
+        errorForDependencies = new CrashedDependencyError(what, "unavailable due to initialization error");
+        errorForDependencies.subject = subject;
+        errorForDependencies.cause = error;
+        return errorForDependencies;
     }
 
     function setStatus(newStatus: Lifecycle.Status) {

packages/general/test/log/LoggerTest.ts

@@ -387,6 +387,37 @@ describe("Logger", () => {
         });
     });
 
+    describe("error reporting", () => {
+        it("logs stack trace on first report but not second", () => {
+            const error = new Error("Oops my bad");
+            error.stack = "at someRandomFunction (some-random-file.ts:10:1)";
+
+            const message1 = captureOne(() => logger.error("Oh no:", error));
+            expect(message1.message).match(/Oops my bad/);
+            expect(message1.message).match(/someRandomFunction/);
+
+            const message2 = captureOne(() => logger.error("Let's make sure you get this", error));
+            expect(message2.message).match(/Oops my bad/);
+            expect(message2.message).not.match(/someRandomFunction/);
+        });
+
+        it("logs stack trace on first report but not second as cause", () => {
+            const error = new Error("Oops my bad");
+            error.stack = "at someRandomFunction (some-random-file.ts:10:1)";
+            const message1 = captureOne(() => logger.error("Oh no:", error));
+            expect(message1.message).match(/Oops my bad/);
+            expect(message1.message).match(/someRandomFunction/);
+
+            const error2 = new Error("Crap sorry about this too", { cause: error });
+            error2.stack = "at someOtherFunction (some-other-function.ts:10:1)";
+            const message2 = captureOne(() => logger.error("And then this happened:", error2));
+            expect(message2.message).match(/Crap sorry/);
+            expect(message2.message).match(/someOtherFunction/);
+            expect(message2.message).match(/Oops my bad/);
+            expect(message2.message).not.match(/someRandomFunction/);
+        });
+    });
+
     function itUsesCorrectConsoleMethod(sourceName: string, sinkName: string = sourceName) {
         it(`maps logger.${sourceName} to console.${sinkName}`, () => {
             const actualLogger = Logger.log;

packages/node/src/behavior/internal/BehaviorBacking.ts

@@ -45,7 +45,11 @@ export abstract class BehaviorBacking {
             // The endpoint reports errors during initialization.  For errors occurring later we report the error
             // ourselves
             if (endpoint.lifecycle.isReady) {
-                logger.error(`Error initializing ${this}:`, error);
+                if (error instanceof BehaviorInitializationError) {
+                    logger.error(error);
+                } else {
+                    logger.error(`Error initializing ${this}:`, error);
+                }
             }
         });
     }
@@ -64,8 +68,12 @@ export abstract class BehaviorBacking {
      * Initiated via {@link Construction#start} by Behaviors class once the backing is installed.
      */
     [Construction.construct](agent: Agent) {
+        let crashError: undefined | BehaviorInitializationError;
         const crash = (cause: unknown) => {
-            throw new BehaviorInitializationError(`Error initializing ${this}`, cause);
+            if (!crashError) {
+                crashError = new BehaviorInitializationError(`Error initializing ${this}`, cause);
+            }
+            throw crashError;
         };
 
         try {

packages/node/src/endpoint/properties/Behaviors.ts

@@ -506,20 +506,26 @@ export class Behaviors {
     }
 
     #activateLate(type: Behavior.Type) {
-        const result = OfflineContext.act("behavior-late-activation", this.#endpoint.env.get(NodeActivity), context =>
-            this.activate(type, context.agentFor(this.#endpoint)),
-        );
+        const result = OfflineContext.act("behavior-late-activation", this.#endpoint.env.get(NodeActivity), context => {
+            this.activate(type, context.agentFor(this.#endpoint));
+
+            // Agent must remain active until backing is initialized
+            const backing = this.#backingFor(type);
+            return backing.construction.ready;
+        });
 
         if (MaybePromise.is(result)) {
             result.then(undefined, error => {
                 // The backing should handle its own errors so if present assume this is a commit error and crash the
                 // backing.  If there's no backing then there shouldn't be a promise so this is effectively an internal
                 // error
                 const backing = this.#backings[type.id];
-                if (backing) {
-                    logger.error(`Error initializing ${backing}`, error);
+                if (error instanceof BehaviorInitializationError) {
+                    logger.error(error);
+                } else if (backing) {
+                    logger.error(`Error initializing ${backing}:`, error);
                 } else {
-                    logger.error(`Unexpected rejection initializing ${type.name}`, error);
+                    logger.error(`Unexpected rejection initializing ${type.name}:`, error);
                 }
             });
         }

packages/node/test/endpoint/EndpointTest.ts

@@ -6,16 +6,21 @@
 
 import { IndexBehavior } from "#behavior/system/index/IndexBehavior.js";
 import { BasicInformationServer } from "#behaviors/basic-information";
+import { OnOffBehavior, OnOffServer } from "#behaviors/on-off";
+import { PowerSourceServer } from "#behaviors/power-source";
 import { WindowCoveringServer } from "#behaviors/window-covering";
 import { AccessControl } from "#clusters/access-control";
 import { BasicInformation } from "#clusters/basic-information";
 import { WindowCoveringCluster } from "#clusters/window-covering";
+import { OnOffLightDevice } from "#devices/on-off-light";
 import { TemperatureSensorDevice } from "#devices/temperature-sensor";
 import { WindowCoveringDevice } from "#devices/window-covering";
 import { Agent } from "#endpoint/Agent.js";
 import { Endpoint } from "#endpoint/Endpoint.js";
+import { AggregatorEndpoint } from "#endpoints/aggregator";
 import { RootEndpoint } from "#endpoints/root";
 import { MockNode } from "../node/mock-node.js";
+import { MockServerNode } from "../node/mock-server-node.js";
 
 const WindowCoveringLiftDevice = WindowCoveringDevice.with(
     WindowCoveringServer.for(WindowCoveringCluster.with("Lift", "PositionAwareLift", "AbsolutePosition")),
@@ -169,4 +174,55 @@ describe("Endpoint", () => {
             ]);
         });
     });
+
+    describe("accepts new behaviors", () => {
+        it("before endpoint installation", async () => {
+            const endpoint = new Endpoint(WindowCoveringLiftDevice);
+            endpoint.behaviors.require(OnOffServer);
+            const node = new MockServerNode();
+            await node.add(endpoint);
+            await node.construction;
+            expect(endpoint.stateOf(OnOffBehavior).onOff).false;
+        });
+
+        it("after endpoint installation", async () => {
+            const endpoint = new Endpoint(WindowCoveringLiftDevice);
+            const node = new MockServerNode();
+            await node.add(endpoint);
+            endpoint.behaviors.require(OnOffServer);
+            node.parts.add(endpoint);
+            await node.construction;
+            expect(endpoint.stateOf(OnOffBehavior).onOff).false;
+        });
+
+        it("after node initialization", async () => {
+            const endpoint = new Endpoint(WindowCoveringLiftDevice);
+            const node = new MockServerNode();
+            await node.add(endpoint);
+            node.parts.add(endpoint);
+            await node.construction;
+            endpoint.behaviors.require(OnOffServer);
+            expect(endpoint.stateOf(OnOffBehavior).onOff).false;
+        });
+
+        it("after node start", async () => {
+            const endpoint = new Endpoint(WindowCoveringLiftDevice);
+            const node = new MockServerNode();
+            await node.add(endpoint);
+            node.parts.add(endpoint);
+            await node.start();
+            endpoint.behaviors.require(OnOffServer);
+            expect(endpoint.stateOf(OnOffBehavior).onOff).false;
+            await node.close();
+        });
+
+        it("with powersource on a bridged node", async () => {
+            const node = new MockServerNode();
+            const bridge = new Endpoint(AggregatorEndpoint);
+            await node.add(bridge);
+            const bridgedNode = new Endpoint(OnOffLightDevice);
+            await bridge.add(bridgedNode);
+            bridgedNode.behaviors.require(PowerSourceServer);
+        });
+    });
 });