Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[TC-DRLK-2.8] Door-lock Set User Command is returning success instead of INVALID_COMMAND #19563

Closed
Ashwinigrl opened this issue Jun 14, 2022 · 10 comments · Fixed by #19813
Closed
Assignees
Labels
app-clusters Application cluster work cert blocker spec Mismatch between spec and implementation V1.0

Comments

@Ashwinigrl
Copy link

Problem -In Set User command, after giving invalid UserType value we are getting success response

Actual Behavior -After giving UserType value as invalid we are getting success response

Expected Behavior - After giving user type value as invalid we have to get INVALID_COMMAND

App used - lock app
Platform - Chip-tool - RPI-4, 8GB RAM
DUT - RPI-4, 8GB RAM
Network - Ble-wifi
Commit - 9493d7b

TH LOG :

./chip-tool doorlock set-user 0 2 xxx 6451 1 10 3 1 1 --timedInteractionTimeoutMs 1000
[1655212761.421326][19184:19184] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs
[1655212761.422174][19184:19184] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini
[1655212761.422370][19184:19184] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini
[1655212761.422504][19184:19184] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini
[1655212761.422914][19184:19184] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-1WRyp5)
[1655212761.423627][19184:19184] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1655212761.423701][19184:19184] CHIP:DL: NVS set: chip-counters/reboot-count = 108 (0x6C)
[1655212761.424622][19184:19184] CHIP:DL: Got Ethernet interface: eth0
[1655212761.425298][19184:19184] CHIP:DL: Found the primary Ethernet interface:eth0
[1655212761.425970][19184:19184] CHIP:DL: Got WiFi interface: wlan0
[1655212761.426057][19184:19184] CHIP:DL: Failed to reset WiFi statistic counts
[1655212761.426122][19184:19184] CHIP:IN: UDP::Init bind&listen port=0
[1655212761.426279][19184:19184] CHIP:IN: UDP::Init bound to port=35671
[1655212761.426307][19184:19184] CHIP:IN: BLEBase::Init - setting/overriding transport
[1655212761.426328][19184:19184] CHIP:IN: TransportMgr initialized
[1655212761.426418][19184:19184] CHIP:FP: Initializing FabricTable from persistent storage
[1655212761.426722][19184:19184] CHIP:TS: Last Known Good Time: 2022-06-14T07:55:16
[1655212761.426941][19184:19184] CHIP:FP: Loading from storage for fabric index 0x1
[1655212761.427774][19184:19184] CHIP:FP: Loading from storage for fabric index 0x2
[1655212761.428498][19184:19184] CHIP:FP: Loading from storage for fabric index 0x3
[1655212761.435645][19184:19184] CHIP:ZCL: Using ZAP configuration...
[1655212761.439934][19184:19184] CHIP:DL: Avahi client registered
[1655212761.441134][19184:19184] CHIP:CTL: System State Initialized...
[1655212761.441219][19184:19184] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1655212761.441274][19184:19184] CHIP:CTL: Setting attestation nonce to random value
[1655212761.441338][19184:19184] CHIP:CTL: Setting CSR nonce to random value
[1655212761.441471][19184:19184] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1655212761.441501][19184:19184] CHIP:CTL: Setting attestation nonce to random value
[1655212761.441548][19184:19184] CHIP:CTL: Setting CSR nonce to random value
[1655212761.444361][19184:19184] CHIP:CTL: Generating NOC
[1655212761.445202][19184:19184] CHIP:FP: Validating NOC chain
[1655212761.447047][19184:19184] CHIP:FP: NOC chain validation successful
[1655212761.447213][19184:19184] CHIP:FP: Added new fabric at index: 0x1, Initialized: 1
[1655212761.447239][19184:19184] CHIP:FP: Assigned compressed fabric ID: 0xA1CC5128D551FAC7, node ID: 0x000000000001B669
[1655212761.460651][19184:19184] CHIP:FP: Fabric (0x1) persisted to storage. Calling OnFabricPersistedToStorage
[1655212761.460705][19184:19184] CHIP:TS: Last Known Good Time: 2022-06-14T07:55:16
[1655212761.460729][19184:19184] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00
[1655212761.460752][19184:19184] CHIP:TS: Retaining current Last Known Good Time
[1655212761.465452][19184:19184] CHIP:CTL: Joined the fabric at index 1. Compressed fabric ID is: 0xA1CC5128D551FAC7
[1655212761.465576][19184:19184] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1655212761.465618][19184:19184] CHIP:CTL: Setting attestation nonce to random value
[1655212761.465696][19184:19184] CHIP:CTL: Setting CSR nonce to random value
[1655212761.466559][19184:19184] CHIP:CTL: Generating NOC
[1655212761.467433][19184:19184] CHIP:FP: Validating NOC chain
[1655212761.469345][19184:19184] CHIP:FP: NOC chain validation successful
[1655212761.469540][19184:19184] CHIP:FP: Added new fabric at index: 0x2, Initialized: 1
[1655212761.469570][19184:19184] CHIP:FP: Assigned compressed fabric ID: 0x13173974745587F1, node ID: 0x000000000001B669
[1655212761.481904][19184:19184] CHIP:FP: Fabric (0x2) persisted to storage. Calling OnFabricPersistedToStorage
[1655212761.481960][19184:19184] CHIP:TS: Last Known Good Time: 2022-06-14T07:55:16
[1655212761.481984][19184:19184] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00
[1655212761.482006][19184:19184] CHIP:TS: Retaining current Last Known Good Time
[1655212761.484817][19184:19184] CHIP:CTL: Joined the fabric at index 2. Compressed fabric ID is: 0x13173974745587F1
[1655212761.484957][19184:19184] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1655212761.484998][19184:19184] CHIP:CTL: Setting attestation nonce to random value
[1655212761.485077][19184:19184] CHIP:CTL: Setting CSR nonce to random value
[1655212761.485934][19184:19184] CHIP:CTL: Generating NOC
[1655212761.486889][19184:19184] CHIP:FP: Validating NOC chain
[1655212761.488630][19184:19184] CHIP:FP: NOC chain validation successful
[1655212761.488843][19184:19184] CHIP:FP: Added new fabric at index: 0x3, Initialized: 1
[1655212761.488870][19184:19184] CHIP:FP: Assigned compressed fabric ID: 0x2352DB2D09AD1D46, node ID: 0x000000000001B669
[1655212761.502236][19184:19184] CHIP:FP: Fabric (0x3) persisted to storage. Calling OnFabricPersistedToStorage
[1655212761.502296][19184:19184] CHIP:TS: Last Known Good Time: 2022-06-14T07:55:16
[1655212761.502323][19184:19184] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00
[1655212761.502347][19184:19184] CHIP:TS: Retaining current Last Known Good Time
[1655212761.505392][19184:19184] CHIP:CTL: Joined the fabric at index 3. Compressed fabric ID is: 0x2352DB2D09AD1D46
[1655212761.580695][19184:19189] CHIP:DL: CHIP task running
[1655212761.580914][19184:19189] CHIP:DL: HandlePlatformSpecificBLEEvent 32787
[1655212761.580949][19184:19189] CHIP:TOO: Sending command to node 0x1
[1655212761.580984][19184:19189] CHIP:CSM: FindOrEstablishSession: PeerId = A1CC5128D551FAC7:0000000000000001
[1655212761.581010][19184:19189] CHIP:CSM: FindOrEstablishSession: No existing OperationalDeviceProxy instance found
[1655212761.581049][19184:19189] CHIP:CTL: OperationalDeviceProxy[A1CC5128D551FAC7:0000000000000001]: State change 1 --> 2
[1655212761.581079][19184:19189] CHIP:DIS: Resolving A1CC5128D551FAC7:0000000000000001 ...
[1655212761.582835][19184:19189] CHIP:DL: Avahi resolve found
[1655212761.582915][19184:19189] CHIP:DIS: Node ID resolved for A1CC5128D551FAC7:0000000000000001
[1655212761.582942][19184:19189] CHIP:DIS:      Hostname: E45F01312CE50000
[1655212761.582970][19184:19189] CHIP:DIS:      IP Address #1: fe80::e65f:1ff:fe31:2ce5
[1655212761.582994][19184:19189] CHIP:DIS:      Port: 5540
[1655212761.583016][19184:19189] CHIP:DIS:      Mrp Interval idle: 5000 ms
[1655212761.583039][19184:19189] CHIP:DIS:      Mrp Interval active: 300 ms
[1655212761.583330][19184:19189] CHIP:DIS: UDP:[fe80::e65f:1ff:fe31:2ce5%eth0]:5540: new best score: 3
[1655212761.583358][19184:19189] CHIP:DIS: Checking node lookup status after 2 ms
[1655212761.583380][19184:19189] CHIP:DIS: Keeping DNSSD lookup active
[1655212761.781686][19184:19189] CHIP:DIS: Checking node lookup status after 200 ms
[1655212761.782003][19184:19189] CHIP:CTL: Updating device address to UDP:[fe80::e65f:1ff:fe31:2ce5%eth0]:5540 while in state 2
[1655212761.782070][19184:19189] CHIP:CTL: OperationalDeviceProxy[A1CC5128D551FAC7:0000000000000001]: State change 2 --> 3
[1655212761.782514][19184:19189] CHIP:IN: SecureSession[0xaaaaeafc67c0]: Allocated Type:2 LSID:15295
[1655212761.782597][19184:19189] CHIP:SC: Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x0000000000000001
[1655212761.784673][19184:19189] CHIP:SC: Including MRP parameters
[1655212761.785381][19184:19189] CHIP:IN: Prepared unauthenticated message 0xaaaaeafcdc78 to 0x0000000000000000 (0)  of type 0x30 and protocolId (0, 0) on exchange 4467i with MessageCounter:81540215.
[1655212761.785489][19184:19189] CHIP:IN: Sending unauthenticated msg 0xaaaaeafcdc78 with MessageCounter:81540215 to 0x0000000000000000 at monotonic time: 00000000019377AE msec
[1655212761.785849][19184:19189] CHIP:SC: Sent Sigma1 msg
[1655212761.785919][19184:19189] CHIP:CTL: OperationalDeviceProxy[A1CC5128D551FAC7:0000000000000001]: State change 3 --> 4
[1655212761.785988][19184:19189] CHIP:DIS: Discovery does not require any more timeouts
[1655212761.788493][19184:19189] CHIP:EM: Received message of type 0x33 with protocolId (0, 0) and MessageCounter:106000514 on exchange 4467i
[1655212761.788571][19184:19189] CHIP:EM: Found matching exchange: 4467i, Delegate: 0xffff680011a0
[1655212761.788657][19184:19189] CHIP:EM: Rxd Ack; Removing MessageCounter:81540215 from Retrans Table on exchange 4467i
[1655212761.788718][19184:19189] CHIP:EM: Removed CHIP MessageCounter:81540215 from RetransTable on exchange 4467i
[1655212761.788799][19184:19189] CHIP:SC: Received Sigma2Resume msg
[1655212761.788982][19184:19189] CHIP:SC: Found MRP parameters in the message
[1655212761.789072][19184:19189] CHIP:SC: Peer assigned session session ID 16428
[1655212761.809223][19184:19189] CHIP:SC: Sending status report. Protocol code 0, exchange 4467
[1655212761.809299][19184:19189] CHIP:EM: Piggybacking Ack for MessageCounter:106000514 on exchange: 4467i
[1655212761.809349][19184:19189] CHIP:IN: Prepared unauthenticated message 0xaaaaeafcdc78 to 0x0000000000000000 (0)  of type 0x40 and protocolId (0, 0) on exchange 4467i with MessageCounter:81540216.
[1655212761.809394][19184:19189] CHIP:IN: Sending unauthenticated msg 0xaaaaeafcdc78 with MessageCounter:81540216 to 0x0000000000000000 at monotonic time: 00000000019377C6 msec
[1655212761.809704][19184:19189] CHIP:IN: SecureSession[0xaaaaeafc67c0]: Activated - Type:2 LSID:15295
[1655212761.809736][19184:19189] CHIP:IN: New secure session created for device <0000000000000001, 1>, LSID:15295 PSID:16428!
[1655212761.809764][19184:19189] CHIP:CTL: OperationalDeviceProxy[A1CC5128D551FAC7:0000000000000001]: State change 4 --> 5
[1655212761.809815][19184:19189] CHIP:TOO: Sending cluster (0x00000101) command (0x0000001A) on endpoint 1
[1655212761.809915][19184:19189] CHIP:DMG: ICR moving to [AddingComm]
[1655212761.809997][19184:19189] CHIP:DMG: ICR moving to [AddedComma]
[1655212761.810099][19184:19189] CHIP:IN: Prepared secure message 0xaaaaeafcdc98 to 0x0000000000000001 (1)  of type 0xa and protocolId (0, 1) on exchange 4468i with MessageCounter:49896653.
[1655212761.810149][19184:19189] CHIP:IN: Sending encrypted msg 0xaaaaeafcdc98 with MessageCounter:49896653 to 0x0000000000000001 (1) at monotonic time: 00000000019377C7 msec
[1655212761.810299][19184:19189] CHIP:DMG: ICR moving to [AwaitingTi]
[1655212761.849129][19184:19189] CHIP:EM: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:106000515 on exchange 4467i
[1655212761.849222][19184:19189] CHIP:EM: Found matching exchange: 4467i, Delegate: (nil)
[1655212761.849324][19184:19189] CHIP:EM: Rxd Ack; Removing MessageCounter:81540216 from Retrans Table on exchange 4467i
[1655212761.849386][19184:19189] CHIP:EM: Removed CHIP MessageCounter:81540216 from RetransTable on exchange 4467i
[1655212761.849887][19184:19189] CHIP:EM: Received message of type 0x1 with protocolId (0, 1) and MessageCounter:232988492 on exchange 4468i
[1655212761.849962][19184:19189] CHIP:EM: Found matching exchange: 4468i, Delegate: 0xffff68009740
[1655212761.850042][19184:19189] CHIP:EM: Rxd Ack; Removing MessageCounter:49896653 from Retrans Table on exchange 4468i
[1655212761.850099][19184:19189] CHIP:EM: Removed CHIP MessageCounter:49896653 from RetransTable on exchange 4468i
[1655212761.850205][19184:19189] CHIP:DMG: StatusResponseMessage =
[1655212761.850295][19184:19189] CHIP:DMG: {
[1655212761.850355][19184:19189] CHIP:DMG:      Status = 0x00 (SUCCESS),
[1655212761.850418][19184:19189] CHIP:DMG:      InteractionModelRevision = 1
[1655212761.850497][19184:19189] CHIP:DMG: }
[1655212761.850556][19184:19189] CHIP:IM: Received status response, status is 0x00 (SUCCESS)
[1655212761.850664][19184:19189] CHIP:EM: Piggybacking Ack for MessageCounter:232988492 on exchange: 4468i
[1655212761.850849][19184:19189] CHIP:IN: Prepared secure message 0xaaaaeafcdc78 to 0x0000000000000001 (1)  of type 0x8 and protocolId (0, 1) on exchange 4468i with MessageCounter:49896654.
[1655212761.850958][19184:19189] CHIP:IN: Sending encrypted msg 0xaaaaeafcdc78 with MessageCounter:49896654 to 0x0000000000000001 (1) at monotonic time: 00000000019377F0 msec
[1655212761.851311][19184:19189] CHIP:DMG: ICR moving to [CommandSen]
[1655212761.854138][19184:19189] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:232988493 on exchange 4468i
[1655212761.854215][19184:19189] CHIP:EM: Found matching exchange: 4468i, Delegate: 0xffff68009740
[1655212761.854296][19184:19189] CHIP:EM: Rxd Ack; Removing MessageCounter:49896654 from Retrans Table on exchange 4468i
[1655212761.854356][19184:19189] CHIP:EM: Removed CHIP MessageCounter:49896654 from RetransTable on exchange 4468i
[1655212761.854432][19184:19189] CHIP:DMG: ICR moving to [ResponseRe]
[1655212761.854548][19184:19189] CHIP:DMG: InvokeResponseMessage =
[1655212761.854610][19184:19189] CHIP:DMG: {
[1655212761.854690][19184:19189] CHIP:DMG:      suppressResponse = false,
[1655212761.854751][19184:19189] CHIP:DMG:      InvokeResponseIBs =
[1655212761.854883][19184:19189] CHIP:DMG:      [
[1655212761.854944][19184:19189] CHIP:DMG:              InvokeResponseIB =
[1655212761.855051][19184:19189] CHIP:DMG:              {
[1655212761.855135][19184:19189] CHIP:DMG:                      CommandStatusIB =
[1655212761.855213][19184:19189] CHIP:DMG:                      {
[1655212761.855303][19184:19189] CHIP:DMG:                              CommandPathIB =
[1655212761.855393][19184:19189] CHIP:DMG:                              {
[1655212761.855497][19184:19189] CHIP:DMG:                                      EndpointId = 0x1,
[1655212761.855603][19184:19189] CHIP:DMG:                                      ClusterId = 0x101,
[1655212761.855689][19184:19189] CHIP:DMG:                                      CommandId = 0x1a,
[1655212761.855764][19184:19189] CHIP:DMG:                              },
[1655212761.855828][19184:19189] CHIP:DMG:
[1655212761.855901][19184:19189] CHIP:DMG:                              StatusIB =
[1655212761.855976][19184:19189] CHIP:DMG:                              {
[1655212761.856037][19184:19189] CHIP:DMG:                                      status = 0x00 (SUCCESS),
[1655212761.856118][19184:19189] CHIP:DMG:                              },
[1655212761.856194][19184:19189] CHIP:DMG:
[1655212761.856249][19184:19189] CHIP:DMG:                      },
[1655212761.856324][19184:19189] CHIP:DMG:
[1655212761.856374][19184:19189] CHIP:DMG:              },
[1655212761.856445][19184:19189] CHIP:DMG:
[1655212761.856489][19184:19189] CHIP:DMG:      ],
[1655212761.856560][19184:19189] CHIP:DMG:
[1655212761.856604][19184:19189] CHIP:DMG:      InteractionModelRevision = 1
[1655212761.856663][19184:19189] CHIP:DMG: },
[1655212761.856778][19184:19189] CHIP:DMG: Received Command Response Status for Endpoint=1 Cluster=0x0000_0101 Command=0x0000_001A Status=0x0
[1655212761.856867][19184:19189] CHIP:DMG: ICR moving to [AwaitingDe]
[1655212761.856979][19184:19189] CHIP:EM: Sending Standalone Ack for MessageCounter:232988493 on exchange 4468i
[1655212761.857094][19184:19189] CHIP:IN: Prepared secure message 0xffff7b7ed958 to 0x0000000000000001 (1)  of type 0x10 and protocolId (0, 0) on exchange 4468i with MessageCounter:49896655.
[1655212761.857159][19184:19189] CHIP:IN: Sending encrypted msg 0xffff7b7ed958 with MessageCounter:49896655 to 0x0000000000000001 (1) at monotonic time: 00000000019377F6 msec
[1655212761.857310][19184:19189] CHIP:EM: Flushed pending ack for MessageCounter:232988493 on exchange 4468i
[1655212761.857598][19184:19184] CHIP:CTL: Shutting down the commissioner
[1655212761.857654][19184:19184] CHIP:CTL: Shutting down the controller
[1655212761.857704][19184:19184] CHIP:CTL: Shutting down the commissioner
[1655212761.857746][19184:19184] CHIP:CTL: Shutting down the controller
[1655212761.857794][19184:19184] CHIP:IN: Expiring all connections for fabric 1!!
[1655212761.857836][19184:19184] CHIP:IN: SecureSession[0xaaaaeafc67c0]: MarkForRemoval Type:2 LSID:15295
[1655212761.857877][19184:19184] CHIP:IN: SecureSession[0xaaaaeafc67c0]: Released - Type:2 LSID:15295
[1655212761.857952][19184:19184] CHIP:CTL: Shutting down the commissioner
[1655212761.857997][19184:19184] CHIP:CTL: Shutting down the controller
[1655212761.858034][19184:19184] CHIP:IN: Expiring all connections for fabric 2!!
[1655212761.858095][19184:19184] CHIP:CTL: Shutting down the commissioner
[1655212761.858136][19184:19184] CHIP:CTL: Shutting down the controller
[1655212761.858172][19184:19184] CHIP:IN: Expiring all connections for fabric 3!!
[1655212761.858226][19184:19184] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack
[1655212761.859792][19184:19184] CHIP:DMG: IM WH moving to [Uninitialized]
[1655212761.859863][19184:19184] CHIP:DMG: IM WH moving to [Uninitialized]
[1655212761.859899][19184:19184] CHIP:DMG: IM WH moving to [Uninitialized]
[1655212761.859938][19184:19184] CHIP:DMG: IM WH moving to [Uninitialized]
[1655212761.859978][19184:19184] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet
[1655212761.860095][19184:19184] CHIP:BLE: BleConnectionDelegate::CancelConnection is not implemented.
[1655212761.860500][19184:19184] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-5m8k7z)
[1655212761.861605][19184:19184] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1655212761.861709][19184:19184] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0)
[1655212761.861757][19184:19184] CHIP:DL: Inet Layer shutdown
[1655212761.861796][19184:19184] CHIP:DL: BLE shutdown
[1655212761.861837][19184:19184] CHIP:DL: System Layer shutdown

