search

project-chip / connectedhomeip

Matter (formerly Project CHIP) creates more connections between more objects, simplifying development for manufacturers and increasing compatibility for consumers, guided by the Connectivity Standards Alliance.
https://buildwithmatter.com
Apache License 2.0
7.47k stars 2k forks source link

[SQA] TC-DM-4.4 DUT fails to send "ScanNetworksResponse" command to the TH #17503

Closed Survensa closed 2 years ago

Survensa commented 2 years ago

Issue : ScanNetworks command for listing all available WiFinetworks within the range fails

Referance : https://github.com/CHIP-Specifications/chip-test-plans/blob/master/src/devicemanagement.adoc#test-procedure-14

Commit used : 20e1a4a705770d5222a8ebf04e12ab2ce0304df6

Platform : RPI ( ble-wifi )

Expected outcome: 

[1648124672.377157][9331:9336] CHIP:TOO: Endpoint: 0 Cluster: 0x0000_0031 Command 0x0000_0001
[1648124672.377274][9331:9336] CHIP:TOO:   ScanNetworksResponse: {
[1648124672.377301][9331:9336] CHIP:TOO:     networkingStatus: 0
[1648124672.377325][9331:9336] CHIP:TOO:     debugText:
[1648124672.377403][9331:9336] CHIP:TOO:     wiFiScanResults: 15 entries
[1648124672.377472][9331:9336] CHIP:TOO:       [1]: {
[1648124672.377496][9331:9336] CHIP:TOO:         Security: 8
[1648124672.377520][9331:9336] CHIP:TOO:         Ssid: 47524C507269766174655F455854
[1648124672.377543][9331:9336] CHIP:TOO:         Bssid: E01CFCE4B236
[1648124672.377565][9331:9336] CHIP:TOO:         Channel: 11
[1648124672.377586][9331:9336] CHIP:TOO:         WiFiBand: 0
[1648124672.377608][9331:9336] CHIP:TOO:         Rssi: -7
[1648124672.377631][9331:9336] CHIP:TOO:        }
[1648124672.377663][9331:9336] CHIP:TOO:       [2]: {
[1648124672.377686][9331:9336] CHIP:TOO:         Security: 8
[1648124672.377709][9331:9336] CHIP:TOO:         Ssid: 47524C50726976617465
[1648124672.377731][9331:9336] CHIP:TOO:         Bssid: 6032B197B89F
[1648124672.377753][9331:9336] CHIP:TOO:         Channel: 153
[1648124672.377774][9331:9336] CHIP:TOO:         WiFiBand: 2
[1648124672.377795][9331:9336] CHIP:TOO:         Rssi: -47
[1648124672.377816][9331:9336] CHIP:TOO:        }
[1648124672.377847][9331:9336] CHIP:TOO:       [3]: {
[1648124672.377870][9331:9336] CHIP:TOO:         Security: 8
[1648124672.377891][9331:9336] CHIP:TOO:         Ssid:
[1648124672.377913][9331:9336] CHIP:TOO:         Bssid: 6632B197B89F
[1648124672.377934][9331:9336] CHIP:TOO:         Channel: 153
[1648124672.377955][9331:9336] CHIP:TOO:         WiFiBand: 2
[1648124672.377976][9331:9336] CHIP:TOO:         Rssi: -47
[1648124672.377997][9331:9336] CHIP:TOO:        }
[1648124672.380203][9331:9336] CHIP:TOO:    }
[1648124672.380331][9331:9336] CHIP:DMG: ICR moving to [AwaitingDe]
[1648124672.380389][9331:9336] CHIP:EM: Sending Standalone Ack for MessageCounter:3026423 on exchange 22723i

Actual outcome :

