diff --git a/src/adapter/ember/adapter/emberAdapter.ts b/src/adapter/ember/adapter/emberAdapter.ts index 3b59ef9512..c0966d15c0 100644 --- a/src/adapter/ember/adapter/emberAdapter.ts +++ b/src/adapter/ember/adapter/emberAdapter.ts @@ -6,6 +6,7 @@ import equals from "fast-deep-equal/es6"; import type {Backup} from "../../../models"; import {BackupUtils, Queue, wait} from "../../../utils"; import {logger} from "../../../utils/logger"; +import {metrics} from "../../../utils/metrics"; import * as ZSpec from "../../../zspec"; import type {Eui64, ExtendedPanId, NodeId, PanId} from "../../../zspec/tstypes"; import * as Zcl from "../../../zspec/zcl"; @@ -2007,6 +2008,8 @@ export class EmberAdapter extends Adapter { } if (status === SLStatus.ZIGBEE_MAX_MESSAGE_LIMIT_REACHED || status === SLStatus.BUSY) { + /* v8 ignore next */ + metrics.emit("adapterRetry", {adapterType: "ember", ieeeAddr, reason: SLStatus[status] ?? String(status)}); await wait(QUEUE_BUSY_DEFER_MSEC); } else if (status === SLStatus.NETWORK_DOWN) { await wait(QUEUE_NETWORK_DOWN_DEFER_MSEC); diff --git a/src/adapter/z-stack/adapter/zStackAdapter.ts b/src/adapter/z-stack/adapter/zStackAdapter.ts index e5f7256e6e..9091568ec6 100644 --- a/src/adapter/z-stack/adapter/zStackAdapter.ts +++ b/src/adapter/z-stack/adapter/zStackAdapter.ts @@ -3,6 +3,7 @@ import debounce from "debounce"; import type * as Models from "../../../models"; import {Queue, Waitress, wait} from "../../../utils"; import {logger} from "../../../utils/logger"; +import {metrics} from "../../../utils/metrics"; import * as ZSpec from "../../../zspec"; import type {BroadcastAddress} from "../../../zspec/enums"; import type {Eui64} from "../../../zspec/tstypes"; @@ -584,6 +585,12 @@ export class ZStackAdapter extends Adapter { * MAC_NO_RESOURCES: Operation could not be completed because no memory resources are available, * wait some time and retry. */ + metrics.emit("adapterRetry", { + adapterType: "zstack", + ieeeAddr, + /* v8 ignore next */ + reason: ZnpCommandStatus[dataConfirmResult] ?? String(dataConfirmResult), + }); await wait(2000); return await this.sendZclFrameToEndpointInternal( ieeeAddr, @@ -665,6 +672,8 @@ export class ZStackAdapter extends Adapter { await wait(2000); } + /* v8 ignore next */ + metrics.emit("adapterRetry", {adapterType: "zstack", ieeeAddr, reason: ZnpCommandStatus[dataConfirmResult] ?? String(dataConfirmResult)}); return await this.sendZclFrameToEndpointInternal( ieeeAddr, networkAddress, @@ -716,6 +725,7 @@ export class ZStackAdapter extends Adapter { }); } // No response could be of invalid route, e.g. when message is send to wrong parent of end device. + metrics.emit("adapterRetry", {adapterType: "zstack", ieeeAddr, reason: "no_response"}); await this.discoverRoute(networkAddress); return await this.sendZclFrameToEndpointInternal( ieeeAddr, diff --git a/src/adapter/zboss/adapter/zbossAdapter.ts b/src/adapter/zboss/adapter/zbossAdapter.ts index e170709d47..3dfaa09222 100644 --- a/src/adapter/zboss/adapter/zbossAdapter.ts +++ b/src/adapter/zboss/adapter/zbossAdapter.ts @@ -4,6 +4,7 @@ import assert from "node:assert"; import type {Backup} from "../../../models"; import {Queue, Waitress} from "../../../utils"; import {logger} from "../../../utils/logger"; +import {metrics} from "../../../utils/metrics"; import * as ZSpec from "../../../zspec"; import * as Zcl from "../../../zspec/zcl"; import * as Zdo from "../../../zspec/zdo"; @@ -387,6 +388,7 @@ export class ZBOSSAdapter extends Adapter { } catch (error) { logger.debug(`Response timeout (${ieeeAddr}:${networkAddress},${responseAttempt})`, NS); if (responseAttempt < 1 && !disableRecovery) { + metrics.emit("adapterRetry", {adapterType: "zboss", ieeeAddr, reason: "no_response"}); return await this.sendZclFrameToEndpointInternal( ieeeAddr, networkAddress, diff --git a/src/adapter/zigate/adapter/zigateAdapter.ts b/src/adapter/zigate/adapter/zigateAdapter.ts index 26b62bed6c..e919b84324 100644 --- a/src/adapter/zigate/adapter/zigateAdapter.ts +++ b/src/adapter/zigate/adapter/zigateAdapter.ts @@ -3,6 +3,7 @@ import type * as Models from "../../../models"; import {Queue, Waitress, wait} from "../../../utils"; import {logger} from "../../../utils/logger"; +import {metrics} from "../../../utils/metrics"; import * as ZSpec from "../../../zspec"; import type {BroadcastAddress} from "../../../zspec/enums"; import * as Zcl from "../../../zspec/zcl"; @@ -368,6 +369,7 @@ export class ZiGateAdapter extends Adapter { } catch { if (responseAttempt < 1 && !disableRecovery) { // @todo discover route + metrics.emit("adapterRetry", {adapterType: "zigate", ieeeAddr, reason: "send_failure"}); return await this.sendZclFrameToEndpointInternal( ieeeAddr, networkAddress, @@ -395,6 +397,7 @@ export class ZiGateAdapter extends Adapter { } catch (error) { logger.error(`Response error ${(error as Error).message} (${ieeeAddr}:${networkAddress},${responseAttempt})`, NS); if (responseAttempt < 1 && !disableRecovery) { + metrics.emit("adapterRetry", {adapterType: "zigate", ieeeAddr, reason: "no_response"}); return await this.sendZclFrameToEndpointInternal( ieeeAddr, networkAddress, diff --git a/src/adapter/zoh/adapter/zohAdapter.ts b/src/adapter/zoh/adapter/zohAdapter.ts index ea5491f0bb..5f294d4b0d 100644 --- a/src/adapter/zoh/adapter/zohAdapter.ts +++ b/src/adapter/zoh/adapter/zohAdapter.ts @@ -8,6 +8,7 @@ import type {ZigbeeAPSHeader, ZigbeeAPSPayload} from "zigbee-on-host/dist/zigbee import type {ZigbeeNWKGPHeader} from "zigbee-on-host/dist/zigbee/zigbee-nwkgp"; import type {Backup} from "../../../models/backup"; import {logger} from "../../../utils/logger"; +import {metrics} from "../../../utils/metrics"; import {Queue} from "../../../utils/queue"; import {wait} from "../../../utils/wait"; import {Waitress} from "../../../utils/waitress"; @@ -646,6 +647,7 @@ export class ZoHAdapter extends Adapter { if (disableRecovery || i === 1) { throw error; } // else retry + metrics.emit("adapterRetry", {adapterType: "zoh", ieeeAddr, reason: "send_failure"}); } /* v8 ignore start */ } // coverage detection failure diff --git a/src/controller/controller.ts b/src/controller/controller.ts index a9cb232790..4087a524f4 100644 --- a/src/controller/controller.ts +++ b/src/controller/controller.ts @@ -5,6 +5,7 @@ import {Adapter, type Events as AdapterEvents, type TsType as AdapterTsType} fro import type {ZclPayload} from "../adapter/events"; import {BackupUtils, wait} from "../utils"; import {logger} from "../utils/logger"; +import {metrics, type SendStatus} from "../utils/metrics.js"; import {isNumberArrayOfLength} from "../utils/utils"; import * as ZSpec from "../zspec"; import type {Eui64} from "../zspec/tstypes"; @@ -28,6 +29,18 @@ import type {DeviceType, GreenPowerDeviceJoinedPayload, RawPayload} from "./tsty const NS = "zh:controller"; +async function instrumentSend(fn: () => Promise, record: (status: SendStatus, durationSeconds: number) => void): Promise { + const start = Date.now(); + try { + const result = await fn(); + record("success", (Date.now() - start) / 1000); + return result; + } catch (e) { + record("failure", (Date.now() - start) / 1000); + throw e; + } +} + interface Options { network: AdapterTsType.NetworkOptions; serialPort: AdapterTsType.SerialPortOptions; @@ -280,7 +293,11 @@ export class Controller extends events.EventEmitter { // will fail if args are incorrect for request const buf = Zdo.Buffalo.buildRequest(this.adapter.hasZdoMessageOverhead, clusterKey, ...zdoParams); - return (await this.adapter.sendZdo(ieeeAddress, networkAddress, clusterKey, buf, disableResponse)) as ZdoTypes.GenericZdoResponse; + return (await instrumentSend( + () => this.adapter.sendZdo(ieeeAddress, networkAddress, clusterKey, buf, disableResponse), + (status, durationSeconds) => + metrics.emit("adapterSendZdo", {ieeeAddr: ieeeAddress, clusterId: clusterKey as number, status, durationSeconds}), + )) as ZdoTypes.GenericZdoResponse; } assert(zcl); @@ -330,7 +347,10 @@ export class Controller extends events.EventEmitter { if (groupId !== undefined) { assert(groupId >= 0x0000 && groupId <= 0xffff); - await this.adapter.sendZclFrameToGroup(groupId, zclFrame, srcEndpoint, profileId); + await instrumentSend( + () => this.adapter.sendZclFrameToGroup(groupId, zclFrame, srcEndpoint, profileId), + (status, durationSeconds) => metrics.emit("adapterSendZclGroup", {groupId, status, durationSeconds}), + ); return; } @@ -339,22 +359,29 @@ export class Controller extends events.EventEmitter { assert(networkAddress !== undefined && networkAddress >= 0x0000 && networkAddress <= 0xffff); if (networkAddress >= ZSpec.BROADCAST_MIN) { - await this.adapter.sendZclFrameToAll(dstEndpoint, zclFrame, srcEndpoint, networkAddress, profileId); + await instrumentSend( + () => this.adapter.sendZclFrameToAll(dstEndpoint, zclFrame, srcEndpoint, networkAddress, profileId), + (status, durationSeconds) => metrics.emit("adapterSendZclBroadcast", {status, durationSeconds}), + ); return; } assert(ieeeAddress); - return await this.adapter.sendZclFrameToEndpoint( - ieeeAddress, - networkAddress, - dstEndpoint, - zclFrame, - timeout, - disableResponse, - false, - srcEndpoint, - profileId, + return await instrumentSend( + () => + this.adapter.sendZclFrameToEndpoint( + ieeeAddress, + networkAddress, + dstEndpoint, + zclFrame, + timeout, + disableResponse, + false, + srcEndpoint, + profileId, + ), + (status, durationSeconds) => metrics.emit("adapterSendZclUnicast", {ieeeAddr: ieeeAddress, status, durationSeconds}), ); } @@ -623,7 +650,10 @@ export class Controller extends events.EventEmitter { undefined, ); - await this.adapter.sendZdo(ZSpec.BLANK_EUI64, ZSpec.BroadcastAddress.SLEEPY, clusterId, zdoPayload, true); + await instrumentSend( + () => this.adapter.sendZdo(ZSpec.BLANK_EUI64, ZSpec.BroadcastAddress.SLEEPY, clusterId, zdoPayload, true), + (status, durationSeconds) => metrics.emit("adapterSendZdo", {ieeeAddr: ZSpec.BLANK_EUI64, clusterId, status, durationSeconds}), + ); logger.info(`Channel changed to '${newChannel}'`, NS); this.networkParametersCached = undefined; // invalidate cache @@ -644,7 +674,10 @@ export class Controller extends events.EventEmitter { const zdoPayload = Zdo.Buffalo.buildRequest(this.adapter.hasZdoMessageOverhead, clusterId, nwkAddress, false, 0); try { - const response = await this.adapter.sendZdo(ZSpec.BLANK_EUI64, nwkAddress, clusterId, zdoPayload, false); + const response = await instrumentSend( + () => this.adapter.sendZdo(ZSpec.BLANK_EUI64, nwkAddress, clusterId, zdoPayload, false), + (status, durationSeconds) => metrics.emit("adapterSendZdo", {ieeeAddr: ZSpec.BLANK_EUI64, clusterId, status, durationSeconds}), + ); if (Zdo.Buffalo.checkStatus(response)) { const payload = response[1]; @@ -904,6 +937,7 @@ export class Controller extends events.EventEmitter { } private onZdoResponse(clusterId: Zdo.ClusterId, response: ZdoTypes.GenericZdoResponse): void { + metrics.emit("adapterReceiveZdoResponse", {clusterId}); logger.debug( `Received ZDO response: clusterId=${Zdo.ClusterId[clusterId]}, status=${Zdo.Status[response[0]]}, payload=${JSON.stringify(response[1])}`, NS, @@ -943,6 +977,12 @@ export class Controller extends events.EventEmitter { return; } + metrics.emit("adapterReceiveZclPayload", { + ieeeAddr: typeof payload.address === "string" ? payload.address : undefined, + clusterID: payload.clusterID, + wasBroadcast: payload.wasBroadcast, + }); + if (payload.clusterID === Zcl.Clusters.greenPower.ID) { try { // Custom clusters are not supported for Green Power since we need to parse the frame to get the device. diff --git a/src/controller/helpers/request.ts b/src/controller/helpers/request.ts index 776fe41896..57e8f4c165 100644 --- a/src/controller/helpers/request.ts +++ b/src/controller/helpers/request.ts @@ -32,6 +32,7 @@ export class Request { private func: () => Promise; frame: Zcl.Frame; expires: number; + enqueuedAt: number | undefined; sendPolicy: SendPolicy | undefined; private resolveQueue: Array<(value: Type) => void>; private rejectQueue: Array<(error: Error) => void>; @@ -49,6 +50,7 @@ export class Request { this.func = func; this.frame = frame; this.expires = timeout + Date.now(); + this.enqueuedAt = undefined; this.sendPolicy = sendPolicy ?? (!frame.command ? undefined : Request.defaultSendPolicy[frame.command.ID]); this.resolveQueue = resolve === undefined ? ([] as ((value: Type) => void)[]) : new Array<(value: Type) => void>(resolve); this.rejectQueue = reject === undefined ? ([] as ((error: Error) => void)[]) : new Array<(error: Error) => void>(reject); diff --git a/src/controller/helpers/requestQueue.ts b/src/controller/helpers/requestQueue.ts index f4ee731518..d942fb776f 100755 --- a/src/controller/helpers/requestQueue.ts +++ b/src/controller/helpers/requestQueue.ts @@ -1,5 +1,6 @@ import equal from "fast-deep-equal/es6"; import {logger} from "../../utils/logger"; +import {metrics} from "../../utils/metrics"; import type * as Zcl from "../../zspec/zcl"; import type {Endpoint} from "../model"; import type Request from "./request"; @@ -36,6 +37,15 @@ export class RequestQueue extends Set { logger.debug(`Request Queue (${this.deviceIeeeAddress}/${this.id}): discard after timeout. Size before: ${this.size}`, NS); request.reject(); this.delete(request); + metrics.emit("requestQueueLength", {ieeeAddr: this.deviceIeeeAddress, endpointId: this.id, length: this.size}); + if (request.enqueuedAt !== undefined) { + metrics.emit("requestQueueDuration", { + ieeeAddr: this.deviceIeeeAddress, + endpointId: this.id, + outcome: "expired", + durationSeconds: (now - request.enqueuedAt) / 1000, + }); + } } } @@ -48,6 +58,15 @@ export class RequestQueue extends Set { logger.debug(`Request Queue (${this.deviceIeeeAddress}/${this.id}): send success`, NS); request.resolve(result); this.delete(request); + metrics.emit("requestQueueLength", {ieeeAddr: this.deviceIeeeAddress, endpointId: this.id, length: this.size}); + if (request.enqueuedAt !== undefined) { + metrics.emit("requestQueueDuration", { + ieeeAddr: this.deviceIeeeAddress, + endpointId: this.id, + outcome: "sent", + durationSeconds: (Date.now() - request.enqueuedAt) / 1000, + }); + } } catch (error) { logger.debug( `Request Queue (${this.deviceIeeeAddress}/${this.id}): send failed, expires in ` + @@ -65,6 +84,8 @@ export class RequestQueue extends Set { return await new Promise((resolve, reject): void => { request.addCallbacks(resolve, reject); this.add(request); + request.enqueuedAt = Date.now(); + metrics.emit("requestQueueLength", {ieeeAddr: this.deviceIeeeAddress, endpointId: this.id, length: this.size}); }); } diff --git a/src/index.ts b/src/index.ts index e331cc3051..251d3024ba 100644 --- a/src/index.ts +++ b/src/index.ts @@ -8,6 +8,8 @@ export {getOtaFirmware, getOtaIndex, parseOtaHeader, parseOtaImage, parseOtaSubE export type * as Models from "./controller/model"; export type * as Types from "./controller/tstype"; export {setLogger} from "./utils/logger"; +export type {MetricsEventMap} from "./utils/metrics"; +export {metrics} from "./utils/metrics"; export {getTimeClusterAttributes} from "./utils/timeService"; export * as ZSpec from "./zspec"; export * as Zcl from "./zspec/zcl"; diff --git a/src/utils/metrics.ts b/src/utils/metrics.ts new file mode 100644 index 0000000000..ce1faf7d91 --- /dev/null +++ b/src/utils/metrics.ts @@ -0,0 +1,70 @@ +import {EventEmitter} from "node:events"; + +export type SendStatus = "success" | "failure"; + +export interface AdapterSendZclUnicastPayload { + ieeeAddr: string; + status: SendStatus; + durationSeconds: number; +} + +export interface AdapterSendZdoPayload { + ieeeAddr: string; + clusterId: number; + status: SendStatus; + durationSeconds: number; +} + +export interface AdapterSendZclGroupPayload { + groupId: number; + status: SendStatus; + durationSeconds: number; +} + +export interface AdapterSendZclBroadcastPayload { + status: SendStatus; + durationSeconds: number; +} + +export interface AdapterRetryPayload { + adapterType: string; + ieeeAddr: string | undefined; + reason: string; +} + +export interface AdapterReceiveZclPayloadPayload { + ieeeAddr: string | undefined; + clusterID: number; + wasBroadcast: boolean; +} + +export interface AdapterReceiveZdoResponsePayload { + clusterId: number; +} + +export interface RequestQueueLengthPayload { + ieeeAddr: string; + endpointId: number; + length: number; +} + +export interface RequestQueueDurationPayload { + ieeeAddr: string; + endpointId: number; + outcome: "sent" | "expired"; + durationSeconds: number; +} + +export interface MetricsEventMap { + adapterSendZclUnicast: [data: AdapterSendZclUnicastPayload]; + adapterSendZdo: [data: AdapterSendZdoPayload]; + adapterSendZclGroup: [data: AdapterSendZclGroupPayload]; + adapterSendZclBroadcast: [data: AdapterSendZclBroadcastPayload]; + adapterRetry: [data: AdapterRetryPayload]; + adapterReceiveZclPayload: [data: AdapterReceiveZclPayloadPayload]; + adapterReceiveZdoResponse: [data: AdapterReceiveZdoResponsePayload]; + requestQueueLength: [data: RequestQueueLengthPayload]; + requestQueueDuration: [data: RequestQueueDurationPayload]; +} + +export const metrics = new EventEmitter(); diff --git a/test/controller.test.ts b/test/controller.test.ts index a67c37d34e..24d81d54e2 100755 --- a/test/controller.test.ts +++ b/test/controller.test.ts @@ -14,6 +14,7 @@ import type {TCustomCluster} from "../src/controller/tstype"; import type * as Models from "../src/models"; import * as Utils from "../src/utils"; import {setLogger} from "../src/utils/logger"; +import {metrics} from "../src/utils/metrics"; import * as timeService from "../src/utils/timeService"; import * as ZSpec from "../src/zspec"; import {BroadcastAddress} from "../src/zspec/enums"; @@ -10608,4 +10609,98 @@ describe("Controller", () => { expect(zclCommandSpy).toHaveBeenCalledTimes(0); }); + + describe("Metrics", () => { + it("emits adapterReceiveZclPayload with ieeeAddr when address is a string", async () => { + const received: Parameters>[1]>[0][] = []; + metrics.on("adapterReceiveZclPayload", (data) => received.push(data)); + const frame = Zcl.Frame.create(0, 1, true, undefined, 10, "readRsp", 0, [{attrId: 5, status: 0, dataType: 66, attrData: "test"}], {}); + await controller.start(); + await mockAdapterEvents.zclPayload({ + wasBroadcast: false, + address: "0x129", + clusterID: frame.cluster.ID, + data: frame.toBuffer(), + header: frame.header, + endpoint: 1, + linkquality: 50, + groupID: 1, + destinationEndpoint: 1, + }); + metrics.removeAllListeners("adapterReceiveZclPayload"); + expect(received).toHaveLength(1); + expect(received[0]).toEqual({ieeeAddr: "0x129", clusterID: frame.cluster.ID, wasBroadcast: false}); + }); + + it("emits adapterReceiveZclPayload with ieeeAddr undefined when address is a number", async () => { + const received: Parameters>[1]>[0][] = []; + metrics.on("adapterReceiveZclPayload", (data) => received.push(data)); + const frame = Zcl.Frame.create(0, 1, true, undefined, 10, "readRsp", 0, [{attrId: 5, status: 0, dataType: 66, attrData: "test"}], {}); + await controller.start(); + await mockAdapterEvents.zclPayload({ + wasBroadcast: true, + address: 129, + clusterID: frame.cluster.ID, + data: frame.toBuffer(), + header: frame.header, + endpoint: 1, + linkquality: 50, + groupID: 1, + destinationEndpoint: 1, + }); + metrics.removeAllListeners("adapterReceiveZclPayload"); + expect(received).toHaveLength(1); + expect(received[0]).toEqual({ieeeAddr: undefined, clusterID: frame.cluster.ID, wasBroadcast: true}); + }); + + it("does not emit adapterReceiveZclPayload for touchlink cluster", async () => { + const received: unknown[] = []; + metrics.on("adapterReceiveZclPayload", (data) => received.push(data)); + await controller.start(); + await mockAdapterEvents.zclPayload({ + wasBroadcast: false, + address: "0x129", + clusterID: Zcl.Clusters.touchlink.ID, + data: Buffer.from([]), + header: undefined, + endpoint: 1, + linkquality: 50, + groupID: 1, + destinationEndpoint: 1, + }); + metrics.removeAllListeners("adapterReceiveZclPayload"); + expect(received).toHaveLength(0); + }); + + it("emits adapterReceiveZdoResponse with clusterId", async () => { + const received: Parameters>[1]>[0][] = []; + metrics.on("adapterReceiveZdoResponse", (data) => received.push(data)); + await controller.start(); + await mockAdapterEvents.zdoResponse(Zdo.ClusterId.END_DEVICE_ANNOUNCE, [ + Zdo.Status.SUCCESS, + {nwkAddress: 129, eui64: "0x129", capabilities: Zdo.Utils.getMacCapFlags(0x10)}, + ]); + metrics.removeAllListeners("adapterReceiveZdoResponse"); + expect(received).toHaveLength(1); + expect(received[0]).toEqual({clusterId: Zdo.ClusterId.END_DEVICE_ANNOUNCE}); + }); + + it("emits adapterReceiveZdoResponse for each ZDO cluster received", async () => { + const received: Parameters>[1]>[0][] = []; + metrics.on("adapterReceiveZdoResponse", (data) => received.push(data)); + await controller.start(); + await mockAdapterEvents.zdoResponse(Zdo.ClusterId.NETWORK_ADDRESS_RESPONSE, [ + Zdo.Status.SUCCESS, + {nwkAddress: 129, eui64: "0x129", startIndex: 0, assocDevList: []}, + ]); + await mockAdapterEvents.zdoResponse(Zdo.ClusterId.IEEE_ADDRESS_RESPONSE, [ + Zdo.Status.SUCCESS, + {nwkAddress: 129, eui64: "0x129", startIndex: 0, assocDevList: []}, + ]); + metrics.removeAllListeners("adapterReceiveZdoResponse"); + expect(received).toHaveLength(2); + expect(received[0]).toEqual({clusterId: Zdo.ClusterId.NETWORK_ADDRESS_RESPONSE}); + expect(received[1]).toEqual({clusterId: Zdo.ClusterId.IEEE_ADDRESS_RESPONSE}); + }); + }); });