DUT LOG :

[1655213700.582061][17592:17592] CHIP:EM: Received message of type 0x30 with protocolId (0, 0) and MessageCounter:42217811 on exchange 58666r
[1655213700.582198][17592:17592] CHIP:EM: Handling via exchange: 58666r, Delegate: 0xaaaae2cf8948
[1655213700.582294][17592:17592] CHIP:IN: CASE Server received Sigma1 message. Starting handshake. EC 0xaaaae2cf8f60
[1655213700.582353][17592:17592] CHIP:IN: CASE Server disabling CASE session setups
[1655213700.582414][17592:17592] CHIP:SC: Received Sigma1 msg
[1655213700.582521][17592:17592] CHIP:SC: Found MRP parameters in the message
[1655213700.582597][17592:17592] CHIP:SC: Peer assigned session key ID 28050
[1655213700.583302][17592:17592] CHIP:SC: Including MRP parameters
[1655213700.583403][17592:17592] CHIP:EM: Piggybacking Ack for MessageCounter:42217811 on exchange: 58666r
[1655213700.583491][17592:17592] CHIP:IN: Prepared unauthenticated message 0xaaaae2cfd618 to 0x0000000000000000 (0)  of type 0x33 and protocolId (0, 0) on exchange 58666r with MessageCounter:226636420.
[1655213700.583576][17592:17592] CHIP:IN: Sending unauthenticated msg 0xaaaae2cfd618 with MessageCounter:226636420 to 0x0000000000000000 at monotonic time: 0000000001A801F2 msec
[1655213700.583957][17592:17592] CHIP:SC: Sent Sigma2Resume msg
[1655213700.592235][17592:17592] CHIP:EM: Received message of type 0x40 with protocolId (0, 0) and MessageCounter:42217812 on exchange 58666r
[1655213700.592310][17592:17592] CHIP:EM: Found matching exchange: 58666r, Delegate: 0xaaaae2cf8980
[1655213700.592392][17592:17592] CHIP:EM: Rxd Ack; Removing MessageCounter:226636420 from Retrans Table on exchange 58666r
[1655213700.592450][17592:17592] CHIP:EM: Removed CHIP MessageCounter:226636420 from RetransTable on exchange 58666r
[1655213700.592532][17592:17592] CHIP:SC: Success status report received. Session was established
[1655213700.593257][17592:17592] CHIP:DL: writing settings to file (/tmp/chip_kvs-lUuzNH)
[1655213700.594673][17592:17592] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs)
[1655213700.594992][17592:17592] CHIP:DL: writing settings to file (/tmp/chip_kvs-MAXxrJ)
[1655213700.596407][17592:17592] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs)
[1655213700.596689][17592:17592] CHIP:DL: writing settings to file (/tmp/chip_kvs-ErCluw)
[1655213700.598048][17592:17592] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs)
[1655213700.598146][17592:17592] CHIP:IN: Expired/released previous local session ID 9196 for peer <000000000001B669, 1>
[1655213700.598196][17592:17592] CHIP:IN: SecureSession[0xaaaae2cf5c88]: MarkForRemoval Type:2 LSID:9196
[1655213700.598238][17592:17592] CHIP:IN: SecureSession[0xaaaae2cf5c88]: Released - Type:2 LSID:9196
[1655213700.598381][17592:17592] CHIP:IN: SecureSession[0xaaaae2cf5d70]: Activated - Type:2 LSID:9197
[1655213700.598428][17592:17592] CHIP:IN: New secure session created for device <000000000001B669, 1>, LSID:9197 PSID:28050!
[1655213700.598486][17592:17592] CHIP:IN: CASE Session established to peer: <000000000001B669, 1>
[1655213700.598526][17592:17592] CHIP:IN: CASE Server enabling CASE session setups
[1655213700.598667][17592:17592] CHIP:IN: SecureSession[0xaaaae2cf5ba0]: Allocated Type:2 LSID:9198
[1655213700.598737][17592:17592] CHIP:SC: Allocated SecureSession (0xaaaae2cf5ba0) - waiting for Sigma1 msg
[1655213700.598788][17592:17592] CHIP:EM: Sending Standalone Ack for MessageCounter:42217812 on exchange 58666r
[1655213700.598882][17592:17592] CHIP:IN: Prepared unauthenticated message 0xffffcb892158 to 0x0000000000000000 (0)  of type 0x10 and protocolId (0, 0) on exchange 58666r with MessageCounter:226636421.
[1655213700.598954][17592:17592] CHIP:IN: Sending unauthenticated msg 0xffffcb892158 with MessageCounter:226636421 to 0x0000000000000000 at monotonic time: 0000000001A80202 msec
[1655213700.599188][17592:17592] CHIP:EM: Flushed pending ack for MessageCounter:42217812 on exchange 58666r
[1655213700.599482][17592:17592] CHIP:EM: Received message of type 0xa with protocolId (0, 1) and MessageCounter:225790207 on exchange 58667r
[1655213700.599552][17592:17592] CHIP:EM: Handling via exchange: 58667r, Delegate: 0xaaaae2cf02b0
[1655213700.599681][17592:17592] CHIP:DMG: TimedRequestMessage =
[1655213700.599733][17592:17592] CHIP:DMG: {
[1655213700.599777][17592:17592] CHIP:DMG:      TimeoutMs = 0x3e8,
[1655213700.599824][17592:17592] CHIP:DMG:      InteractionModelRevision = 1
[1655213700.599867][17592:17592] CHIP:DMG: }
[1655213700.599930][17592:17592] CHIP:DMG: Got Timed Request with timeout 1000: handler 0xaaaae9a7cd10 exchange 58667r
[1655213700.600029][17592:17592] CHIP:EM: Piggybacking Ack for MessageCounter:225790207 on exchange: 58667r
[1655213700.600144][17592:17592] CHIP:IN: Prepared secure message 0xaaaae2cfd618 to 0x000000000001B669 (1)  of type 0x1 and protocolId (0, 1) on exchange 58667r with MessageCounter:223344283.
[1655213700.600207][17592:17592] CHIP:IN: Sending encrypted msg 0xaaaae2cfd618 with MessageCounter:223344283 to 0x000000000001B669 (1) at monotonic time: 0000000001A80203 msec
[1655213700.600469][17592:17592] CHIP:DMG: Timed Request time limit 0x0000000001A805EB: handler 0xaaaae9a7cd10 exchange 58667r
[1655213700.601316][17592:17592] CHIP:EM: Received message of type 0x8 with protocolId (0, 1) and MessageCounter:225790208 on exchange 58667r
[1655213700.601371][17592:17592] CHIP:EM: Found matching exchange: 58667r, Delegate: 0xaaaae9a7cd10
[1655213700.601433][17592:17592] CHIP:EM: Rxd Ack; Removing MessageCounter:223344283 from Retrans Table on exchange 58667r
[1655213700.601476][17592:17592] CHIP:EM: Removed CHIP MessageCounter:223344283 from RetransTable on exchange 58667r
[1655213700.601532][17592:17592] CHIP:DMG: Timed following action arrived at 0x0000000001A80204: handler 0xaaaae9a7cd10 exchange 58667r
[1655213700.601576][17592:17592] CHIP:DMG: Handing timed invoke to IM engine: handler 0xaaaae9a7cd10 exchange 58667r
[1655213700.601656][17592:17592] CHIP:DMG: InvokeRequestMessage =
[1655213700.601702][17592:17592] CHIP:DMG: {
[1655213700.601744][17592:17592] CHIP:DMG:      suppressResponse = false,
[1655213700.601801][17592:17592] CHIP:DMG:      timedRequest = true,
[1655213700.601847][17592:17592] CHIP:DMG:      InvokeRequests =
[1655213700.601907][17592:17592] CHIP:DMG:      [
[1655213700.601951][17592:17592] CHIP:DMG:              CommandDataIB =
[1655213700.602000][17592:17592] CHIP:DMG:              {
[1655213700.602047][17592:17592] CHIP:DMG:                      CommandPathIB =
[1655213700.602103][17592:17592] CHIP:DMG:                      {
[1655213700.602163][17592:17592] CHIP:DMG:                              EndpointId = 0x1,
[1655213700.602225][17592:17592] CHIP:DMG:                              ClusterId = 0x101,
[1655213700.602286][17592:17592] CHIP:DMG:                              CommandId = 0x1a,
[1655213700.602349][17592:17592] CHIP:DMG:                      },
[1655213700.602408][17592:17592] CHIP:DMG:
[1655213700.602456][17592:17592] CHIP:DMG:                      CommandFields =
[1655213700.602511][17592:17592] CHIP:DMG:                      {
[1655213700.602571][17592:17592] CHIP:DMG:                              0x0 = 0,
[1655213700.602740][17592:17592] CHIP:DMG:                              0x1 = 2,
[1655213700.602815][17592:17592] CHIP:DMG:                              0x2 = "xxx",
[1655213700.602884][17592:17592] CHIP:DMG:                              0x3 = 6451,
[1655213700.602944][17592:17592] CHIP:DMG:                              0x4 = 1,
[1655213700.603012][17592:17592] CHIP:DMG:                              0x5 = 10,
[1655213700.603078][17592:17592] CHIP:DMG:                              0x6 = 3,
[1655213700.603141][17592:17592] CHIP:DMG:                      },
[1655213700.603194][17592:17592] CHIP:DMG:              },
[1655213700.603259][17592:17592] CHIP:DMG:
[1655213700.603303][17592:17592] CHIP:DMG:      ],
[1655213700.603361][17592:17592] CHIP:DMG:
[1655213700.603405][17592:17592] CHIP:DMG:      InteractionModelRevision = 1
[1655213700.603447][17592:17592] CHIP:DMG: },
[1655213700.603564][17592:17592] CHIP:DMG: AccessControl: checking f=1 a=c s=0x000000000001B669 t= c=0x0000_0101 e=1 p=a
[1655213700.603624][17592:17592] CHIP:DMG: AccessControl: allowed
[1655213700.603673][17592:17592] CHIP:DMG: Received command for Endpoint=1 Cluster=0x0000_0101 Command=0x0000_001A
[1655213700.603752][17592:17592] CHIP:ZCL: [SetUser] Incoming command [endpointId=1,userIndex=2]
[1655213700.603819][17592:17592] CHIP:ZCL: Lock App: LockEndpoint::GetUser [endpoint=1,userIndex=2]
[1655213700.603860][17592:17592] CHIP:ZCL: Found unoccupied user [endpoint=1,adjustedIndex=1]
[1655213700.603901][17592:17592] CHIP:ZCL: Lock App: LockEndpoint::SetUser [endpoint=1,userIndex=2,creator=1,modifier=1,userName="xxx",uniqueId=1933,userStatus=1,userType=10,credentialRule=3,credentials=(nil),totalCredentials=0]
[1655213700.603950][17592:17592] CHIP:ZCL: Successfully set the user [mEndpointId=1,index=2,adjustedIndex=1]
[1655213700.603988][17592:17592] CHIP:ZCL: [createUser] User created [endpointId=1,creatorFabricId=1,userIndex=2,userName="xxx",userUniqueId=0x1933,userStatus=1,userType=10,credentialRule=3,totalCredentials=0]
[1655213700.604090][17592:17592] CHIP:EVL: LogEvent event number: 0x0000000000000002 priority: 1, endpoint id:  0x1 cluster id: 0x0000_0101 event id: 0x4 Sys timestamp: 0x0000000001A80207
[1655213700.604121][17592:17592] CHIP:ZCL: [RemoteLockUserChange] Sent lock user change event [endpointId=1,eventNumber=2,dataType=2,operation=0,nodeId=112233,fabricIndex=1]
[1655213700.604154][17592:17592] CHIP:DMG: ICR moving to [ Preparing]
[1655213700.604184][17592:17592] CHIP:DMG: ICR moving to [AddingComm]
[1655213700.604261][17592:17592] CHIP:DMG: ICR moving to [AddedComma]
[1655213700.604307][17592:17592] CHIP:DMG: Decreasing reference count for CommandHandler, remaining 0
[1655213700.604339][17592:17592] CHIP:EM: Piggybacking Ack for MessageCounter:225790208 on exchange: 58667r
[1655213700.604400][17592:17592] CHIP:IN: Prepared secure message 0xaaaae2cfd618 to 0x000000000001B669 (1)  of type 0x9 and protocolId (0, 1) on exchange 58667r with MessageCounter:223344284.
[1655213700.604439][17592:17592] CHIP:IN: Sending encrypted msg 0xaaaae2cfd618 with MessageCounter:223344284 to 0x000000000001B669 (1) at monotonic time: 0000000001A80207 msec
[1655213700.604610][17592:17592] CHIP:DMG: ICR moving to [CommandSen]
[1655213700.604637][17592:17592] CHIP:DMG: ICR moving to [AwaitingDe]
[1655213700.606340][17592:17592] CHIP:EM: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:225790209 on exchange 58667r
[1655213700.606372][17592:17592] CHIP:EM: Found matching exchange: 58667r, Delegate: (nil)
[1655213700.606407][17592:17592] CHIP:EM: Rxd Ack; Removing MessageCounter:223344284 from Retrans Table on exchange 58667r
[1655213700.606431][17592:17592] CHIP:EM: Removed CHIP MessageCounter:223344284 from RetransTable on exchange 58667r


