From 77ff5ee8950af2887c4daec285659e71e206f46d Mon Sep 17 00:00:00 2001 From: Samuel Degueldre Date: Mon, 14 Mar 2022 09:37:21 +0100 Subject: [PATCH] [IMP] component: emit warning when async hooks take too long This commit adds a warning when an async hook (onWillUpdateProps/onWillStart) takes longer than 3 seconds, as these hooks block the rendering and patching of the application, it is rarely desirable and often a sign of a deadlock. This warning will contain the stack trace of the call to the hook to help in debugging. --- doc/reference/app.md | 2 + src/component/lifecycle_hooks.ts | 14 ++++ .../__snapshots__/lifecycle.test.ts.snap | 37 +++++++++ tests/components/lifecycle.test.ts | 78 +++++++++++++++++++ tests/helpers.ts | 2 +- 5 files changed, 132 insertions(+), 1 deletion(-) diff --git a/doc/reference/app.md b/doc/reference/app.md index 489944fb..0e189db1 100644 --- a/doc/reference/app.md +++ b/doc/reference/app.md @@ -117,3 +117,5 @@ Dev mode activates some additional checks and developer amenities: - [Props validation](./props.md#props-validation) is performed - [t-foreach](./templates.md#loops) loops check for key unicity - Lifecycle hooks are wrapped to report their errors in a more developer-friendly way +- onWillStart and onWillUpdateProps will emit a warning in the console when they + take longer than 3 seconds in an effort to ease debugging the presence of deadlocks diff --git a/src/component/lifecycle_hooks.ts b/src/component/lifecycle_hooks.ts index 3d7fafd5..16984ef3 100644 --- a/src/component/lifecycle_hooks.ts +++ b/src/component/lifecycle_hooks.ts @@ -1,14 +1,28 @@ import { getCurrent } from "./component_node"; import { nodeErrorHandlers } from "./error_handling"; +const TIMEOUT = Symbol("timeout"); function wrapError(fn: (...args: any[]) => any, hookName: string) { const error = new Error(`The following error occurred in ${hookName}: `) as Error & { cause: any; }; + const timeoutError = new Error(`${hookName}'s promise hasn't resolved after 3 seconds`); + const node = getCurrent(); return (...args: any[]) => { try { const result = fn(...args); if (result instanceof Promise) { + if (hookName === "onWillStart" || hookName === "onWillUpdateProps") { + const fiber = node.fiber; + Promise.race([ + result, + new Promise((resolve) => setTimeout(() => resolve(TIMEOUT), 3000)), + ]).then((res) => { + if (res === TIMEOUT && node.fiber === fiber) { + console.warn(timeoutError); + } + }); + } return result.catch((cause) => { error.cause = cause; if (cause instanceof Error) { diff --git a/tests/components/__snapshots__/lifecycle.test.ts.snap b/tests/components/__snapshots__/lifecycle.test.ts.snap index 71d5c43d..19a52e7c 100644 --- a/tests/components/__snapshots__/lifecycle.test.ts.snap +++ b/tests/components/__snapshots__/lifecycle.test.ts.snap @@ -658,6 +658,43 @@ exports[`lifecycle hooks sub widget (inside sub node): hooks are correctly calle }" `; +exports[`lifecycle hooks timeout in onWillStart emits a warning 1`] = ` +"function anonymous(bdom, helpers +) { + let { text, createBlock, list, multi, html, toggler, component, comment } = bdom; + + let block1 = createBlock(\`\`); + + return function template(ctx, node, key = \\"\\") { + return block1(); + } +}" +`; + +exports[`lifecycle hooks timeout in onWillUpdateProps emits a warning 1`] = ` +"function anonymous(bdom, helpers +) { + let { text, createBlock, list, multi, html, toggler, component, comment } = bdom; + + return function template(ctx, node, key = \\"\\") { + const props1 = {prop: ctx['state'].prop}; + helpers.validateProps(\`Child\`, props1, ctx); + return component(\`Child\`, props1, key + \`__1\`, node, ctx); + } +}" +`; + +exports[`lifecycle hooks timeout in onWillUpdateProps emits a warning 2`] = ` +"function anonymous(bdom, helpers +) { + let { text, createBlock, list, multi, html, toggler, component, comment } = bdom; + + return function template(ctx, node, key = \\"\\") { + return text(\`\`); + } +}" +`; + exports[`lifecycle hooks willPatch, patched hook are called on subsubcomponents, in proper order 1`] = ` "function anonymous(bdom, helpers ) { diff --git a/tests/components/lifecycle.test.ts b/tests/components/lifecycle.test.ts index 8900839f..5b913a6c 100644 --- a/tests/components/lifecycle.test.ts +++ b/tests/components/lifecycle.test.ts @@ -14,6 +14,7 @@ import { logStep, makeDeferred, makeTestFixture, + nextMicroTick, nextTick, snapshotEverything, useLogLifecycle, @@ -104,6 +105,83 @@ describe("lifecycle hooks", () => { await mount(Test, fixture); }); + test("timeout in onWillStart emits a warning", async () => { + const { warn } = console; + let warnArgs: any[]; + console.warn = jest.fn((...args) => (warnArgs = args)); + const { setTimeout } = window; + let timeoutCbs: any = {}; + let timeoutId = 0; + window.setTimeout = ((cb: any) => { + timeoutCbs[++timeoutId] = cb; + return timeoutId; + }) as any; + class Test extends Component { + static template = xml``; + setup() { + onWillStart(() => new Promise(() => {})); + } + } + mount(Test, fixture, { test: true }); + nextTick(); + for (const id in timeoutCbs) { + timeoutCbs[id](); + delete timeoutCbs[id]; + } + await nextMicroTick(); + await nextMicroTick(); + expect(console.warn).toHaveBeenCalledTimes(1); + expect(warnArgs![0]!.message).toBe("onWillStart's promise hasn't resolved after 3 seconds"); + console.warn = warn; + window.setTimeout = setTimeout; + }); + + test("timeout in onWillUpdateProps emits a warning", async () => { + class Child extends Component { + static template = xml``; + setup() { + onWillUpdateProps(() => new Promise(() => {})); + } + } + class Parent extends Component { + static template = xml``; + static components = { Child }; + state = useState({ prop: 1 }); + } + const parent = await mount(Parent, fixture, { test: true }); + + const { warn } = console; + let warnArgs: any[]; + console.warn = jest.fn((...args) => (warnArgs = args)); + const { setTimeout } = window; + let timeoutCbs: any = {}; + let timeoutId = 0; + window.setTimeout = ((cb: any) => { + timeoutCbs[++timeoutId] = cb; + return timeoutId; + }) as any; + + parent.state.prop = 2; + let tick = nextTick(); + for (const id in timeoutCbs) { + timeoutCbs[id](); + delete timeoutCbs[id]; + } + await tick; + tick = nextTick(); + for (const id in timeoutCbs) { + timeoutCbs[id](); + delete timeoutCbs[id]; + } + await tick; + expect(console.warn).toHaveBeenCalledTimes(1); + expect(warnArgs![0]!.message).toBe( + "onWillUpdateProps's promise hasn't resolved after 3 seconds" + ); + console.warn = warn; + window.setTimeout = setTimeout; + }); + test("mounted hook is called if mounted in DOM", async () => { let mounted = false; class Test extends Component { diff --git a/tests/helpers.ts b/tests/helpers.ts index 13d72654..44574c00 100644 --- a/tests/helpers.ts +++ b/tests/helpers.ts @@ -49,7 +49,7 @@ export async function nextTick(): Promise { interface Deferred extends Promise { resolve(val?: any): void; - reject(): void; + reject(val?: any): void; } export function makeDeferred(): Deferred {