[1.0] [TC-OO-2-3] Failed to send OnWithTimedOff Command to dynamic endpoint, return error "Unsupported Endpoint"

[KaMeHaMeHaaaa]

Reproduction steps

We have a Bridge device，its zap config as follow:
Endpoint 0: RootNode
Endpoint 1: Aggregator
Endpoint 2: Disabled last fixed endpoint，which is used as a placeholder for all of the supported cluster so that zap will generated the requisite code

Steps to trigger this bug:
Step1: Register bridge device to non-matter side
Step2: Commissioning bridge device to matter fabric
Step3: Register a non-matter device to non-matter side
Step4: After step3, we turn this non-matter device to a dynamic endpoint, and endpoint id is 3.
Step5: Then send command "./chip-tool onoff on-with-timed-off 1 300 300 1 3" to this dynamic endpoint.
Step6: we got an error "unsupported endpoint"

And we look into the "src/app/cluster/on-off-server.cpp" and found command "OnWithTimedOff" will check whether the EventControl is nullptr, but "eventControls[EMBER_AF_ON_OFF_CLUSTER_SRVER_ENDPOINT_COUNT]" in "src/app/cluster/on-off-server/on-off-server.h" shows that it seems only has effect on fixed endpoint.

Bug prevalence

always

GitHub hash of the SDK that was being used

4744889

Platform

ameba

Platform Version(s)

No response

Type

Common Cluster Logic

Anything else?