@bzbarsky-apple bzbarsky-apple added spec Mismatch between spec and implementation app-clusters Application cluster work V1.0 labels Jun 14, 2022
@bzbarsky-apple
Copy link
Contributor

@Morozov-5F do you have time to take a look at this one? Or any pointers to anyone else working on door locks?

@andy31415
Copy link
Contributor

@Ashwinigrl - for future bug reports, please attach logs instead of pasting (paste only small excerpts that are human reviewed for relevance). https://github.com/project-chip/connectedhomeip/blob/master/docs/BUG_REPORT.md

@andy31415
Copy link
Contributor

The actual command would also be useful for fast reproduction. the command you used for chip-tool (or set of commands) would allow developers to quickly reproduce this.

@bzbarsky-apple
Copy link
Contributor

The actual command would also be useful for fast reproduction

It's at the top of the first log:

./chip-tool doorlock set-user 0 2 xxx 6451 1 10 3 1 1 --timedInteractionTimeoutMs 1000

That "10" is out of range of the enum.

@sumaky
Copy link
Contributor

sumaky commented Jun 15, 2022

@bzbarsky-apple 10 is out of range. We expected a failure but seeing success.

@Morozov-5F
Copy link
Contributor

It is really interesting. The userType is provided to cluster code as an enum class DlUserType, which is generated straight from door-lock-cluster.xml definition.
I assumed that such parameters range would be checked by the underlying SDK code but it appears to be the opposite. I'm still not sure how to feel about this but anyway it requires a lot of code changes, mostly trivial: we need to add the range checks for each parameter in the commands.