[1650374520.850094][44931:44936] CHIP:EM: Removed CHIP MessageCounter:13773792 from RetransTable on exchange 54588i
[1650374520.850214][44931:44936] CHIP:DMG: ICR moving to [ResponseRe]
[1650374520.850347][44931:44936] CHIP:DMG: InvokeResponseMessage =
[1650374520.850412][44931:44936] CHIP:DMG: {
[1650374520.850491][44931:44936] CHIP:DMG:      suppressResponse = false,
[1650374520.850554][44931:44936] CHIP:DMG:      InvokeResponseIBs =
[1650374520.850650][44931:44936] CHIP:DMG:      [
[1650374520.850712][44931:44936] CHIP:DMG:              InvokeResponseIB =
[1650374520.850818][44931:44936] CHIP:DMG:              {
[1650374520.850884][44931:44936] CHIP:DMG:                      CommandStatusIB =
[1650374520.850981][44931:44936] CHIP:DMG:                      {
[1650374520.851058][44931:44936] CHIP:DMG:                              CommandPathIB =
[1650374520.851163][44931:44936] CHIP:DMG:                              {
[1650374520.851276][44931:44936] CHIP:DMG:                                      EndpointId = 0x1,
[1650374520.851364][44931:44936] CHIP:DMG:                                      ClusterId = 0x31,
[1650374520.851478][44931:44936] CHIP:DMG:                                      CommandId = 0x0,
[1650374520.851582][44931:44936] CHIP:DMG:                              },
[1650374520.851684][44931:44936] CHIP:DMG:
[1650374520.851780][44931:44936] CHIP:DMG:                              StatusIB =
[1650374520.851884][44931:44936] CHIP:DMG:                              {
[1650374520.851996][44931:44936] CHIP:DMG:                                      status = 0xc3 (UNSUPPORTED_CLUSTER),
[1650374520.852085][44931:44936] CHIP:DMG:                              },
[1650374520.852186][44931:44936] CHIP:DMG:
[1650374520.852263][44931:44936] CHIP:DMG:                      },
[1650374520.852376][44931:44936] CHIP:DMG:
[1650374520.852463][44931:44936] CHIP:DMG:              },
[1650374520.852545][44931:44936] CHIP:DMG:
[1650374520.852627][44931:44936] CHIP:DMG:      ],
[1650374520.852703][44931:44936] CHIP:DMG:
[1650374520.852785][44931:44936] CHIP:DMG:      InteractionModelRevision = 1
[1650374520.852845][44931:44936] CHIP:DMG: },
[1650374520.853006][44931:44936] CHIP:DMG: Received Command Response Status for Endpoint=1 Cluster=0x0000_0031 Command=0x0000_0000 Status=0xc3
[1650374520.853107][44931:44936] CHIP:TOO: Error: IM Error 0x000005C3: General error: 0xc3 (UNSUPPORTED_CLUSTER)
[1650374520.853197][44931:44936] CHIP:DMG: ICR moving to [AwaitingDe]
[1650374520.853331][44931:44936] CHIP:EM: Sending Standalone Ack for MessageCounter:3661564 on exchange 54588i
[1650374520.853485][44931:44936] CHIP:IN: Prepared secure message 0xffff9a557938 to 0x0000000000000001 (1)  of type 0x10 and protocolId (0, 0) on exchange 54588i with MessageCounter:13773793.
[1650374520.853572][44931:44936] CHIP:IN: Sending encrypted msg 0xffff9a557938 with MessageCounter:13773793 to 0x0000000000000001 (1) at monotonic time: 0000000001A80B47 msec

Error log :

TC_DM_4.4 Error log

erjiaqing commented 2 years ago

From the log

[1650374520.851058][44931:44936] CHIP:DMG:                              CommandPathIB =
[1650374520.851163][44931:44936] CHIP:DMG:                              {
[1650374520.851276][44931:44936] CHIP:DMG:                                      EndpointId = 0x1,
[1650374520.851364][44931:44936] CHIP:DMG:                                      ClusterId = 0x31,
[1650374520.851478][44931:44936] CHIP:DMG:                                      CommandId = 0x0,
[1650374520.851582][44931:44936] CHIP:DMG:                              },

Seems you are sending this command to Endpoint 1

Network Commissioning cluster does not live on endpoint 1, since the device type of endpoint 1 does not support network commissioning cluster.

Please use endpoint 0

Survensa commented 2 years ago

