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.49k stars 2.01k forks source link

[BUG] Failed to do thread commissioning with iOS chip-tool mobile application #31537

Open Mitun90 opened 10 months ago

Mitun90 commented 10 months ago

Reproduction steps

I'm facing issue when trying to commissioning Thread board in iOS Darwin application. During commissioning process I got error like "CHIP Error 0x000000AC: Internal error'".

please review below logs.

2024-01-18 12:24:04.492836+0530 CHIPTool[525:15389] [Controller] Device confirmed that it has received the root certificate
2024-01-18 12:24:04.492904+0530 CHIPTool[525:15389] [Controller] Successfully finished commissioning step 'SendTrustedRootCert'
2024-01-18 12:24:04.493015+0530 CHIPTool[525:15389] [Controller] Commissioning stage next step: 'SendTrustedRootCert' -> 'SendNOC'
2024-01-18 12:24:04.493089+0530 CHIPTool[525:15389] [Controller] Performing next commissioning step 'SendNOC'
2024-01-18 12:24:04.493296+0530 CHIPTool[525:15389] [DataManagement] ICR moving to [AddingComm]
2024-01-18 12:24:04.493392+0530 CHIPTool[525:15389] [DataManagement] ICR moving to [AddedComma]
2024-01-18 12:24:04.494561+0530 CHIPTool[525:15389] [ExchangeManager] <<< [E:43267i S:10445 M:267240482] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:08 (IM:InvokeCommandRequest)
2024-01-18 12:24:04.495156+0530 CHIPTool[525:15389] [DataManagement] ICR moving to [CommandSen]
2024-01-18 12:24:04.495199+0530 CHIPTool[525:15389] [Controller] Sent operational certificate to the device
2024-01-18 12:24:04.495335+0530 CHIPTool[525:15389] [DataManagement] ICR moving to [AwaitingDe]
2024-01-18 12:24:04.612140+0530 CHIPTool[525:15043] [ExchangeManager] >>> [E:43267i S:10445 M:31478943] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
2024-01-18 12:24:04.612414+0530 CHIPTool[525:15043] [ExchangeManager] Found matching exchange: 43267i, Delegate: 0x102709278
2024-01-18 12:24:04.612501+0530 CHIPTool[525:15043] [DataManagement] ICR moving to [ResponseRe]
2024-01-18 12:24:04.612569+0530 CHIPTool[525:15043] [DataManagement] InvokeResponseMessage =
2024-01-18 12:24:04.612592+0530 CHIPTool[525:15043] [DataManagement] {
2024-01-18 12:24:04.612612+0530 CHIPTool[525:15043] [DataManagement]    suppressResponse = false,
2024-01-18 12:24:04.612629+0530 CHIPTool[525:15043] [DataManagement]    InvokeResponseIBs =
2024-01-18 12:24:04.612664+0530 CHIPTool[525:15043] [DataManagement]    [
2024-01-18 12:24:04.612683+0530 CHIPTool[525:15043] [DataManagement]        InvokeResponseIB =
2024-01-18 12:24:04.612721+0530 CHIPTool[525:15043] [DataManagement]        {
2024-01-18 12:24:04.612737+0530 CHIPTool[525:15043] [DataManagement]            CommandDataIB =
2024-01-18 12:24:04.612756+0530 CHIPTool[525:15043] [DataManagement]            {
2024-01-18 12:24:04.612773+0530 CHIPTool[525:15043] [DataManagement]                CommandPathIB =
2024-01-18 12:24:04.612791+0530 CHIPTool[525:15043] [DataManagement]                {
2024-01-18 12:24:04.612811+0530 CHIPTool[525:15043] [DataManagement]                    EndpointId = 0x0,
2024-01-18 12:24:04.612829+0530 CHIPTool[525:15043] [DataManagement]                    ClusterId = 0x3e,
2024-01-18 12:24:04.612847+0530 CHIPTool[525:15043] [DataManagement]                    CommandId = 0x8,
2024-01-18 12:24:04.612863+0530 CHIPTool[525:15043] [DataManagement]                },
2024-01-18 12:24:04.612887+0530 CHIPTool[525:15043] [DataManagement] 
2024-01-18 12:24:04.612905+0530 CHIPTool[525:15043] [DataManagement]                CommandFields =
2024-01-18 12:24:04.613474+0530 CHIPTool[525:15043] [DataManagement]                {
2024-01-18 12:24:04.613518+0530 CHIPTool[525:15043] [DataManagement]                    0x0 = 0,
2024-01-18 12:24:04.613543+0530 CHIPTool[525:15043] [DataManagement]                    0x1 = 1,
2024-01-18 12:24:04.613565+0530 CHIPTool[525:15043] [DataManagement]                },
2024-01-18 12:24:04.613582+0530 CHIPTool[525:15043] [DataManagement]            },
2024-01-18 12:24:04.613614+0530 CHIPTool[525:15043] [DataManagement] 
2024-01-18 12:24:04.613630+0530 CHIPTool[525:15043] [DataManagement]        },
2024-01-18 12:24:04.613663+0530 CHIPTool[525:15043] [DataManagement] 
2024-01-18 12:24:04.613678+0530 CHIPTool[525:15043] [DataManagement]    ],
2024-01-18 12:24:04.613821+0530 CHIPTool[525:15043] [DataManagement] 
2024-01-18 12:24:04.613863+0530 CHIPTool[525:15043] [DataManagement]    InteractionModelRevision = 1
2024-01-18 12:24:04.613882+0530 CHIPTool[525:15043] [DataManagement] },
2024-01-18 12:24:04.614009+0530 CHIPTool[525:15043] [DataManagement] Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0008
2024-01-18 12:24:04.614152+0530 CHIPTool[525:15043] [Controller] Device returned status 0 on receiving the NOC
2024-01-18 12:24:04.614234+0530 CHIPTool[525:15043] [Controller] Operational credentials provisioned on device 0x10a01ce00
2024-01-18 12:24:04.614307+0530 CHIPTool[525:15043] [Default] DeviceControllerDelegate status updated: 0
2024-01-18 12:24:04.614458+0530 CHIPTool[525:15043] [Controller] Successfully finished commissioning step 'SendNOC'
2024-01-18 12:24:04.614621+0530 CHIPTool[525:15043] [Controller] No NetworkScan enabled or WiFi/Thread endpoint not specified, skipping ScanNetworks
2024-01-18 12:24:04.614702+0530 CHIPTool[525:15043] [Controller] Commissioning stage next step: 'SendNOC' -> 'ThreadNetworkSetup'
2024-01-18 12:24:04.614777+0530 CHIPTool[525:15043] [Controller] Performing next commissioning step 'ThreadNetworkSetup'
2024-01-18 12:24:04.615804+0530 CHIPTool[525:15043] [DataManagement] ICR moving to [AddingComm]
2024-01-18 12:24:04.615874+0530 CHIPTool[525:15043] [DataManagement] ICR moving to [AddedComma]
2024-01-18 12:24:04.616728+0530 CHIPTool[525:15043] [ExchangeManager] <<< [E:43268i S:10445 M:267240483] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:08 (IM:InvokeCommandRequest)
2024-01-18 12:24:04.617332+0530 CHIPTool[525:15043] [DataManagement] ICR moving to [CommandSen]
2024-01-18 12:24:04.617421+0530 CHIPTool[525:15043] [DataManagement] ICR moving to [AwaitingDe]
2024-01-18 12:24:04.672041+0530 CHIPTool[525:15043] [ExchangeManager] >>> [E:43268i S:10445 M:31478944] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
2024-01-18 12:24:04.672220+0530 CHIPTool[525:15043] [ExchangeManager] Found matching exchange: 43268i, Delegate: 0x1027093c8
2024-01-18 12:24:04.672275+0530 CHIPTool[525:15043] [DataManagement] ICR moving to [ResponseRe]
2024-01-18 12:24:04.672332+0530 CHIPTool[525:15043] [DataManagement] InvokeResponseMessage =
2024-01-18 12:24:04.672355+0530 CHIPTool[525:15043] [DataManagement] {
2024-01-18 12:24:04.672374+0530 CHIPTool[525:15043] [DataManagement]    suppressResponse = false,
2024-01-18 12:24:04.672390+0530 CHIPTool[525:15043] [DataManagement]    InvokeResponseIBs =
2024-01-18 12:24:04.672423+0530 CHIPTool[525:15043] [DataManagement]    [
2024-01-18 12:24:04.672439+0530 CHIPTool[525:15043] [DataManagement]        InvokeResponseIB =
2024-01-18 12:24:04.672471+0530 CHIPTool[525:15043] [DataManagement]        {
2024-01-18 12:24:04.672491+0530 CHIPTool[525:15043] [DataManagement]            CommandDataIB =
2024-01-18 12:24:04.672510+0530 CHIPTool[525:15043] [DataManagement]            {
2024-01-18 12:24:04.672526+0530 CHIPTool[525:15043] [DataManagement]                CommandPathIB =
2024-01-18 12:24:04.672544+0530 CHIPTool[525:15043] [DataManagement]                {
2024-01-18 12:24:04.672567+0530 CHIPTool[525:15043] [DataManagement]                    EndpointId = 0x0,
2024-01-18 12:24:04.672586+0530 CHIPTool[525:15043] [DataManagement]                    ClusterId = 0x31,
2024-01-18 12:24:04.672604+0530 CHIPTool[525:15043] [DataManagement]                    CommandId = 0x5,
2024-01-18 12:24:04.672619+0530 CHIPTool[525:15043] [DataManagement]                },
2024-01-18 12:24:04.672643+0530 CHIPTool[525:15043] [DataManagement] 
2024-01-18 12:24:04.672659+0530 CHIPTool[525:15043] [DataManagement]                CommandFields =
2024-01-18 12:24:04.672680+0530 CHIPTool[525:15043] [DataManagement]                {
2024-01-18 12:24:04.672700+0530 CHIPTool[525:15043] [DataManagement]                    0x0 = 1,
2024-01-18 12:24:04.672719+0530 CHIPTool[525:15043] [DataManagement]                },
2024-01-18 12:24:04.672734+0530 CHIPTool[525:15043] [DataManagement]            },
2024-01-18 12:24:04.672762+0530 CHIPTool[525:15043] [DataManagement] 
2024-01-18 12:24:04.672777+0530 CHIPTool[525:15043] [DataManagement]        },
2024-01-18 12:24:04.673068+0530 CHIPTool[525:15043] [DataManagement] 
2024-01-18 12:24:04.673104+0530 CHIPTool[525:15043] [DataManagement]    ],
2024-01-18 12:24:04.673142+0530 CHIPTool[525:15043] [DataManagement] 
2024-01-18 12:24:04.673163+0530 CHIPTool[525:15043] [DataManagement]    InteractionModelRevision = 1
2024-01-18 12:24:04.673180+0530 CHIPTool[525:15043] [DataManagement] },
2024-01-18 12:24:04.673277+0530 CHIPTool[525:15043] [DataManagement] Received Command Response Data, Endpoint=0 Cluster=0x0000_0031 Command=0x0000_0005
2024-01-18 12:24:04.673503+0530 CHIPTool[525:15043] [Controller] Received NetworkConfig response, networkingStatus=1
2024-01-18 12:24:04.673618+0530 CHIPTool[525:15043] [Controller] Error on commissioning step 'ThreadNetworkSetup': 'src/controller/CHIPDeviceController.cpp:2336: CHIP Error 0x000000AC: Internal error'
2024-01-18 12:24:04.673701+0530 CHIPTool[525:15043] [Controller] Failed to perform commissioning step 21
2024-01-18 12:24:04.673784+0530 CHIPTool[525:15043] [Controller] Going from commissioning step 'ThreadNetworkSetup' with lastErr = 'src/controller/CHIPDeviceController.cpp:2336: CHIP Error 0x000000AC: Internal error' -> 'Cleanup'
2024-01-18 12:24:04.674539+0530 CHIPTool[525:15043] [Controller] Performing next commissioning step 'Cleanup' with completion status = 'src/controller/CHIPDeviceController.cpp:2336: CHIP Error 0x000000AC: Internal error'
2024-01-18 12:24:04.674632+0530 CHIPTool[525:15043] [Controller] Successfully finished commissioning step 'Cleanup'
2024-01-18 12:24:04.674723+0530 CHIPTool[525:15043] [Default] DeviceControllerDelegate Commissioning complete. NodeId 2 Status src/controller/CHIPDeviceController.cpp:2336: CHIP Error 0x000000AC: Internal error
2024-01-18 12:24:04.674881+0530 CHIPTool[525:15389] [Controller] Creating NSError from src/controller/CHIPDeviceController.cpp:2336: CHIP Error 0x000000AC: Internal error
2024-01-18 12:24:04.674888+0530 CHIPTool[525:15043] [DataManagement] ICR moving to [AwaitingDe]
2024-01-18 12:24:04.675544+0530 CHIPTool[525:15389] Error retrieving device informations over Mdns: Error Domain=MTRErrorDomain Code=1 "Undefined error:172." UserInfo={NSLocalizedDescription=Undefined error:172., errorCode=172}