@woody-apple
Copy link
Contributor

Spec Issue Review: Assigning to @Morozov-5F

@woody-apple
Copy link
Contributor

Spec Issue Review: Tagging cert blocker.

@bzbarsky-apple
Copy link
Contributor

@Morozov-5F Yes, the underlying code does not yet know to do range checks on enums.... Sorry. :(

@Morozov-5F
Copy link
Contributor

@bzbarsky-apple no problem, should be a fairly straightforward fix

Morozov-5F added a commit to Morozov-5F/connectedhomeip that referenced this issue Jun 21, 2022
- Refactor the cluster, so it is consistent in way of handling commands
@cjandhyala cjandhyala changed the title Door-lock Set User Command is returning success instead of INVALID_COMMAND [TC-DRLK-2.8] Door-lock Set User Command is returning success instead of INVALID_COMMAND Jun 28, 2022
Morozov-5F added a commit to Morozov-5F/connectedhomeip that referenced this issue Jul 6, 2022
- Refactor the cluster, so it is consistent in way of handling commands
Morozov-5F added a commit to Morozov-5F/connectedhomeip that referenced this issue Jul 6, 2022
- Refactor the cluster, so it is consistent in way of handling commands
Morozov-5F added a commit to Morozov-5F/connectedhomeip that referenced this issue Jul 7, 2022
- Refactor the cluster, so it is consistent in way of handling commands
selissia pushed a commit that referenced this issue Jul 7, 2022
* [#19622] Return generic failure instead of not found for schedule operations in the door lock

* [#19563] Check enum ranges for Door Lock commands
- Refactor the cluster, so it is consistent in way of handling commands

* Refactoring of the door lock cluster: move credential error checking into a single function, fix typos

* Fix tests for Door Lock cluster and run them against the lock app

* Update auto-generated files
github-actions bot pushed a commit that referenced this issue Jul 7, 2022
* [#19622] Return generic failure instead of not found for schedule operations in the door lock

* [#19563] Check enum ranges for Door Lock commands
- Refactor the cluster, so it is consistent in way of handling commands

* Refactoring of the door lock cluster: move credential error checking into a single function, fix typos

* Fix tests for Door Lock cluster and run them against the lock app

* Update auto-generated files
andy31415 pushed a commit that referenced this issue Jul 7, 2022
* [#19622] Return generic failure instead of not found for schedule operations in the door lock

* [#19563] Check enum ranges for Door Lock commands
- Refactor the cluster, so it is consistent in way of handling commands

* Refactoring of the door lock cluster: move credential error checking into a single function, fix typos

* Fix tests for Door Lock cluster and run them against the lock app

* Update auto-generated files

Co-authored-by: Evgeniy Morozov <[email protected]>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
app-clusters Application cluster work cert blocker spec Mismatch between spec and implementation V1.0
Projects
None yet
Development

Successfully merging a pull request may close this issue.

6 participants