diff --git a/packages/zwave-js/src/lib/driver/CommandQueueMachine.ts b/packages/zwave-js/src/lib/driver/CommandQueueMachine.ts index c9dda1742b36..d01b96b8681d 100644 --- a/packages/zwave-js/src/lib/driver/CommandQueueMachine.ts +++ b/packages/zwave-js/src/lib/driver/CommandQueueMachine.ts @@ -330,8 +330,6 @@ export function createCommandQueueMachine( { services: { executeSerialAPICommand: (ctx) => { - // If there is an error while creating the command machine (e.g. during message serialization) - // wrap it in a rejected promise, so xstate can handle it try { return createSerialAPICommandMachine( ctx.currentTransaction!.parts.current!, @@ -339,6 +337,8 @@ export function createCommandQueueMachine( params, ); } catch (e) { + // If there is an error while creating the command machine (e.g. during message serialization) + // wrap it in a rejected promise, so xstate can handle it implementations.log( `Unexpected error during SerialAPI command: ${getErrorMessage( e, diff --git a/packages/zwave-js/src/lib/driver/Driver.ts b/packages/zwave-js/src/lib/driver/Driver.ts index 04fa625dd5cc..9a800b14673c 100644 --- a/packages/zwave-js/src/lib/driver/Driver.ts +++ b/packages/zwave-js/src/lib/driver/Driver.ts @@ -43,6 +43,7 @@ import { createDeferredPromise, DeferredPromise, } from "alcalzone-shared/deferred-promise"; +import { roundTo } from "alcalzone-shared/math"; import { isArray, isObject } from "alcalzone-shared/typeguards"; import { randomBytes } from "crypto"; import type { EventEmitter } from "events"; @@ -190,7 +191,7 @@ const defaultOptions: ZWaveOptions = { ack: 1000, byte: 150, response: 1600, - report: 10000, + report: 1000, // ReportTime timeout SHOULD be set to CommandTime + 1 second nonce: 5000, sendDataCallback: 65000, // as defined in INS13954 refreshValue: 5000, // Default should handle most slow devices until we have a better solution @@ -244,9 +245,9 @@ function checkOptions(options: ZWaveOptions): void { ZWaveErrorCodes.Driver_InvalidOptions, ); } - if (options.timeouts.report < 1000 || options.timeouts.report > 40000) { + if (options.timeouts.report < 500 || options.timeouts.report > 10000) { throw new ZWaveError( - `The Report timeout must be between 1000 and 40000 milliseconds!`, + `The Report timeout must be between 500 and 10000 milliseconds!`, ZWaveErrorCodes.Driver_InvalidOptions, ); } @@ -3262,6 +3263,19 @@ ${handlers.length} left`, node.incrementStatistics("commandsDroppedTX"); } else { node.incrementStatistics("commandsTX"); + if (msg.rtt) { + const rttMs = msg.rtt / 1e6; + node.updateStatistics((current) => ({ + ...current, + rtt: + current.rtt != undefined + ? roundTo( + current.rtt * 0.9 + rttMs * 0.1, + 1, + ) + : roundTo(rttMs, 1), + })); + } } // Notify listeners about the status report if one was received diff --git a/packages/zwave-js/src/lib/driver/MessageGenerators.ts b/packages/zwave-js/src/lib/driver/MessageGenerators.ts index 05058f8bad07..86d4c4b5d8aa 100644 --- a/packages/zwave-js/src/lib/driver/MessageGenerators.ts +++ b/packages/zwave-js/src/lib/driver/MessageGenerators.ts @@ -31,16 +31,20 @@ export type MessageGeneratorImplementation = ( * without waiting for the message generator to finish completely. */ onMessageSent: (msg: Message, result: Message | undefined) => void, + + /** Can be used to extend the timeout wa */ + additionalCommandTimeoutMs?: number, ) => AsyncGenerator; export async function waitForNodeUpdate( driver: Driver, msg: Message, + timeoutMs: number, ): Promise { try { return await driver.waitForMessage((received) => { return msg.isExpectedNodeUpdate(received); - }, driver.options.timeouts.report); + }, timeoutMs); } catch (e) { throw new ZWaveError( `Timed out while waiting for a response from the node`, @@ -51,14 +55,26 @@ export async function waitForNodeUpdate( /** A simple message generator that simply sends a message, waits for the ACK (and the response if one is expected) */ export const simpleMessageGenerator: MessageGeneratorImplementation = - async function* (driver, msg, onMessageSent) { + async function* ( + driver, + msg, + onMessageSent, + additionalCommandTimeoutMs = 0, + ) { // Pass this message to the send thread and wait for it to be sent let result: Message; + let commandTimeMs: number; try { // The yield can throw and must be handled here result = yield msg; + + // Figure out how long the message took to be handled + msg.markAsCompleted(); + commandTimeMs = Math.ceil(msg.rtt! / 1e6); + onMessageSent(msg, result); } catch (e) { + msg.markAsCompleted(); throw e; } @@ -74,7 +90,13 @@ export const simpleMessageGenerator: MessageGeneratorImplementation = // If the sent message expects an update from the node, wait for it if (msg.expectsNodeUpdate()) { - return waitForNodeUpdate(driver, msg); + // CommandTime is measured by the application + // ReportTime timeout SHOULD be set to CommandTime + 1 second. + const timeout = + commandTimeMs + + driver.options.timeouts.report + + additionalCommandTimeoutMs; + return waitForNodeUpdate(driver, msg, timeout); } return result; @@ -121,6 +143,7 @@ export const secureMessageGeneratorS0: MessageGeneratorImplementation = // Step 1: Acquire a nonce const secMan = driver.securityManager!; const nodeId = msg.command.nodeId; + let additionalTimeoutMs: number | undefined; // Try to get a free nonce before requesting a new one let nonce: Buffer | undefined = secMan.getFreeNonce(nodeId); @@ -134,7 +157,10 @@ export const secureMessageGeneratorS0: MessageGeneratorImplementation = yield* sendCommandGenerator( driver, cc, - onMessageSent, + (msg, result) => { + additionalTimeoutMs = Math.ceil(msg.rtt! / 1e6); + onMessageSent(msg, result); + }, { // Only try getting a nonce once maxSendAttempts: 1, @@ -151,7 +177,12 @@ export const secureMessageGeneratorS0: MessageGeneratorImplementation = msg.command.nonce = nonce; // Now send the actual secure command - return yield* simpleMessageGenerator(driver, msg, onMessageSent); + return yield* simpleMessageGenerator( + driver, + msg, + onMessageSent, + additionalTimeoutMs, + ); }; /** A message generator for security encapsulated messages (S2) */ @@ -177,6 +208,7 @@ export const secureMessageGeneratorS2: MessageGeneratorImplementation = const secMan = driver.securityManager2!; const nodeId = msg.command.nodeId; const spanState = secMan.getSPANState(nodeId); + let additionalTimeoutMs: number | undefined; if ( spanState.type === SPANState.None || @@ -193,7 +225,10 @@ export const secureMessageGeneratorS2: MessageGeneratorImplementation = yield* sendCommandGenerator( driver, cc, - onMessageSent, + (msg, result) => { + additionalTimeoutMs = Math.ceil(msg.rtt! / 1e6); + onMessageSent(msg, result); + }, { // Only try getting a nonce once maxSendAttempts: 1, @@ -214,6 +249,7 @@ export const secureMessageGeneratorS2: MessageGeneratorImplementation = driver, msg, onMessageSent, + additionalTimeoutMs, ); if ( isCommandClassContainer(response) && @@ -238,6 +274,7 @@ export const secureMessageGeneratorS2: MessageGeneratorImplementation = driver, msg, onMessageSent, + additionalTimeoutMs, ); if ( isCommandClassContainer(response) && diff --git a/packages/zwave-js/src/lib/driver/SerialAPICommandMachine.ts b/packages/zwave-js/src/lib/driver/SerialAPICommandMachine.ts index 853921e03fcd..79239645c0b7 100644 --- a/packages/zwave-js/src/lib/driver/SerialAPICommandMachine.ts +++ b/packages/zwave-js/src/lib/driver/SerialAPICommandMachine.ts @@ -316,7 +316,11 @@ export function getSerialAPICommandMachineOptions( ): SerialAPICommandMachineOptions { return { services: { - send: (ctx) => sendData(ctx.data), + send: (ctx) => { + // Mark the message as sent immediately before actually sending + ctx.msg.markAsSent(); + return sendData(ctx.data); + }, notifyRetry: (ctx) => { notifyRetry?.( "SerialAPI", diff --git a/packages/zwave-js/src/lib/driver/ZWaveOptions.ts b/packages/zwave-js/src/lib/driver/ZWaveOptions.ts index d2a4277cb1b2..15325198b1ca 100644 --- a/packages/zwave-js/src/lib/driver/ZWaveOptions.ts +++ b/packages/zwave-js/src/lib/driver/ZWaveOptions.ts @@ -20,7 +20,7 @@ export interface ZWaveOptions { sendDataCallback: number; // >=10000, default: 65000 ms /** How much time a node gets to process a request and send a response */ - report: number; // [1000...40000], default: 10000 ms + report: number; // [500...10000], default: 1000 ms /** How long generated nonces are valid */ nonce: number; // [3000...20000], default: 5000 ms diff --git a/packages/zwave-js/src/lib/message/Message.ts b/packages/zwave-js/src/lib/message/Message.ts index 89dfe0001aa1..52e7c7d5490b 100644 --- a/packages/zwave-js/src/lib/message/Message.ts +++ b/packages/zwave-js/src/lib/message/Message.ts @@ -2,6 +2,7 @@ import { getNodeTag, + highResTimestamp, MessageOrCCLogEntry, ZWaveError, ZWaveErrorCodes, @@ -367,6 +368,35 @@ export class Message { if (nodeId != undefined) return this.driver.controller.nodes.get(nodeId); } + + private _transmissionTimestamp: number | undefined; + /** The timestamp when this message was (last) transmitted (in nanoseconds) */ + public get transmissionTimestamp(): number | undefined { + return this._transmissionTimestamp; + } + + /** Marks this message as sent and sets the transmission timestamp */ + public markAsSent(): void { + this._transmissionTimestamp = highResTimestamp(); + this._completedTimestamp = undefined; + } + + private _completedTimestamp: number | undefined; + public get completedTimestamp(): number | undefined { + return this._completedTimestamp; + } + + /** Marks this message as completed and sets the corresponding timestamp */ + public markAsCompleted(): void { + this._completedTimestamp = highResTimestamp(); + } + + /** Returns the round trip time of this message from transmission until completion. */ + public get rtt(): number | undefined { + if (this._transmissionTimestamp == undefined) return undefined; + if (this._completedTimestamp == undefined) return undefined; + return this._completedTimestamp - this._transmissionTimestamp; + } } /** Computes the checksum for a serialized message as defined in the Z-Wave specs */ diff --git a/packages/zwave-js/src/lib/node/NodeStatistics.ts b/packages/zwave-js/src/lib/node/NodeStatistics.ts index 063401bbb902..a75bb1602b99 100644 --- a/packages/zwave-js/src/lib/node/NodeStatistics.ts +++ b/packages/zwave-js/src/lib/node/NodeStatistics.ts @@ -30,4 +30,10 @@ export interface NodeStatistics { commandsDroppedTX: number; /** No. of Get-type commands where the node's response did not come in time */ timeoutResponse: number; + + /** + * Average round-trip-time in ms of commands to this node. + * Consecutive measurements are combined using an exponential moving average. + */ + rtt?: number; } diff --git a/packages/zwave-js/src/lib/test/messages.ts b/packages/zwave-js/src/lib/test/messages.ts index 8ea845704c29..eceef0732f2e 100644 --- a/packages/zwave-js/src/lib/test/messages.ts +++ b/packages/zwave-js/src/lib/test/messages.ts @@ -17,6 +17,8 @@ const defaultImplementations = { toLogEntry: () => ({ tags: [] }), needsCallbackId: () => true, getCallbackTimeout: () => undefined, + markAsSent: () => void 0, + markAsCompleted: () => void 0, }; export const dummyResponseOK = {