$ ./chip-tool onoff on-with-timed-off 1 300 300 1 3
[1682302961.608545][61116:61116] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs
[1682302961.614116][61116:61116] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini
[1682302961.614423][61116:61116] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini
[1682302961.614554][61116:61116] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini
[1682302961.614873][61116:61116] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-lAI0zQ)
[1682302961.615498][61116:61116] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1682302961.615556][61116:61116] CHIP:DL: NVS set: chip-counters/reboot-count = 2 (0x2)
[1682302961.616373][61116:61116] CHIP:DL: Got Ethernet interface: eth0
[1682302961.616955][61116:61116] CHIP:DL: Found the primary Ethernet interface:eth0
[1682302961.617522][61116:61116] CHIP:DL: Got WiFi interface: wlan0
[1682302961.617589][61116:61116] CHIP:DL: Failed to reset WiFi statistic counts
[1682302961.617643][61116:61116] CHIP:IN: UDP::Init bind&listen port=0
[1682302961.617750][61116:61116] CHIP:IN: UDP::Init bound to port=51571
[1682302961.617771][61116:61116] CHIP:IN: BLEBase::Init - setting/overriding transport
[1682302961.617789][61116:61116] CHIP:IN: TransportMgr initialized
[1682302961.617822][61116:61116] CHIP:FP: Initializing FabricTable from persistent storage
[1682302961.617962][61116:61116] CHIP:TS: Last Known Good Time: 2022-10-21T23:13:11
[1682302961.619406][61116:61116] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0x8FECD154B02E71F6, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1
[1682302961.621569][61116:61116] CHIP:ZCL: Using ZAP configuration...
[1682302961.625441][61116:61116] CHIP:DL: Avahi client registered
[1682302961.626610][61116:61116] CHIP:CTL: System State Initialized...
[1682302961.626722][61116:61116] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1682302961.626764][61116:61116] CHIP:CTL: Setting attestation nonce to random value
[1682302961.626800][61116:61116] CHIP:CTL: Setting CSR nonce to random value
[1682302961.627085][61116:61121] CHIP:DL: CHIP task running
[1682302961.627391][61116:61121] CHIP:DL: HandlePlatformSpecificBLEEvent 32784
[1682302961.627466][61116:61121] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1682302961.627501][61116:61121] CHIP:CTL: Setting attestation nonce to random value
[1682302961.627678][61116:61121] CHIP:CTL: Setting CSR nonce to random value
[1682302961.628812][61116:61121] CHIP:CTL: Generating NOC
[1682302961.629955][61116:61121] CHIP:FP: Validating NOC chain
[1682302961.632036][61116:61121] CHIP:FP: NOC chain validation successful
[1682302961.632214][61116:61121] CHIP:FP: Updated fabric at index: 0x1, Node ID: 0x000000000001B669
[1682302961.632249][61116:61121] CHIP:TS: Last Known Good Time: 2022-10-21T23:13:11
[1682302961.632273][61116:61121] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00
[1682302961.632296][61116:61121] CHIP:TS: Retaining current Last Known Good Time
[1682302961.639743][61116:61121] CHIP:FP: Metadata for Fabric 0x1 persisted to storage.
[1682302961.641749][61116:61121] CHIP:TS: Committing Last Known Good Time to storage: 2022-10-21T23:13:11
[1682302961.644204][61116:61121] CHIP:CTL: Joined the fabric at index 1. Compressed fabric ID is: 0x0000000000000000
[1682302961.653335][61116:61121] CHIP:TOO: Sending command to node 0x1
[1682302961.653387][61116:61121] CHIP:CSM: FindOrEstablishSession: PeerId = [1:0000000000000001]
[1682302961.653411][61116:61121] CHIP:CSM: FindOrEstablishSession: No existing OperationalSessionSetup instance found
[1682302961.653448][61116:61121] CHIP:CTL: OperationalSessionSetup[1:0000000000000001]: State change 1 --> 2
[1682302961.653479][61116:61121] CHIP:DIS: Resolving 8FECD154B02E71F6:0000000000000001 ...
[1682302961.655214][61116:61121] CHIP:DL: Avahi resolve found
[1682302961.655287][61116:61121] CHIP:DIS: Node ID resolved for 8FECD154B02E71F6:0000000000000001
[1682302961.655310][61116:61121] CHIP:DIS: Hostname: 00E04CB72300
[1682302961.655336][61116:61121] CHIP:DIS: IP Address #1: fe80::2e0:4cff:feb7:2300
[1682302961.655358][61116:61121] CHIP:DIS: Port: 5540
[1682302961.655379][61116:61121] CHIP:DIS: Mrp Interval idle: 5000 ms
[1682302961.655399][61116:61121] CHIP:DIS: Mrp Interval active: 300 ms
[1682302961.655420][61116:61121] CHIP:DIS: TCP Supported: 1
[1682302961.655555][61116:61121] CHIP:DIS: UDP:[fe80::2e0:4cff:feb7:2300%eth0]:5540: new best score: 3
[1682302961.655601][61116:61121] CHIP:DIS: Checking node lookup status after 2 ms
[1682302961.655620][61116:61121] CHIP:DIS: Keeping DNSSD lookup active
[1682302961.854046][61116:61121] CHIP:DIS: Checking node lookup status after 200 ms
[1682302961.854362][61116:61121] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: Updating device address to UDP:[fe80::2e0:4cff:feb7:2300%eth0]:5540 while in state 2
[1682302961.854431][61116:61121] CHIP:CTL: OperationalSessionSetup[1:0000000000000001]: State change 2 --> 3
[1682302961.854646][61116:61121] CHIP:IN: SecureSession[0xffff8c00a0a0]: Allocated Type:2 LSID:26145
[1682302961.854735][61116:61121] CHIP:SC: Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x0000000000000001
[1682302961.856408][61116:61121] CHIP:SC: Including MRP parameters
[1682302961.856799][61116:61121] CHIP:IN: Prepared unauthenticated message 0xffff8c007028 to 0x0000000000000000 (0) of type 0x30 and protocolId (0, 0) on exchange 36124i with MessageCounter:242630426.
[1682302961.856905][61116:61121] CHIP:IN: Sending unauthenticated msg 0xffff8c007028 with MessageCounter:242630426 to 0x0000000000000000 at monotonic time: 0000000042AC0910 msec
[1682302961.857216][61116:61121] CHIP:SC: Sent Sigma1 msg
[1682302961.857287][61116:61121] CHIP:CTL: OperationalSessionSetup[1:0000000000000001]: State change 3 --> 4
[1682302961.922975][61116:61121] CHIP:EM: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:263731168 on exchange 36124i
[1682302961.923075][61116:61121] CHIP:EM: Found matching exchange: 36124i, Delegate: 0xffff8c00b138
[1682302961.923158][61116:61121] CHIP:EM: Rxd Ack; Removing MessageCounter:242630426 from Retrans Table on exchange 36124i
[1682302961.923216][61116:61121] CHIP:EM: Removed CHIP MessageCounter:242630426 from RetransTable on exchange 36124i
[1682302962.512764][61116:61121] CHIP:EM: Received message of type 0x31 with protocolId (0, 0) and MessageCounter:263731169 on exchange 36124i
[1682302962.512843][61116:61121] CHIP:EM: Found matching exchange: 36124i, Delegate: 0xffff8c00b138
[1682302962.512888][61116:61121] CHIP:EM: CHIP MessageCounter:242630426 not in RetransTable on exchange 36124i
[1682302962.512953][61116:61121] CHIP:SC: Received Sigma2 msg
[1682302962.513007][61116:61121] CHIP:SC: Peer assigned session session ID 10598
[1682302962.519785][61116:61121] CHIP:SC: Found MRP parameters in the message
[1682302962.519868][61116:61121] CHIP:SC: Sending Sigma3
[1682302962.520634][61116:61121] CHIP:EM: Piggybacking Ack for MessageCounter:263731169 on exchange: 36124i
[1682302962.520718][61116:61121] CHIP:IN: Prepared unauthenticated message 0xffff8c007728 to 0x0000000000000000 (0) of type 0x32 and protocolId (0, 0) on exchange 36124i with MessageCounter:242630427.
[1682302962.520777][61116:61121] CHIP:IN: Sending unauthenticated msg 0xffff8c007728 with MessageCounter:242630427 to 0x0000000000000000 at monotonic time: 0000000042AC0BA8 msec
[1682302962.520998][61116:61121] CHIP:SC: Sent Sigma3 msg
[1682302962.584161][61116:61121] CHIP:EM: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:263731170 on exchange 36124i
[1682302962.584228][61116:61121] CHIP:EM: Found matching exchange: 36124i, Delegate: 0xffff8c00b138
[1682302962.584288][61116:61121] CHIP:EM: Rxd Ack; Removing MessageCounter:242630427 from Retrans Table on exchange 36124i
[1682302962.584331][61116:61121] CHIP:EM: Removed CHIP MessageCounter:242630427 from RetransTable on exchange 36124i
[1682302963.905678][61116:61121] CHIP:EM: Received message of type 0x40 with protocolId (0, 0) and MessageCounter:263731171 on exchange 36124i
[1682302963.905782][61116:61121] CHIP:EM: Found matching exchange: 36124i, Delegate: 0xffff8c00b138
[1682302963.905846][61116:61121] CHIP:EM: CHIP MessageCounter:242630427 not in RetransTable on exchange 36124i
[1682302963.905939][61116:61121] CHIP:SC: Success status report received. Session was established
[1682302963.912589][61116:61121] CHIP:SC: SecureSession[0xffff8c00a0a0]: Moving from state 'kEstablishing' --> 'kActive'
[1682302963.912666][61116:61121] CHIP:IN: SecureSession[0xffff8c00a0a0]: Activated - Type:2 LSID:26145
[1682302963.912707][61116:61121] CHIP:IN: New secure session activated for device <0000000000000001, 1>, LSID:26145 PSID:10598!
[1682302963.912756][61116:61121] CHIP:CTL: OperationalSessionSetup[1:0000000000000001]: State change 4 --> 5
[1682302963.912843][61116:61121] CHIP:TOO: Sending cluster (0x00000006) command (0x00000042) on endpoint 3
[1682302963.912935][61116:61121] CHIP:DMG: ICR moving to [AddingComm]
[1682302963.912990][61116:61121] CHIP:DMG: ICR moving to [AddedComma]
[1682302963.913325][61116:61121] CHIP:IN: Prepared secure message 0xffff8c00d208 to 0x0000000000000001 (1) of type 0x8 and protocolId (0, 1) on exchange 36125i with MessageCounter:149376042.
[1682302963.913409][61116:61121] CHIP:IN: Sending encrypted msg 0xffff8c00d208 with MessageCounter:149376042 to 0x0000000000000001 (1) at monotonic time: 0000000042AC1118 msec
[1682302963.913663][61116:61121] CHIP:DMG: ICR moving to [CommandSen]
[1682302963.913750][61116:61121] CHIP:EM: Sending Standalone Ack for MessageCounter:263731171 on exchange 36124i
[1682302963.913818][61116:61121] CHIP:IN: Prepared unauthenticated message 0xffffa14ed968 to 0x0000000000000000 (0) of type 0x10 and protocolId (0, 0) on exchange 36124i with MessageCounter:242630428.
[1682302963.913879][61116:61121] CHIP:IN: Sending unauthenticated msg 0xffffa14ed968 with MessageCounter:242630428 to 0x0000000000000000 at monotonic time: 0000000042AC1119 msec
[1682302963.914017][61116:61121] CHIP:EM: Flushed pending ack for MessageCounter:263731171 on exchange 36124i
[1682302964.067799][61116:61121] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:153876781 on exchange 36125i
[1682302964.067899][61116:61121] CHIP:EM: Found matching exchange: 36125i, Delegate: 0xffff8c009908
[1682302964.067981][61116:61121] CHIP:EM: Rxd Ack; Removing MessageCounter:149376042 from Retrans Table on exchange 36125i
[1682302964.068040][61116:61121] CHIP:EM: Removed CHIP MessageCounter:149376042 from RetransTable on exchange 36125i
[1682302964.068117][61116:61121] CHIP:DMG: ICR moving to [ResponseRe]
[1682302964.068225][61116:61121] CHIP:DMG: InvokeResponseMessage =
[1682302964.068285][61116:61121] CHIP:DMG: {
[1682302964.068342][61116:61121] CHIP:DMG: suppressResponse = false,
[1682302964.068403][61116:61121] CHIP:DMG: InvokeResponseIBs =
[1682302964.068524][61116:61121] CHIP:DMG: [
[1682302964.068589][61116:61121] CHIP:DMG: InvokeResponseIB =
[1682302964.068670][61116:61121] CHIP:DMG: {
[1682302964.068735][61116:61121] CHIP:DMG: CommandStatusIB =
[1682302964.068815][61116:61121] CHIP:DMG: {
[1682302964.068883][61116:61121] CHIP:DMG: CommandPathIB =
[1682302964.068961][61116:61121] CHIP:DMG: {
[1682302964.069040][61116:61121] CHIP:DMG: EndpointId = 0x3,
[1682302964.069125][61116:61121] CHIP:DMG: ClusterId = 0x6,
[1682302964.069205][61116:61121] CHIP:DMG: CommandId = 0x42,
[1682302964.069282][61116:61121] CHIP:DMG: },
[1682302964.069370][61116:61121] CHIP:DMG:
[1682302964.069441][61116:61121] CHIP:DMG: StatusIB =
[1682302964.069519][61116:61121] CHIP:DMG: {
[1682302964.069598][61116:61121] CHIP:DMG: status = 0x7f (UNSUPPORTED_ENDPOINT),
[1682302964.069677][61116:61121] CHIP:DMG: },
[1682302964.069750][61116:61121] CHIP:DMG:
[1682302964.069817][61116:61121] CHIP:DMG: },
[1682302964.069896][61116:61121] CHIP:DMG:
[1682302964.069958][61116:61121] CHIP:DMG: },
[1682302964.070032][61116:61121] CHIP:DMG:
[1682302964.070089][61116:61121] CHIP:DMG: ],
[1682302964.070162][61116:61121] CHIP:DMG:
[1682302964.070219][61116:61121] CHIP:DMG: InteractionModelRevision = 1
[1682302964.070277][61116:61121] CHIP:DMG: },
[1682302964.070410][61116:61121] CHIP:DMG: Received Command Response Status for Endpoint=3 Cluster=0x0000_0006 Command=0x0000_0042 Status=0x7f
[1682302964.070484][61116:61121] CHIP:TOO: Error: IM Error 0x0000057F: General error: 0x7f (UNSUPPORTED_ENDPOINT)
[1682302964.070569][61116:61121] CHIP:DMG: ICR moving to [AwaitingDe]
[1682302964.070681][61116:61121] CHIP:EM: Sending Standalone Ack for MessageCounter:153876781 on exchange 36125i
[1682302964.070852][61116:61121] CHIP:IN: Prepared secure message 0xffffa14ed978 to 0x0000000000000001 (1) of type 0x10 and protocolId (0, 0) on exchange 36125i with MessageCounter:149376043.
[1682302964.070946][61116:61121] CHIP:IN: Sending encrypted msg 0xffffa14ed978 with MessageCounter:149376043 to 0x0000000000000001 (1) at monotonic time: 0000000042AC11B6 msec
[1682302964.071169][61116:61121] CHIP:EM: Flushed pending ack for MessageCounter:153876781 on exchange 36125i
[1682302964.071539][61116:61116] CHIP:CTL: Shutting down the commissioner
[1682302964.071613][61116:61116] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1682302964.071674][61116:61116] CHIP:CTL: Shutting down the controller
[1682302964.071726][61116:61116] CHIP:IN: Expiring all sessions for fabric 0x1!!
[1682302964.071777][61116:61116] CHIP:IN: SecureSession[0xffff8c00a0a0]: MarkForEviction Type:2 LSID:26145
[1682302964.071830][61116:61116] CHIP:SC: SecureSession[0xffff8c00a0a0]: Moving from state 'kActive' --> 'kPendingEviction'
[1682302964.071883][61116:61116] CHIP:IN: SecureSession[0xffff8c00a0a0]: Released - Type:2 LSID:26145
[1682302964.071942][61116:61116] CHIP:FP: Forgetting fabric 0x1
[1682302964.072012][61116:61116] CHIP:TS: Pending Last Known Good Time: 2022-10-21T23:13:11
[1682302964.072292][61116:61116] CHIP:TS: Previous Last Known Good Time: 2022-10-21T23:13:11
[1682302964.072354][61116:61116] CHIP:TS: Reverted Last Known Good Time to previous value
[1682302964.072441][61116:61116] CHIP:CTL: Shutting down the commissioner
[1682302964.072540][61116:61116] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1682302964.072595][61116:61116] CHIP:CTL: Shutting down the controller
[1682302964.072645][61116:61116] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack
[1682302964.074636][61116:61116] CHIP:DMG: IM WH moving to [Uninitialized]
[1682302964.074716][61116:61116] CHIP:DMG: IM WH moving to [Uninitialized]
[1682302964.074765][61116:61116] CHIP:DMG: IM WH moving to [Uninitialized]
[1682302964.074814][61116:61116] CHIP:DMG: IM WH moving to [Uninitialized]
[1682302964.074869][61116:61116] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet
[1682302964.075040][61116:61116] CHIP:BLE: BleConnectionDelegate::CancelConnection is not implemented.
[1682302964.075511][61116:61116] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-hwr1qG)
[1682302964.076907][61116:61116] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1682302964.077052][61116:61116] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0)
[1682302964.077113][61116:61116] CHIP:DL: Inet Layer shutdown
[1682302964.077164][61116:61116] CHIP:DL: BLE shutdown
[1682302964.077216][61116:61116] CHIP:DL: System Layer shutdown
[1682302964.077471][61116:61116] CHIP:TOO: Run command failure: IM Error 0x0000057F: General error: 0x7f (UNSUPPORTED_ENDPOINT)