From 822762305dc9a829f7b80f851da9647f8e78db57 Mon Sep 17 00:00:00 2001 From: AlCalzone Date: Thu, 21 Sep 2023 15:33:11 +0200 Subject: [PATCH] fix: attempt soft-resetting controller when callback times out (#6296) --- .eslintrc.js | 2 +- packages/core/src/error/ZWaveError.ts | 8 + .../src/rules/no-debug-in-tests.ts | 10 +- packages/zwave-js/src/lib/driver/Driver.ts | 120 ++++++---- .../cc-specific/notificationEnums.test.ts | 4 +- .../lib/test/driver/controllerJammed.test.ts | 2 +- .../driver/nodeAsleepMessageOrder.test.ts | 4 +- .../src/lib/test/driver/sendDataAbort.test.ts | 171 -------------- .../sendDataMissingCallbackAbort.test.ts | 215 ++++++++++++++++++ .../lib/test/driver/unresponsiveStick.test.ts | 11 + 10 files changed, 320 insertions(+), 227 deletions(-) delete mode 100644 packages/zwave-js/src/lib/test/driver/sendDataAbort.test.ts create mode 100644 packages/zwave-js/src/lib/test/driver/sendDataMissingCallbackAbort.test.ts diff --git a/.eslintrc.js b/.eslintrc.js index f5f3e2f53b9f..914b6a49d6e8 100644 --- a/.eslintrc.js +++ b/.eslintrc.js @@ -164,7 +164,7 @@ module.exports = { "@typescript-eslint/no-floating-promises": "off", "@typescript-eslint/require-await": "off", "@typescript-eslint/unbound-method": "off", - "@typescript-eslint/no-unused-vars": "warn", + "@typescript-eslint/no-unused-vars": "off", "@typescript-eslint/dot-notation": "off", "@zwave-js/no-debug-in-tests": "error", diff --git a/packages/core/src/error/ZWaveError.ts b/packages/core/src/error/ZWaveError.ts index df7585d54707..43678cc8d9ee 100644 --- a/packages/core/src/error/ZWaveError.ts +++ b/packages/core/src/error/ZWaveError.ts @@ -285,3 +285,11 @@ export function isMissingControllerACK( && e.code === ZWaveErrorCodes.Controller_Timeout && e.context === "ACK"; } + +export function isMissingControllerCallback( + e: unknown, +): e is ZWaveError { + return isZWaveError(e) + && e.code === ZWaveErrorCodes.Controller_Timeout + && e.context === "callback"; +} diff --git a/packages/eslint-plugin/src/rules/no-debug-in-tests.ts b/packages/eslint-plugin/src/rules/no-debug-in-tests.ts index 202baf172fd0..ea0b7578fc20 100644 --- a/packages/eslint-plugin/src/rules/no-debug-in-tests.ts +++ b/packages/eslint-plugin/src/rules/no-debug-in-tests.ts @@ -2,6 +2,8 @@ import { AST_NODE_TYPES, ESLintUtils } from "@typescript-eslint/utils"; import path from "node:path"; import { repoRoot } from "../utils.js"; +const isFixMode = process.argv.some((arg) => arg.startsWith("--fix")); + const integrationTestDefinitionFiles = new Set( [ "packages/zwave-js/src/lib/test/integrationTestSuite", @@ -57,7 +59,10 @@ export const noDebugInTests = ESLintUtils.RuleCreator.withoutDocs({ context.report({ node, messageId: "no-debug", - fix: (fixer) => fixer.insertTextBefore(node, "// "), + // Do not auto-fix in the editor + fix: isFixMode + ? (fixer) => fixer.insertTextBefore(node, "// ") + : undefined, }); } }, @@ -69,7 +74,8 @@ export const noDebugInTests = ESLintUtils.RuleCreator.withoutDocs({ "Integration tests should have the `debug` flag set to `false` when not actively debugging.", }, type: "problem", - fixable: "code", + // Do not auto-fix in the editor + fixable: isFixMode ? "code" : undefined, schema: [], messages: { "no-debug": diff --git a/packages/zwave-js/src/lib/driver/Driver.ts b/packages/zwave-js/src/lib/driver/Driver.ts index bf7c4576b515..a543707b89de 100644 --- a/packages/zwave-js/src/lib/driver/Driver.ts +++ b/packages/zwave-js/src/lib/driver/Driver.ts @@ -85,6 +85,7 @@ import { getCCName, highResTimestamp, isMissingControllerACK, + isMissingControllerCallback, isZWaveError, messageRecordToLines, securityClassIsS2, @@ -466,6 +467,13 @@ type PrefixedNodeEvents = { ]: ZWaveNodeEventCallbacks[K]; }; +const enum ControllerRecoveryPhase { + None, + NoACK, + CallbackTimeout, + CallbackTimeoutAfterReset, +} + // Strongly type the event emitter events export interface DriverEventCallbacks extends PrefixedNodeEvents { "driver ready": () => void; @@ -538,9 +546,12 @@ export class Driver extends TypedEventEmitter this.immediateQueue = new TransactionQueue({ name: "immediate", mayStartNextTransaction: (t) => { - // While the controller is unresponsive, only soft resetting is allowed + // While the controller is unresponsive, only soft resetting is allowed. + // Since we use GetControllerVersionRequest to check if the controller responds after soft-reset, + // allow that too. if (this.controller.status === ControllerStatus.Unresponsive) { - return t.message instanceof SoftResetRequest; + return t.message instanceof SoftResetRequest + || t.message instanceof GetControllerVersionRequest; } // All other messages on the immediate queue may always be sent as long as the controller is ready to send @@ -693,6 +704,9 @@ export class Driver extends TypedEventEmitter return this._bootloader != undefined; } + private _recoveryPhase: ControllerRecoveryPhase = + ControllerRecoveryPhase.None; + private _securityManager: SecurityManager | undefined; /** * **!!! INTERNAL !!!** @@ -1021,16 +1035,9 @@ export class Driver extends TypedEventEmitter return; } - const message = `Serial port errored: ${err.message}`; - this.driverLog.print(message, "error"); - - const error = new ZWaveError( - message, - ZWaveErrorCodes.Driver_Failed, + void this.destroyWithMessage( + `Serial port errored: ${err.message}`, ); - this.emit("error", error); - - void this.destroy(); }); // If the port is already open, close it first if (this.serial.isOpen) await this.serial.close(); @@ -1097,17 +1104,9 @@ export class Driver extends TypedEventEmitter this._controller = new ZWaveController(this, true); this.emit("bootloader ready"); } else { - const message = - "Failed to recover from bootloader. Please flash a new firmware to continue..."; - this.driverLog.print(message, "error"); - this.emit( - "error", - new ZWaveError( - message, - ZWaveErrorCodes.Driver_Failed, - ), + void this.destroyWithMessage( + "Failed to recover from bootloader. Please flash a new firmware to continue...", ); - void this.destroy(); } return; @@ -1131,12 +1130,8 @@ export class Driver extends TypedEventEmitter message = `Failed to create the cache directory. Please make sure that it is writable or change the location with the "storage.cacheDir" driver option.`; } - this.driverLog.print(message, "error"); - this.emit( - "error", - new ZWaveError(message, ZWaveErrorCodes.Driver_Failed), - ); - void this.destroy(); + + void this.destroyWithMessage(message); return; } @@ -1151,12 +1146,7 @@ export class Driver extends TypedEventEmitter e, ) }`; - this.driverLog.print(message, "error"); - this.emit( - "error", - new ZWaveError(message, ZWaveErrorCodes.Driver_Failed), - ); - void this.destroy(); + void this.destroyWithMessage(message); return; } } @@ -2764,6 +2754,18 @@ export class Driver extends TypedEventEmitter ); } + private async destroyWithMessage(message: string): Promise { + this.driverLog.print(message, "error"); + + const error = new ZWaveError( + message, + ZWaveErrorCodes.Driver_Failed, + ); + this.emit("error", error); + + await this.destroy(); + } + /** * Terminates the driver instance and closes the underlying serial connection. * Must be called under any circumstances. @@ -3461,27 +3463,38 @@ export class Driver extends TypedEventEmitter } } - private handleMissingControllerACK( + private handleUnresponsiveController( transaction: Transaction, error: ZWaveError, ): boolean { if (!this._controller) return false; - const fail = () => { - this.driverLog.print( - "Recovering unresponsive controller failed. Restarting the driver...", - "error", - ); - void this.destroy(); + const fail = (message: string) => { + this.rejectTransaction(transaction, error); + + void this.destroyWithMessage(message); }; - if (this._controller.status !== ControllerStatus.Unresponsive) { + if ( + this._recoveryPhase + === ControllerRecoveryPhase.CallbackTimeoutAfterReset + ) { + // The controller is still timing out transmitting after a soft reset, don't try again. + // Reject the transaction and destroy the driver. + fail("Controller is still timing out. Restarting the driver..."); + + return true; + } else if (this._controller.status !== ControllerStatus.Unresponsive) { // The controller was responsive before this transaction failed. // Mark it as unresponsive and try to soft-reset it. this.controller.setStatus( ControllerStatus.Unresponsive, ); + this._recoveryPhase = isMissingControllerACK(error) + ? ControllerRecoveryPhase.NoACK + : ControllerRecoveryPhase.CallbackTimeout; + this.driverLog.print( "Attempting to recover unresponsive controller...", "warn", @@ -3496,11 +3509,21 @@ export class Driver extends TypedEventEmitter void this.softReset().then(() => { // The controller responded. It is no longer unresponsive this._controller?.setStatus(ControllerStatus.Ready); + + if (this._recoveryPhase === ControllerRecoveryPhase.NoACK) { + this._recoveryPhase = ControllerRecoveryPhase.None; + } else if ( + this._recoveryPhase + === ControllerRecoveryPhase.CallbackTimeout + ) { + this._recoveryPhase = + ControllerRecoveryPhase.CallbackTimeoutAfterReset; + } }).catch(() => { - // Soft-reset failed. - // Reject the original transaction and try restarting the driver. - this.rejectTransaction(transaction, error); - fail(); + // Soft-reset failed. Reject the original transaction and try restarting the driver. + fail( + "Recovering unresponsive controller failed. Restarting the driver...", + ); }); return true; @@ -5487,9 +5510,10 @@ ${handlers.length} left`, // If a node failed to respond in time, it might be sleeping if (this.isMissingNodeACK(transaction, error)) { if (this.handleMissingNodeACK(transaction as any, error)) return; - } else if (isMissingControllerACK(error)) { - // If the controller failed to respond in time, we attempt to recover from this - if (this.handleMissingControllerACK(transaction, error)) return; + } else if ( + isMissingControllerACK(error) || isMissingControllerCallback(error) + ) { + if (this.handleUnresponsiveController(transaction, error)) return; } this.rejectTransaction(transaction, error); diff --git a/packages/zwave-js/src/lib/test/cc-specific/notificationEnums.test.ts b/packages/zwave-js/src/lib/test/cc-specific/notificationEnums.test.ts index fb4eb842d8fb..5f5c696d572c 100644 --- a/packages/zwave-js/src/lib/test/cc-specific/notificationEnums.test.ts +++ b/packages/zwave-js/src/lib/test/cc-specific/notificationEnums.test.ts @@ -7,10 +7,10 @@ import { createMockZWaveRequestFrame } from "@zwave-js/testing"; import { wait } from "alcalzone-shared/async"; import { integrationTest } from "../integrationTestSuite"; -integrationTest.only( +integrationTest( "Notifications with enum event parameters are evaluated correctly", { - debug: true, + // debug: true, nodeCapabilities: { commandClasses: [ diff --git a/packages/zwave-js/src/lib/test/driver/controllerJammed.test.ts b/packages/zwave-js/src/lib/test/driver/controllerJammed.test.ts index 41b631efccae..17c4707ccd5e 100644 --- a/packages/zwave-js/src/lib/test/driver/controllerJammed.test.ts +++ b/packages/zwave-js/src/lib/test/driver/controllerJammed.test.ts @@ -85,7 +85,7 @@ integrationTest("update the controller status and wait if TX status is Fail", { return true; } else if (msg instanceof SendDataAbort) { - // Put the controller into sending state + // Put the controller into idle state controller.state.set( MockControllerStateKeys.CommunicationState, MockControllerCommunicationState.Idle, diff --git a/packages/zwave-js/src/lib/test/driver/nodeAsleepMessageOrder.test.ts b/packages/zwave-js/src/lib/test/driver/nodeAsleepMessageOrder.test.ts index 8399d39f72a1..8d8308c96527 100644 --- a/packages/zwave-js/src/lib/test/driver/nodeAsleepMessageOrder.test.ts +++ b/packages/zwave-js/src/lib/test/driver/nodeAsleepMessageOrder.test.ts @@ -108,10 +108,10 @@ integrationTest( }, ); -integrationTest.only( +integrationTest( "When a sleeping node with pending commands wakes up, the queue continues executing", { - debug: true, + // debug: true, provisioningDirectory: path.join( __dirname, diff --git a/packages/zwave-js/src/lib/test/driver/sendDataAbort.test.ts b/packages/zwave-js/src/lib/test/driver/sendDataAbort.test.ts deleted file mode 100644 index a30ba1e1462c..000000000000 --- a/packages/zwave-js/src/lib/test/driver/sendDataAbort.test.ts +++ /dev/null @@ -1,171 +0,0 @@ -import { CommandClass } from "@zwave-js/cc"; -import { TransmitOptions, ZWaveErrorCodes, isZWaveError } from "@zwave-js/core"; -import { FunctionType, MessageOrigin } from "@zwave-js/serial"; -import { - type MockControllerBehavior, - createMockZWaveRequestFrame, -} from "@zwave-js/testing"; -import { wait } from "alcalzone-shared/async"; -import { - MockControllerCommunicationState, - MockControllerStateKeys, -} from "../../controller/MockControllerState"; -import { - SendDataAbort, - SendDataRequest, - SendDataResponse, -} from "../../serialapi/transport/SendDataMessages"; -import { integrationTest } from "../integrationTestSuite"; - -integrationTest("abort if SendData is missing the callback", { - // debug: true, - // provisioningDirectory: path.join( - // __dirname, - // "__fixtures/supervision_binary_switch", - // ), - - additionalDriverOptions: { - testingHooks: { - skipNodeInterview: true, - }, - }, - - customSetup: async (driver, controller, mockNode) => { - // This is almost a 1:1 copy of the default behavior, except that the callback never gets sent - const handleSendData: MockControllerBehavior = { - async onHostMessage(host, controller, msg) { - if (msg instanceof SendDataRequest) { - // Check if this command is legal right now - const state = controller.state.get( - MockControllerStateKeys.CommunicationState, - ) as MockControllerCommunicationState | undefined; - if ( - state != undefined - && state !== MockControllerCommunicationState.Idle - ) { - throw new Error( - "Received SendDataRequest while not idle", - ); - } - - // Put the controller into sending state - controller.state.set( - MockControllerStateKeys.CommunicationState, - MockControllerCommunicationState.Sending, - ); - - // We deferred parsing of the CC because it requires the node's host to do so. - // Now we can do that. Also set the CC node ID to the controller's own node ID, - // so CC knows it came from the controller's node ID. - const node = controller.nodes.get(msg.getNodeId()!)!; - // Simulate the frame being transmitted via radio - const ackPromise = wait(node.capabilities.txDelay).then( - () => { - // Deserialize on the node after a short delay - try { - msg.command = CommandClass.from(node.host, { - nodeId: controller.host.ownNodeId, - data: msg.payload, - origin: MessageOrigin.Host, - }); - } catch (e) { - let handled = false; - if (isZWaveError(e)) { - // We want to know when we're using a command in tests that cannot be decoded yet - if ( - e.code - === ZWaveErrorCodes - .Deserialization_NotImplemented - ) { - console.error(e.message); - } else if ( - e.code - === ZWaveErrorCodes - .CC_NotImplemented - ) { - // The whole CC is not implemented yet. If this happens in tests, it is because we sent a raw CC. - try { - msg.command = new CommandClass( - host, - { - nodeId: controller.host - .ownNodeId, - ccId: msg.payload[0], - ccCommand: msg.payload[1], - payload: msg.payload - .subarray( - 2, - ), - }, - ); - handled = true; - } catch (e: any) { - console.error(e.message); - } - } - } - - if (!handled) { - console.error(e); - throw e; - } - } - - // Send the data to the node - const frame = createMockZWaveRequestFrame( - msg.command, - { - ackRequested: !!( - msg.transmitOptions - & TransmitOptions.ACK - ), - }, - ); - - return controller.sendToNode(node, frame); - }, - ); - - // Notify the host that the message was sent - const res = new SendDataResponse(host, { - wasSent: true, - }); - await controller.sendToHost(res.serialize()); - - return true; - } else if (msg instanceof SendDataAbort) { - // Put the controller into sending state - controller.state.set( - MockControllerStateKeys.CommunicationState, - MockControllerCommunicationState.Idle, - ); - } - }, - }; - controller.defineBehavior(handleSendData); - }, - testBody: async (t, driver, node, mockController, mockNode) => { - // Circumvent the options validation so the test doesn't take forever - driver.options.timeouts.sendDataCallback = 1500; - - let pingResult: boolean; - pingResult = await node.ping(); - t.false(pingResult); - - mockController.assertReceivedHostMessage( - (msg) => msg.functionType === FunctionType.SendDataAbort, - ); - mockController.clearReceivedHostMessages(); - - pingResult = await node.ping(); - t.false(pingResult); - - mockController.assertReceivedHostMessage( - (msg) => msg.functionType === FunctionType.SendDataAbort, - ); - mockController.clearReceivedHostMessages(); - - // The test doesn't get stuck in an infinite loop - t.pass(); - }, -}); diff --git a/packages/zwave-js/src/lib/test/driver/sendDataMissingCallbackAbort.test.ts b/packages/zwave-js/src/lib/test/driver/sendDataMissingCallbackAbort.test.ts new file mode 100644 index 000000000000..82cca7e252d3 --- /dev/null +++ b/packages/zwave-js/src/lib/test/driver/sendDataMissingCallbackAbort.test.ts @@ -0,0 +1,215 @@ +import { FunctionType } from "@zwave-js/serial"; +import { type MockControllerBehavior } from "@zwave-js/testing"; +import { wait } from "alcalzone-shared/async"; +import { + MockControllerCommunicationState, + MockControllerStateKeys, +} from "../../controller/MockControllerState"; + +import { ZWaveErrorCodes, assertZWaveError } from "@zwave-js/core"; +import Sinon from "sinon"; +import { SoftResetRequest } from "../../serialapi/misc/SoftResetRequest"; +import { + SendDataAbort, + SendDataRequest, + SendDataResponse, +} from "../../serialapi/transport/SendDataMessages"; +import { integrationTest } from "../integrationTestSuite"; + +let shouldTimeOut: boolean; + +integrationTest( + "Abort transmission and soft-reset stick if SendData is missing the callback", + { + // debug: true, + + // provisioningDirectory: path.join( + // __dirname, + // "__fixtures/supervision_binary_switch", + // ), + + additionalDriverOptions: { + testingHooks: { + skipNodeInterview: true, + }, + }, + + customSetup: async (driver, mockController, mockNode) => { + // This is almost a 1:1 copy of the default behavior, except that the callback never gets sent + const handleBrokenSendData: MockControllerBehavior = { + async onHostMessage(host, controller, msg) { + // If the controller is operating normally, defer to the default behavior + if (!shouldTimeOut) return false; + + if (msg instanceof SendDataRequest) { + // Check if this command is legal right now + const state = controller.state.get( + MockControllerStateKeys.CommunicationState, + ) as MockControllerCommunicationState | undefined; + if ( + state != undefined + && state !== MockControllerCommunicationState.Idle + ) { + throw new Error( + "Received SendDataRequest while not idle", + ); + } + + // Put the controller into sending state + controller.state.set( + MockControllerStateKeys.CommunicationState, + MockControllerCommunicationState.Sending, + ); + + // Notify the host that the message was sent + const res = new SendDataResponse(host, { + wasSent: true, + }); + await controller.sendToHost(res.serialize()); + + return true; + } else if (msg instanceof SendDataAbort) { + // Put the controller into idle state + controller.state.set( + MockControllerStateKeys.CommunicationState, + MockControllerCommunicationState.Idle, + ); + + return true; + } + }, + }; + mockController.defineBehavior(handleBrokenSendData); + + const handleSoftReset: MockControllerBehavior = { + onHostMessage(host, controller, msg) { + // Soft reset should restore normal operation + if (msg instanceof SoftResetRequest) { + shouldTimeOut = false; + return true; + } + }, + }; + mockController.defineBehavior(handleSoftReset); + }, + testBody: async (t, driver, node, mockController, mockNode) => { + // Circumvent the options validation so the test doesn't take forever + driver.options.timeouts.sendDataCallback = 1500; + + shouldTimeOut = true; + + const pingPromise = node.ping(); + + await wait(2000); + + mockController.assertReceivedHostMessage( + (msg) => msg.functionType === FunctionType.SendDataAbort, + ); + mockController.clearReceivedHostMessages(); + + // The stick should have been soft-reset + await wait(1000); + mockController.assertReceivedHostMessage( + (msg) => msg.functionType === FunctionType.SoftReset, + ); + + // And the ping should eventually succeed + t.true(await pingPromise); + }, + }, +); + +integrationTest( + "Destroy driver if SendData is still missing the callback after soft-reset", + { + // debug: true, + + // provisioningDirectory: path.join( + // __dirname, + // "__fixtures/supervision_binary_switch", + // ), + + additionalDriverOptions: { + testingHooks: { + skipNodeInterview: true, + }, + }, + + customSetup: async (driver, mockController, mockNode) => { + // This is almost a 1:1 copy of the default behavior, except that the callback never gets sent + const handleBrokenSendData: MockControllerBehavior = { + async onHostMessage(host, controller, msg) { + if (msg instanceof SendDataRequest) { + // Check if this command is legal right now + const state = controller.state.get( + MockControllerStateKeys.CommunicationState, + ) as MockControllerCommunicationState | undefined; + if ( + state != undefined + && state !== MockControllerCommunicationState.Idle + ) { + throw new Error( + "Received SendDataRequest while not idle", + ); + } + + // Put the controller into sending state + controller.state.set( + MockControllerStateKeys.CommunicationState, + MockControllerCommunicationState.Sending, + ); + + // Notify the host that the message was sent + const res = new SendDataResponse(host, { + wasSent: true, + }); + await controller.sendToHost(res.serialize()); + + return true; + } else if (msg instanceof SendDataAbort) { + // Put the controller into idle state + controller.state.set( + MockControllerStateKeys.CommunicationState, + MockControllerCommunicationState.Idle, + ); + + return true; + } + }, + }; + mockController.defineBehavior(handleBrokenSendData); + }, + testBody: async (t, driver, node, mockController, mockNode) => { + // Circumvent the options validation so the test doesn't take forever + driver.options.timeouts.sendDataCallback = 1500; + shouldTimeOut = true; + + const errorSpy = Sinon.spy(); + driver.on("error", errorSpy); + + const pingPromise = node.ping(); + + await wait(2000); + + mockController.assertReceivedHostMessage( + (msg) => msg.functionType === FunctionType.SendDataAbort, + ); + mockController.clearReceivedHostMessages(); + + // The stick should have been soft-reset + await wait(1000); + mockController.assertReceivedHostMessage( + (msg) => msg.functionType === FunctionType.SoftReset, + ); + + // The ping should eventually fail + t.false(await pingPromise); + + // The driver should have been destroyed + await wait(100); + assertZWaveError(t, errorSpy.getCall(0).args[0], { + errorCode: ZWaveErrorCodes.Driver_Failed, + }); + }, + }, +); diff --git a/packages/zwave-js/src/lib/test/driver/unresponsiveStick.test.ts b/packages/zwave-js/src/lib/test/driver/unresponsiveStick.test.ts index 7d5388bb4393..3d95d6dd6f62 100644 --- a/packages/zwave-js/src/lib/test/driver/unresponsiveStick.test.ts +++ b/packages/zwave-js/src/lib/test/driver/unresponsiveStick.test.ts @@ -1,5 +1,7 @@ import { ZWaveErrorCodes, assertZWaveError } from "@zwave-js/core"; import { type MockControllerBehavior } from "@zwave-js/testing"; +import { wait } from "alcalzone-shared/async"; +import Sinon from "sinon"; import { GetControllerIdRequest, type GetControllerIdResponse, @@ -72,6 +74,9 @@ integrationTest( shouldRespond = false; mockController.autoAckHostMessages = false; + const errorSpy = Sinon.spy(); + driver.on("error", errorSpy); + await assertZWaveError( t, () => @@ -84,6 +89,12 @@ integrationTest( context: "ACK", }, ); + + // The driver should have been destroyed + await wait(100); + assertZWaveError(t, errorSpy.getCall(0).args[0], { + errorCode: ZWaveErrorCodes.Driver_Failed, + }); }, }, );