@erjiaqing Verified using both the endpoints 1 and 0 and below are the results

log for end point 0 :

./chip-tool networkcommissioning scan-networks 1 0

[1650431602.261927][6054:6059] CHIP:EM: Removed CHIP MessageCounter:13506436 from RetransTable on exchange 43630i
[1650431602.261997][6054:6059] CHIP:DMG: ICR moving to [ResponseRe]
[1650431602.262100][6054:6059] CHIP:DMG: InvokeResponseMessage =
[1650431602.262159][6054:6059] CHIP:DMG: {
[1650431602.262216][6054:6059] CHIP:DMG:        suppressResponse = false,
[1650431602.262278][6054:6059] CHIP:DMG:        InvokeResponseIBs =
[1650431602.262353][6054:6059] CHIP:DMG:        [
[1650431602.262414][6054:6059] CHIP:DMG:                InvokeResponseIB =
[1650431602.262504][6054:6059] CHIP:DMG:                {
[1650431602.262570][6054:6059] CHIP:DMG:                        CommandStatusIB =
[1650431602.262646][6054:6059] CHIP:DMG:                        {
[1650431602.262769][6054:6059] CHIP:DMG:                                CommandPathIB =
[1650431602.262859][6054:6059] CHIP:DMG:                                {
[1650431602.262935][6054:6059] CHIP:DMG:                                        EndpointId = 0x0,
[1650431602.263023][6054:6059] CHIP:DMG:                                        ClusterId = 0x31,
[1650431602.263115][6054:6059] CHIP:DMG:                                        CommandId = 0x0,
[1650431602.263195][6054:6059] CHIP:DMG:                                },
[1650431602.263277][6054:6059] CHIP:DMG:
[1650431602.263352][6054:6059] CHIP:DMG:                                StatusIB =
[1650431602.263448][6054:6059] CHIP:DMG:                                {
[1650431602.263526][6054:6059] CHIP:DMG:                                        status = 0x85 (INVALID_COMMAND),
[1650431602.263598][6054:6059] CHIP:DMG:                                },
[1650431602.263669][6054:6059] CHIP:DMG:
[1650431602.263733][6054:6059] CHIP:DMG:                        },
[1650431602.263809][6054:6059] CHIP:DMG:
[1650431602.263868][6054:6059] CHIP:DMG:                },
[1650431602.263936][6054:6059] CHIP:DMG:
[1650431602.263986][6054:6059] CHIP:DMG:        ],
[1650431602.264050][6054:6059] CHIP:DMG:
[1650431602.264100][6054:6059] CHIP:DMG:        InteractionModelRevision = 1
[1650431602.264150][6054:6059] CHIP:DMG: },
[1650431602.264272][6054:6059] CHIP:DMG: Received Command Response Status for Endpoint=0 Cluster=0x0000_0031 Command=0x0000_0000 Status=0x85
[1650431602.264339][6054:6059] CHIP:TOO: Error: IM Error 0x00000585: General error: 0x85 (INVALID_COMMAND)

Attched full log for the referance :
NC error log.txt

Survensa commented 2 years ago

Hi @erjiaqing, below are my observations on this issue.

Observation:

  1. DUT and TH are commissioned with EP0.
  2. while executing the scan-networks command expected arguments are 4 ( SSID, Breadcrumb, NodeID and Endpoint)
  3. But in Chip-tool the scan-networks command is accepting only 2 arguments ( NodeID and Endpoint)
  4. As the Network commissioning is live on Endpoint 0 and commissioning is also executed on endpoint 0. So it's expected to get output on endpoint 0.

Questions:

  1. Why scan-networks command could not be executed with EP0? When commission and network commissioning are both live in EP0.

    1. As per specification scan-networks command needs to have 4 arguments? But in chip-tool, it's accepting only 2 arguments ( NodeID and Endpoint)

Actual behavior:

with EP0 ubuntu@matter-7:~/cntrl/connectedhomeip/examples/chip-tool/out/debug$ ./chip-tool networkcommissioning scan-networks 1 0

The output is 0x85 (INVALID_COMMAND)

Logs:

DM.4.4_Error_log.txt

erjiaqing commented 2 years ago

After checking the spec, and the code, this is an expected behavior.

ScanNetworks accepts a Nullable ssid (required field for WiFi endpoint) and a Optional breadcrumb.

The the correct request is sending a null ssid instead of missing ssid.

The code works fine with repl as the controller.

In [24]: await devCtrl.SendCommand(1, 0, Clusters.NetworkCommissioning.Commands.ScanNetworks(ssid=Clusters.Types.NullValue))
Out[24]: 
ScanNetworksResponse(
│   networkingStatus=<NetworkCommissioningStatus.kSuccess: 0>,
│   debugText=None,
│   wiFiScanResults=[
│   │   WiFiInterfaceScanResult(
│   │   │   security=24,
│   │   │   ssid=b'(personal wifi)',
│   │   │   bssid=b'(personal wifi)',
│   │   │   channel=4,
│   │   │   wiFiBand=<WiFiBand.k2g4: 0>,
│   │   │   rssi=-41
│   │   ),
Survensa commented 2 years ago

Used the command :./chip-tool networkcommissioning scan-networks 1 0 --Ssid null --Breadcrumb 0

We can able to get expected outcome as below :


[1650440008.081437][6696:6701] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0031 Command=0x0000_0001
[1650440008.081495][6696:6701] CHIP:TOO: Endpoint: 0 Cluster: 0x0000_0031 Command 0x0000_0001
[1650440008.081615][6696:6701] CHIP:TOO:   ScanNetworksResponse: {
[1650440008.081668][6696:6701] CHIP:TOO:     networkingStatus: 0
[1650440008.081763][6696:6701] CHIP:TOO:     wiFiScanResults: 15 entries
[1650440008.081841][6696:6701] CHIP:TOO:       [1]: {
[1650440008.081865][6696:6701] CHIP:TOO:         Security: 12
[1650440008.081890][6696:6701] CHIP:TOO:         Ssid: 63686970736574757033
[1650440008.081913][6696:6701] CHIP:TOO:         Bssid: 0C0E764D4144
[1650440008.081935][6696:6701] CHIP:TOO:         Channel: 11
[1650440008.081957][6696:6701] CHIP:TOO:         WiFiBand: 0
[1650440008.081980][6696:6701] CHIP:TOO:         Rssi: -10
[1650440008.082004][6696:6701] CHIP:TOO:        }
[1650440008.082036][6696:6701] CHIP:TOO:       [2]: {
[1650440008.082058][6696:6701] CHIP:TOO:         Security: 12
[1650440008.082081][6696:6701] CHIP:TOO:         Ssid: 7A69676265652D7468726561642D3547487A
[1650440008.082103][6696:6701] CHIP:TOO:         Bssid: 6C198FC83ABE
[1650440008.082125][6696:6701] CHIP:TOO:         Channel: 44
[1650440008.082147][6696:6701] CHIP:TOO:         WiFiBand: 2
[1650440008.082168][6696:6701] CHIP:TOO:         Rssi: -32
[1650440008.082189][6696:6701] CHIP:TOO:        }
[1650440008.082220][6696:6701] CHIP:TOO:       [3]: {
[1650440008.082243][6696:6701] CHIP:TOO:         Security: 8
[1650440008.082266][6696:6701] CHIP:TOO:         Ssid: 47524C50726976617465
[1650440008.082288][6696:6701] CHIP:TOO:         Bssid: 6032B197B89F
[1650440008.082309][6696:6701] CHIP:TOO:         Channel: 153
[1650440008.082331][6696:6701] CHIP:TOO:         WiFiBand: 2
[1650440008.082352][6696:6701] CHIP:TOO:         Rssi: -37
[1650440008.082373][6696:6701] CHIP:TOO:        }
[1650440008.082404][6696:6701] CHIP:TOO:       [4]: {
[1650440008.082426][6696:6701] CHIP:TOO:         Security: 8
[1650440008.082448][6696:6701] CHIP:TOO:         Ssid:
[1650440008.082469][6696:6701] CHIP:TOO:         Bssid: 6632B197B89F
[1650440008.082491][6696:6701] CHIP:TOO:         Channel: 153
[1650440008.082512][6696:6701] CHIP:TOO:         WiFiBand: 2
[1650440008.082534][6696:6701] CHIP:TOO:         Rssi: -34
[1650440008.082555][6696:6701] CHIP:TOO:        }
[1650440008.082585][6696:6701] CHIP:TOO:       [5]: {
[1650440008.082607][6696:6701] CHIP:TOO:         Security: 8
[1650440008.082629][6696:6701] CHIP:TOO:         Ssid: 7A6967626565315F3547
[1650440008.082651][6696:6701] CHIP:TOO:         Bssid: E848B8C2123A
[1650440008.082689][6696:6701] CHIP:TOO:         Channel: 153
[1650440008.082710][6696:6701] CHIP:TOO:         WiFiBand: 2
[1650440008.082732][6696:6701] CHIP:TOO:         Rssi: -50
[1650440008.082753][6696:6701] CHIP:TOO:        }
[1650440008.082783][6696:6701] CHIP:TOO:       [6]: {
[1650440008.082806][6696:6701] CHIP:TOO:         Security: 8
[1650440008.082828][6696:6701] CHIP:TOO:         Ssid: 47524C50726976617465
[1650440008.082850][6696:6701] CHIP:TOO:         Bssid: C006C3F95EEB
[1650440008.082871][6696:6701] CHIP:TOO:         Channel: 153
[1650440008.082893][6696:6701] CHIP:TOO:         WiFiBand: 2
[1650440008.082914][6696:6701] CHIP:TOO:         Rssi: -45
[1650440008.082935][6696:6701] CHIP:TOO:        }
[1650440008.082965][6696:6701] CHIP:TOO:       [7]: {
[1650440008.082987][6696:6701] CHIP:TOO:         Security: 8
[1650440008.083009][6696:6701] CHIP:TOO:         Ssid: 47524C50726976617465
[1650440008.083031][6696:6701] CHIP:TOO:         Bssid: C006C3F95F31
[1650440008.083052][6696:6701] CHIP:TOO:         Channel: 48
[1650440008.083074][6696:6701] CHIP:TOO:         WiFiBand: 2
[1650440008.083095][6696:6701] CHIP:TOO:         Rssi: -51
[1650440008.083117][6696:6701] CHIP:TOO:        }
[1650440008.083146][6696:6701] CHIP:TOO:       [8]: {
[1650440008.083168][6696:6701] CHIP:TOO:         Security: 8
[1650440008.083192][6696:6701] CHIP:TOO:         Ssid: 4449524543542D564C4445534B544F502D3735334B364B4C6D735A55
[1650440008.083214][6696:6701] CHIP:TOO:         Bssid: E66A6A36F393
[1650440008.083236][6696:6701] CHIP:TOO:         Channel: 153
[1650440008.083257][6696:6701] CHIP:TOO:         WiFiBand: 2
[1650440008.083278][6696:6701] CHIP:TOO:         Rssi: -67
[1650440008.083299][6696:6701] CHIP:TOO:        }
[1650440008.083329][6696:6701] CHIP:TOO:       [9]: {
[1650440008.083352][6696:6701] CHIP:TOO:         Security: 8
[1650440008.083374][6696:6701] CHIP:TOO:         Ssid:
[1650440008.083395][6696:6701] CHIP:TOO:         Bssid: 1627F5374EC7
[1650440008.083417][6696:6701] CHIP:TOO:         Channel: 153
[1650440008.083438][6696:6701] CHIP:TOO:         WiFiBand: 2
[1650440008.083459][6696:6701] CHIP:TOO:         Rssi: -67
[1650440008.083480][6696:6701] CHIP:TOO:        }
[1650440008.083510][6696:6701] CHIP:TOO:       [10]: {
[1650440008.083533][6696:6701] CHIP:TOO:         Security: 8
[1650440008.083555][6696:6701] CHIP:TOO:         Ssid: 47524C50726976617465
[1650440008.083576][6696:6701] CHIP:TOO:         Bssid: 1027F5374EC7
[1650440008.083598][6696:6701] CHIP:TOO:         Channel: 153
[1650440008.083619][6696:6701] CHIP:TOO:         WiFiBand: 2
[1650440008.083640][6696:6701] CHIP:TOO:         Rssi: -70
[1650440008.083661][6696:6701] CHIP:TOO:        }
[1650440008.083691][6696:6701] CHIP:TOO:       [11]: {
[1650440008.083714][6696:6701] CHIP:TOO:         Security: 8
[1650440008.083735][6696:6701] CHIP:TOO:         Ssid: 47524C50726976617465
[1650440008.083758][6696:6701] CHIP:TOO:         Bssid: B0BE7653B01B
[1650440008.083779][6696:6701] CHIP:TOO:         Channel: 40
[1650440008.083800][6696:6701] CHIP:TOO:         WiFiBand: 2
[1650440008.083821][6696:6701] CHIP:TOO:         Rssi: -68
[1650440008.083843][6696:6701] CHIP:TOO:        }
[1650440008.083872][6696:6701] CHIP:TOO:       [12]: {
[1650440008.083895][6696:6701] CHIP:TOO:         Security: 8
[1650440008.083917][6696:6701] CHIP:TOO:         Ssid: 7A696762656531
[1650440008.083939][6696:6701] CHIP:TOO:         Bssid: E848B8C2123B
[1650440008.083960][6696:6701] CHIP:TOO:         Channel: 9
[1650440008.083981][6696:6701] CHIP:TOO:         WiFiBand: 0
[1650440008.084002][6696:6701] CHIP:TOO:         Rssi: -26
[1650440008.084024][6696:6701] CHIP:TOO:        }
[1650440008.084054][6696:6701] CHIP:TOO:       [13]: {
[1650440008.084077][6696:6701] CHIP:TOO:         Security: 12
[1650440008.084099][6696:6701] CHIP:TOO:         Ssid: 7A6967626565686F6D65
[1650440008.084121][6696:6701] CHIP:TOO:         Bssid: 0C0E764CB140
[1650440008.084142][6696:6701] CHIP:TOO:         Channel: 10
[1650440008.084164][6696:6701] CHIP:TOO:         WiFiBand: 0
[1650440008.084185][6696:6701] CHIP:TOO:         Rssi: -38
[1650440008.084206][6696:6701] CHIP:TOO:        }
[1650440008.084236][6696:6701] CHIP:TOO:       [14]: {
[1650440008.084259][6696:6701] CHIP:TOO:         Security: 12
[1650440008.084281][6696:6701] CHIP:TOO:         Ssid: 43686970736574757034
[1650440008.084303][6696:6701] CHIP:TOO:         Bssid: 0C0E764EF338
[1650440008.084324][6696:6701] CHIP:TOO:         Channel: 11
[1650440008.084345][6696:6701] CHIP:TOO:         WiFiBand: 0
[1650440008.084367][6696:6701] CHIP:TOO:         Rssi: -25
[1650440008.084388][6696:6701] CHIP:TOO:        }
[1650440008.084418][6696:6701] CHIP:TOO:       [15]: {
[1650440008.084441][6696:6701] CHIP:TOO:         Security: 8
[1650440008.084463][6696:6701] CHIP:TOO:         Ssid: 47524C50726976617465
[1650440008.084485][6696:6701] CHIP:TOO:         Bssid: 6032B197B89E
[1650440008.084507][6696:6701] CHIP:TOO:         Channel: 11
[1650440008.084528][6696:6701] CHIP:TOO:         WiFiBand: 0
[1650440008.084549][6696:6701] CHIP:TOO:         Rssi: -29
[1650440008.084570][6696:6701] CHIP:TOO:        }
[1650440008.084594][6696:6701] CHIP:TOO:    }
[1650440008.084735][6696:6701] CHIP:DMG: ICR moving to [AwaitingDe]
[1650440008.084796][6696:6701] CHIP:EM: Sending Standalone Ack for MessageCounter:1915221 on exchange 33200i