diff --git a/packages/general/src/log/Diagnostic.ts b/packages/general/src/log/Diagnostic.ts index 24edf4b3d1..b8889ba83f 100644 --- a/packages/general/src/log/Diagnostic.ts +++ b/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(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 = [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)); } diff --git a/packages/general/src/log/Logger.ts b/packages/general/src/log/Logger.ts index 3c4a26ab33..59127a90ae 100644 --- a/packages/general/src/log/Logger.ts +++ b/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; 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)), + ); + } } } diff --git a/packages/general/src/util/Construction.ts b/packages/general/src/util/Construction.ts index 6ef2c2983c..ba51bd3f96 100644 --- a/packages/general/src/util/Construction.ts +++ b/packages/general/src/util/Construction.ts @@ -233,6 +233,7 @@ export function Construction( 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( 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,6 +591,10 @@ export function Construction( return error; } + if (errorForDependencies) { + return errorForDependencies; + } + let what; if (subject.toString === Object.prototype.toString) { what = subject.constructor.name; @@ -597,9 +602,10 @@ export function Construction( 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) { diff --git a/packages/general/test/log/LoggerTest.ts b/packages/general/test/log/LoggerTest.ts index 03782ac4bf..e78cc2c8db 100644 --- a/packages/general/test/log/LoggerTest.ts +++ b/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; diff --git a/packages/node/src/behavior/internal/BehaviorBacking.ts b/packages/node/src/behavior/internal/BehaviorBacking.ts index 882213962a..070da88dc9 100644 --- a/packages/node/src/behavior/internal/BehaviorBacking.ts +++ b/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 { diff --git a/packages/node/src/endpoint/properties/Behaviors.ts b/packages/node/src/endpoint/properties/Behaviors.ts index b6c61db82e..f6df0a609e 100644 --- a/packages/node/src/endpoint/properties/Behaviors.ts +++ b/packages/node/src/endpoint/properties/Behaviors.ts @@ -506,9 +506,13 @@ 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 => { @@ -516,10 +520,12 @@ export class Behaviors { // 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); } }); } diff --git a/packages/node/test/endpoint/EndpointTest.ts b/packages/node/test/endpoint/EndpointTest.ts index 3142f8b858..a8433f2bf6 100644 --- a/packages/node/test/endpoint/EndpointTest.ts +++ b/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); + }); + }); }); diff --git a/packages/node/test/endpoint/type/MutableEndpointTest.ts b/packages/node/test/endpoint/type/MutableEndpointTest.ts index 3a8a6199ae..d2c690f7bb 100644 --- a/packages/node/test/endpoint/type/MutableEndpointTest.ts +++ b/packages/node/test/endpoint/type/MutableEndpointTest.ts @@ -6,6 +6,7 @@ import { SupportedBehaviors } from "#endpoint/properties/SupportedBehaviors.js"; import { MutableEndpoint } from "#endpoint/type/MutableEndpoint.js"; +import { RootEndpoint } from "#endpoints/root"; import { DeviceClassification } from "#model"; import { DeviceTypeId } from "#types"; import { MockBehavior1, MockBehavior2 } from "../mock-endpoint.js"; @@ -93,6 +94,17 @@ describe("MutableEndpoint", () => { expectIdentityWithBehaviors(Type); }); + it("supports withBehavior alias", () => { + const Type = MutableEndpoint(Identity).withBehaviors(MockBehavior1, MockBehavior2); + expectIdentityWithBehaviors(Type); + }); + + it("RootEndpoint supports withBehavior", () => { + const Type = RootEndpoint.withBehaviors(MockBehavior1, MockBehavior2); + expect(Type.behaviors.one).not.undefined; + expect(Type.behaviors.two).not.undefined; + }); + it("extends with one behavior twice", () => { const Type = MutableEndpoint(Identity).with(MockBehavior1).with(MockBehavior2); expectIdentityWithBehaviors(Type); diff --git a/packages/testing/src/cli.ts b/packages/testing/src/cli.ts index f454ecf95c..235457f2ba 100644 --- a/packages/testing/src/cli.ts +++ b/packages/testing/src/cli.ts @@ -10,6 +10,7 @@ import "./util/node-shims.js"; import "./global-definitions.js"; import { Builder, Graph, Package, Project } from "#tools"; +import { clear } from "console"; import yargs from "yargs"; import { hideBin } from "yargs/helpers"; import { TestRunner } from "./runner.js"; @@ -57,6 +58,7 @@ export async function main(argv = process.argv) { .option("profile", { type: "boolean", describe: "Write profiling data to build/profiles (node only)" }) .option("wtf", { type: "boolean", describe: "Enlist wtfnode to detect test leaks" }) .option("trace-unhandled", { type: "boolean", describe: "Detail unhandled rejections with trace-unhandled" }) + .option("clear", { type: "boolean", describe: "Clear terminal before testing" }) .command("*", "run all supported test types") .command("esm", "run tests on node (ES6 modules)", () => testTypes.add(TestType.esm)) .command("cjs", "run tests on node (CommonJS modules)", () => testTypes.add(TestType.cjs)) @@ -77,9 +79,15 @@ export async function main(argv = process.argv) { // If the location is a workspace, test all packages with test const builder = new Builder(); const pkg = new Package({ path: packageLocation }); + if (pkg.isWorkspace) { const graph = await Graph.load(pkg); await graph.build(builder, false); + + if (args.clear) { + clear(); + } + for (const node of graph.nodes) { if (!node.pkg.hasTests || node.pkg.json.matter?.test === false) { continue; @@ -94,6 +102,11 @@ export async function main(argv = process.argv) { } else { await builder.build(new Project(pkg)); } + + if (args.clear) { + clear(); + } + await test(pkg); }