feat: compute message RTT, time out node updates faster (#3756)

packages/zwave-js/src/lib/driver/CommandQueueMachine.ts

@@ -334,15 +334,15 @@ 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!,
 							implementations,
 							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,

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

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<Message, Message, Message>;
 
 export async function waitForNodeUpdate<T extends Message>(
 	driver: Driver,
 	msg: Message,
+	timeoutMs: number,
 ): Promise<T> {
 	try {
 		return await driver.waitForMessage<T>((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<T extends Message>(
 
 /** 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<SecurityCCNonceReport>(
 					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<Security2CCNonceReport>(
 					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) &&

packages/zwave-js/src/lib/driver/SerialAPICommandMachine.ts

@@ -320,7 +320,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",

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

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 */

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;
 }

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 = {