Bug: readAttributesStructured.response frames logged as unknown_command_received after being handled correctly

[gpmachado]

Package: zigbee-clusters
Version: 3.5.0
Environment: Homey Pro, app built on homey-zigbeedriver

Summary

When a device replies to a readAttributesStructured request, the response frame is correctly parsed and delivered to the caller (I can see the real attribute values land in my driver code) — but immediately afterwards the same frame (same trxSequenceNumber, same cmdId, same payload) is logged a second time and this second pass fails with unknown_command_received. It happens on multiple clusters (basic, electricalMeasurement observed so far), always with cmdId: 1 and frameControl: [directionToClient, disableDefaultResponse].

Functionally harmless (the data was already delivered on the first pass), but it's confusing noise in debug logs and looks like a real error at first glance.

Repro log (basic cluster, ep 1)

zigbee-clusters:cluster ep: 1, cl: basic (0) received frame readAttributesStructured.response basic.readAttributesStructured.response {
  attributes: <Buffer 04 00 00 42 10 5f 54 5a 33 30 30 30 5f ... >
}
zigbee-clusters:cluster ep: 1, cl: basic (0) unknown command received: ZCLStandardHeader {
  frameControl: Bitmap [ directionToClient, disableDefaultResponse ],
  trxSequenceNumber: 1,
  cmdId: 1,
  data: <Buffer 04 00 00 42 10 5f 54 5a 33 30 30 30 5f ... >
} { dstEndpoint: 1 }
zigbee-clusters:endpoint ep: 1, cl: basic (0), error while handling frame unknown_command_received {
  meta: { dstEndpoint: 1 },
  frame: ZCLStandardHeader { frameControl: [...], trxSequenceNumber: 1, cmdId: 1, data: <Buffer ...> }
}
zigbee-clusters:cluster ep: 1, cl: basic (0) read attributes result basic.readAttributesStructured.response {
  attributes: <Buffer 04 00 00 42 10 5f 54 5a 33 30 30 30 5f ... >
}

Same pattern reproduced on electricalMeasurement (2820):

zigbee-clusters:cluster ep: 1, cl: electricalMeasurement (2820) received frame readAttributesStructured.response ... { attributes: <Buffer 0b 05 00 29 00 00 08 05 00 21 0d 00> }
zigbee-clusters:cluster ep: 1, cl: electricalMeasurement (2820) read attributes result ... { attributes: <Buffer 0b 05 00 29 00 00 08 05 00 21 0d 00> }
[application log] Poll power=2.69W current=0.013A          <-- correct value, already used
zigbee-clusters:cluster ep: 1, cl: electricalMeasurement (2820) received frame readAttributesStructured.response ... { attributes: <Buffer 0b 05 00 29 00 00 08 05 00 21 0d 00> }   <-- same buffer, again
zigbee-clusters:cluster ep: 1, cl: electricalMeasurement (2820) unknown command received: ZCLStandardHeader { ..., trxSequenceNumber: 2, cmdId: 1, data: <Buffer 0b 05 00 29 00 00 08 05 00 21 0d 00> }
zigbee-clusters:endpoint ep: 1, cl: electricalMeasurement (2820), error while handling frame unknown_command_received { ... }

Root cause (as far as I could trace it)

In lib/Cluster.js, handleFrame():

async handleFrame(frame, meta, rawFrame) {
  const commands = this.constructor.commandsById[frame.cmdId] || [];
  ...
  const handler = this._trxHandlers[frame.trxSequenceNumber] || this[handlerName];
  delete this._trxHandlers[frame.trxSequenceNumber];
  if (handler) {
    ...
    return;
  }

  debug(this.logId, 'unknown command received:', frame, meta);
  throw new Error('unknown_command_received');
}

The transaction-scoped handler registered for a readAttributesStructured() call (this._trxHandlers[trxSequenceNumber]) is deleted as soon as it's looked up. If handleFrame is invoked a second time for the identical frame/transaction (which the logs above show happening — same trxSequenceNumber, same payload, arriving a few ms after the first, successful pass), the trx handler is already gone, there's no generic on... method for readAttributesStructured.response, and it falls through to unknown_command_received.

So the underlying issue looks like the same physical frame reaching Cluster.handleFrame() (via Endpoint.handleZCLFrame → Endpoint.handleFrame) twice — I wasn't able to pin down exactly where the duplicate dispatch originates (possibly two paths both routing the response: one via a readAttributesStructured() promise resolution, one via generic frame processing), but the log timestamps and identical payloads make it clear it's the same frame both times, not a real duplicate frame over the air.

Impact

• No functional impact observed — the correct attribute values are always delivered on the first pass and used successfully by the calling code.
• Produces a spurious error while handling frame unknown_command_received in debug logs for every readAttributesStructured call, which is confusing when debugging real issues (had to trace this precisely to rule it out as the cause of an unrelated investigation).
• Also triggers a default-response-error frame being sent back to the device for no reason (Endpoint.handleFrame's catch branch sends a ZCL error response), which seems unintended.

Steps to reproduce

Call cluster.readAttributesStructured([...]) (or trigger a driver code path that does) against any cluster/device on Homey Pro with zigbee-clusters 3.5.0. Enable zigbee-clusters:* debug output (ZCL_DEBUG/DEBUG=zigbee-clusters:*) and watch for the response frame being logged twice, with the second occurrence failing.

Happy to share more context/logs if useful.