Bug prevalence

every time

GitHub hash of the SDK that was being used

master branch - 4 Jan, 2024

Platform

darwin

Platform Version(s)

No response

Anything else?

No response

bzbarsky-apple commented 10 months ago

The key part is this:

2024-01-18 12:24:04.673503+0530 CHIPTool[525:15043] [Controller] Received NetworkConfig response, networkingStatus=1

So the device responded to the AddOrUpdateThreadNetwork command with an OutOfRange status.

I don't know which "Thread board" you are using, so not sure which code to look at for the server side, but most likely you want to look at the logs from the server to see what command it got and why it replied OutOfRange.

Mitun90 commented 9 months ago

hello @bzbarsky-apple,

Thank you for reviewing my query.

For hardware detail, we setup below board.

Screenshot 2024-01-22 at 2 05 00 PM

Hardware Requirements:

  1. Raspberry pi
  2. Radio Co-Processor (RCP):
    • EFR32MG24/12/21
  3. Matter End Device or Matter Accessory Device (MAD):
    • EFR32MG24/12 NOTE: MG12 device doesn’t require Bootloader

Software Information: RCP: A Radio Co-Processor (RCP), which the OTBR uses to communicate with the Thread network. This is attached to the Raspberry Pi.

Matter End Device: Flash the ERF32 board with prebuild example application (eg. Lighting app)

bzbarsky-apple commented 9 months ago

OK, so if you got OutOfRange on that hardware, that would probably be this line:

    VerifyOrReturnError(newDataset.Init(operationalDataset) == CHIP_NO_ERROR && newDataset.IsCommissioned(), Status::kOutOfRange);

in GenericThreadDriver::AddOrUpdateNetwork. So possibly something off with the dataset value you are passing in? You could add some logging to OperationalDataset::Init and see what the server-side logs look like to see what exactly is failing here....