• State Verified Answer
  • Replies 3 replies
  • Subscribers 90 subscribers
  • Views 1603 views
  • Users 0 members are here
Attachments (0)
Nordic Case Info
  • Case ID: 308867
Options

Matter Commissionning Attestation verification step error

Candela

Hi,

We want to test the Nordic’s Light Bulb example using a nrf5280dk as a Matter over Thread device, so, as a starting point, we are setting up a Matter network to run it. We are getting the Attestation Information error 601 on the commissioning step 8.

To reproduce the error, we count on the following environment:

  • PCA10056 with light bulb
  • PCA10059 with radio co-proccesor
  • Linux virtual machine (using VirtualBox Oracle) in a Windows 11 PC, to run Docker and CHIP. 

Test steps:

  1. Run light bulb in PCA10056 and radio co-processor In PCA10059
  2. Running OTBR using Docker, following: https://developer.nordicsemi.com/nRF_Connect_SDK/doc/latest/nrf/protocols/thread/tools.html#id10, cloning the repository sdk-connectedhomeip (nrfconnect/sdk-connectedhomeip (github.com)) and using the v2.1.1 tag, instead of cloning the provided repository on the guide.
  3. Build Matter,  https://developer.nordicsemi.com/nRF_Connect_SDK/doc/latest/matter/BUILDING.html 
  4. Use CHIP Tool for Matter device testing, following the steps in https://developer.nordicsemi.com/nRF_Connect_SDK/doc/latest/matter/chip_tool_guide.html

We get the error when introducing the BLE pairing command:

user@UBUNTU:~/sdk-connectedhomeip/out/host$ ./chip-tool pairing ble-thread 1000 <HEX_GENERATED> 20202021 3840

As it is shown in the log, the commissioning fails on step 8.

[1685602490.834181][6351:6351] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs

[1685602490.836556][6351:6351] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini

[1685602490.836733][6351:6351] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini

[1685602490.836753][6351:6351] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini

[1685602490.836831][6351:6351] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-2kHWk4)

[1685602490.837661][6351:6351] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)

[1685602490.837683][6351:6351] CHIP:DL: NVS set: chip-counters/reboot-count = 2 (0x2)

[1685602490.838132][6351:6351] CHIP:DL: Got Ethernet interface: enp0s8

[1685602490.838556][6351:6351] CHIP:DL: Found the primary Ethernet interface:enp0s8

[1685602490.839255][6351:6351] CHIP:DL: Failed to get WiFi interface

[1685602490.839323][6351:6351] CHIP:DL: Failed to reset WiFi statistic counts

[1685602490.839343][6351:6351] CHIP:IN: UDP::Init bind&listen port=0

[1685602490.839366][6351:6351] CHIP:IN: UDP::Init bound to port=44883

[1685602490.839375][6351:6351] CHIP:IN: UDP::Init bind&listen port=0

[1685602490.839392][6351:6351] CHIP:IN: UDP::Init bound to port=49891

[1685602490.839399][6351:6351] CHIP:IN: BLEBase::Init - setting/overriding transport

[1685602490.839447][6351:6351] CHIP:IN: TransportMgr initialized

[1685602490.839459][6351:6351] CHIP:FP: Initializing FabricTable from persistent storage

[1685602490.839479][6351:6351] CHIP:TS: Last Known Good Time: 2023-05-31T15:55:46

[1685602490.839864][6351:6351] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0x5E2FA24391444C73, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1

[1685602490.851201][6351:6351] CHIP:ZCL: Using ZAP configuration...

[1685602490.851663][6351:6351] CHIP:DL: MDNS failed to join multicast group on enp0s8 for address type IPv4: ../../src/inet/UDPEndPointImplSockets.cpp:764: Inet Error 0x00000110: Address not found

[1685602490.854010][6351:6351] CHIP:DL: MDNS failed to join multicast group on vethaa44ce4 for address type IPv4: ../../src/inet/UDPEndPointImplSockets.cpp:764: Inet Error 0x00000110: Address not found

[1685602490.854115][6351:6351] CHIP:CTL: System State Initialized...

[1685602490.854137][6351:6351] CHIP:CTL: Stopping commissioning discovery over DNS-SD

[1685602490.854144][6351:6351] CHIP:CTL: Setting attestation nonce to random value

[1685602490.854208][6351:6351] CHIP:CTL: Setting CSR nonce to random value

[1685602490.856732][6351:6356] CHIP:DL: CHIP task running

[1685602490.860207][6351:6356] CHIP:CTL: Stopping commissioning discovery over DNS-SD

[1685602490.860240][6351:6356] CHIP:CTL: Setting attestation nonce to random value

[1685602490.860294][6351:6356] CHIP:CTL: Setting CSR nonce to random value

[1685602490.860576][6351:6356] CHIP:CTL: Generating NOC

[1685602490.860746][6351:6356] CHIP:FP: Validating NOC chain

[1685602490.862238][6351:6356] CHIP:FP: NOC chain validation successful

[1685602490.862318][6351:6356] CHIP:FP: Updated fabric at index: 0x1, Node ID: 0x000000000001B669

[1685602490.862333][6351:6356] CHIP:TS: Last Known Good Time: 2023-05-31T15:55:46

[1685602490.862344][6351:6356] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00

[1685602490.862355][6351:6356] CHIP:TS: Retaining current Last Known Good Time

[1685602490.882705][6351:6356] CHIP:FP: Metadata for Fabric 0x1 persisted to storage.

[1685602490.885155][6351:6356] CHIP:TS: Committing Last Known Good Time to storage: 2023-05-31T15:55:46

[1685602490.886379][6351:6356] CHIP:CTL: Joined the fabric at index 1. Compressed fabric ID is: 0x0000000000000000

[1685602490.906794][6351:6356] CHIP:IN: SecureSession[0x7fc2bc00ac90]: Allocated Type:1 LSID:47565

[1685602490.906828][6351:6356] CHIP:SC: Assigned local session key ID 47565

[1685602490.906846][6351:6356] CHIP:SC: Including MRP parameters in PBKDF param request

[1685602490.906867][6351:6356] CHIP:EM: <<< [E:20529i M:186418585] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:20 (SecureChannel:PBKDFParamRequest)

[1685602490.906883][6351:6356] CHIP:IN: (U) Sending msg 186418585 to IP address 'BLE'

[1685602490.906894][6351:6356] CHIP:IN: Message appended to BLE send queue

[1685602490.906904][6351:6356] CHIP:SC: Sent PBKDF param request

[1685602490.906916][6351:6356] CHIP:CTL: Setting thread operational dataset from parameters

[1685602490.906925][6351:6356] CHIP:CTL: Setting attempt thread scan from parameters

[1685602490.906934][6351:6356] CHIP:CTL: Setting attestation nonce to random value

[1685602490.906945][6351:6356] CHIP:CTL: Setting CSR nonce to random value

[1685602490.906958][6351:6356] CHIP:CTL: Commission called for node ID 0x00000000000003E8

[1685602490.907186][6351:6357] CHIP:DL: TRACE: Bluez mainloop starting Thread

[1685602490.907608][6351:6354] CHIP:DL: TRACE: Bus acquired for name C-18cf

[1685602490.936654][6351:6356] CHIP:DL: PlatformBlueZInit init success

[1685602490.938385][6351:6354] CHIP:BLE: BLE removing known devices.

[1685602490.939250][6351:6354] CHIP:BLE: BLE initiating scan.

[1685602492.729541][6351:6356] CHIP:DL: Long dispatch time: 1823 ms, for event type 2

[1685602492.830032][6351:6354] CHIP:BLE: Device 10:38:1F:F7:66:4E does not look like a CHIP device.

[1685602492.839055][6351:6354] CHIP:BLE: New device scanned: CC:92:E4:E3:93:7B

[1685602492.839164][6351:6354] CHIP:BLE: Device discriminator match. Attempting to connect.

[1685602492.931327][6351:6354] CHIP:BLE: Scan complete notification without an active scan.

[1685602493.270186][6351:6354] CHIP:DL: ConnectDevice complete

[1685602494.377483][6351:6354] CHIP:DL: Char1 /org/bluez/hci0/dev_CC_92_E4_E3_93_7B/service0010

[1685602494.377574][6351:6354] CHIP:DL: Char1 /org/bluez/hci0/dev_CC_92_E4_E3_93_7B/service0010

[1685602494.377587][6351:6354] CHIP:DL: Char1 /org/bluez/hci0/dev_CC_92_E4_E3_93_7B/service0010

[1685602494.377592][6351:6354] CHIP:DL: Char1 /org/bluez/hci0/dev_CC_92_E4_E3_93_7B/service0010

[1685602494.377600][6351:6354] CHIP:DL: Char1 /org/bluez/hci0/dev_CC_92_E4_E3_93_7B/service0001

[1685602494.377606][6351:6354] CHIP:DL: Char1 /org/bluez/hci0/dev_CC_92_E4_E3_93_7B/service0010

[1685602494.377612][6351:6354] CHIP:DL: Char1 /org/bluez/hci0/dev_CC_92_E4_E3_93_7B/service0001

[1685602494.377617][6351:6354] CHIP:DL: Char1 /org/bluez/hci0/dev_CC_92_E4_E3_93_7B/service0010

[1685602494.377776][6351:6354] CHIP:DL: Char1 /org/bluez/hci0/dev_CC_92_E4_E3_93_7B/service0001

[1685602494.377786][6351:6354] CHIP:DL: Char1 /org/bluez/hci0/dev_CC_92_E4_E3_93_7B/service0010

[1685602494.377794][6351:6354] CHIP:DL: Char1 /org/bluez/hci0/dev_CC_92_E4_E3_93_7B/service0010

[1685602494.377800][6351:6354] CHIP:DL: Char1 /org/bluez/hci0/dev_CC_92_E4_E3_93_7B/service0010

[1685602494.377808][6351:6354] CHIP:DL: New BLE connection 0x7fc2c8035180, device CC:92:E4:E3:93:7B, path /org/bluez/hci0/dev_CC_92_E4_E3_93_7B

[1685602494.377858][6351:6356] CHIP:DL: HandlePlatformSpecificBLEEvent 16385

[1685602494.377867][6351:6356] CHIP:IN: BleConnectionComplete: endPoint 0x5636859303e0

[1685602494.798960][6351:6356] CHIP:DL: HandlePlatformSpecificBLEEvent 16387

[1685602494.888175][6351:6356] CHIP:DL: HandlePlatformSpecificBLEEvent 16388

[1685602494.888205][6351:6356] CHIP:BLE: subscribe complete, ep = 0x5636859303e0

[1685602494.895853][6351:6354] CHIP:DL: Indication received, conn = 0x7fc2c8035180

[1685602494.897074][6351:6356] CHIP:DL: HandlePlatformSpecificBLEEvent 16389

[1685602494.897306][6351:6356] CHIP:BLE: peripheral chose BTP version 4; central expected between 4 and 4

[1685602494.897312][6351:6356] CHIP:BLE: using BTP fragment sizes rx 244 / tx 244.

[1685602494.897314][6351:6356] CHIP:BLE: local and remote recv window size = 5

[1685602494.897338][6351:6356] CHIP:IN: BLE EndPoint 0x5636859303e0 Connection Complete

[1685602494.983774][6351:6354] CHIP:DL: Indication received, conn = 0x7fc2c8035180

[1685602494.984441][6351:6356] CHIP:DL: HandlePlatformSpecificBLEEvent 16387

[1685602494.984461][6351:6356] CHIP:DL: HandlePlatformSpecificBLEEvent 16389

[1685602494.984482][6351:6356] CHIP:EM: >>> [E:20529i M:185581985] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:21 (SecureChannel:PBKDFParamResponse)

[1685602494.984488][6351:6356] CHIP:EM: Found matching exchange: 20529i, Delegate: 0x7fc2bc00cc10

[1685602494.984493][6351:6356] CHIP:SC: Received PBKDF param response

[1685602494.984502][6351:6356] CHIP:SC: Peer assigned session ID 37442

[1685602494.984504][6351:6356] CHIP:SC: Found MRP parameters in the message

[1685602494.987578][6351:6356] CHIP:EM: <<< [E:20529i M:186418586] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:22 (SecureChannel:PASE_Pake1)

[1685602494.987647][6351:6356] CHIP:IN: (U) Sending msg 186418586 to IP address 'BLE'

[1685602494.988085][6351:6356] CHIP:SC: Sent spake2p msg1

[1685602495.060040][6351:6356] CHIP:DL: HandlePlatformSpecificBLEEvent 16387

[1685602496.999245][6351:6354] CHIP:DL: Indication received, conn = 0x7fc2c8035180

[1685602496.999463][6351:6356] CHIP:DL: HandlePlatformSpecificBLEEvent 16389

[1685602496.999493][6351:6356] CHIP:EM: >>> [E:20529i M:185581986] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:23 (SecureChannel:PASE_Pake2)

[1685602496.999501][6351:6356] CHIP:EM: Found matching exchange: 20529i, Delegate: 0x7fc2bc00cc10

[1685602496.999507][6351:6356] CHIP:SC: Received spake2p msg2

[1685602497.000338][6351:6356] CHIP:EM: <<< [E:20529i M:186418587] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:24 (SecureChannel:PASE_Pake3)

[1685602497.000610][6351:6356] CHIP:IN: (U) Sending msg 186418587 to IP address 'BLE'

[1685602497.000657][6351:6356] CHIP:SC: Sent spake2p msg3

[1685602497.084232][6351:6356] CHIP:DL: HandlePlatformSpecificBLEEvent 16387

[1685602497.086303][6351:6354] CHIP:DL: Indication received, conn = 0x7fc2c8035180

[1685602497.086354][6351:6356] CHIP:DL: HandlePlatformSpecificBLEEvent 16389

[1685602497.086373][6351:6356] CHIP:EM: >>> [E:20529i M:185581987] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)

[1685602497.086377][6351:6356] CHIP:EM: Found matching exchange: 20529i, Delegate: 0x7fc2bc00cc10

[1685602497.086446][6351:6356] CHIP:SC: SecureSession[0x7fc2bc00ac90]: Moving from state 'kEstablishing' --> 'kActive'

[1685602497.086449][6351:6356] CHIP:IN: SecureSession[0x7fc2bc00ac90]: Activated - Type:1 LSID:47565

[1685602497.086451][6351:6356] CHIP:IN: New secure session activated for device <FFFFFFFB00000000, 0>, LSID:47565 PSID:37442!

[1685602497.086522][6351:6356] CHIP:CTL: Remote device completed SPAKE2+ handshake

[1685602497.086528][6351:6356] CHIP:TOO: Pairing Success

[1685602497.086530][6351:6356] CHIP:TOO: PASE establishment successful

[1685602497.086534][6351:6356] CHIP:CTL: Commissioning stage next step: 'SecurePairing' -> 'ReadCommissioningInfo'

[1685602497.086537][6351:6356] CHIP:CTL: Performing next commissioning step 'ReadCommissioningInfo'

[1685602497.086539][6351:6356] CHIP:CTL: Sending request for commissioning information

[1685602497.086542][6351:6356] CHIP:DMG: SendReadRequest ReadClient[0x7fc2bc017c50]: Sending Read Request

[1685602497.086572][6351:6356] CHIP:EM: <<< [E:20530i M:174188700] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)

[1685602497.086577][6351:6356] CHIP:IN: (S) Sending msg 174188700 on secure session with LSID: 47565

[1685602497.086593][6351:6356] CHIP:DMG: MoveToState ReadClient[0x7fc2bc017c50]: Moving to [AwaitingIn]

[1685602497.189361][6351:6356] CHIP:DL: HandlePlatformSpecificBLEEvent 16387

[1685602497.223027][6351:6354] CHIP:DL: Indication received, conn = 0x7fc2c8035180

[1685602497.223161][6351:6356] CHIP:DL: HandlePlatformSpecificBLEEvent 16389

[1685602497.310083][6351:6354] CHIP:DL: Indication received, conn = 0x7fc2c8035180

[1685602497.310250][6351:6356] CHIP:DL: HandlePlatformSpecificBLEEvent 16389

[1685602497.310351][6351:6356] CHIP:EM: >>> [E:20530i M:219572784] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)

[1685602497.310359][6351:6356] CHIP:EM: Found matching exchange: 20530i, Delegate: 0x7fc2bc017c60

[1685602497.310496][6351:6356] CHIP:CTL: ----- NetworkCommissioning Features: has Thread. endpointid = 0

[1685602497.310553][6351:6356] CHIP:CTL: Successfully finished commissioning step 'ReadCommissioningInfo'

[1685602497.310558][6351:6356] CHIP:CTL: Commissioning stage next step: 'ReadCommissioningInfo' -> 'ArmFailSafe'

[1685602497.310562][6351:6356] CHIP:CTL: Performing next commissioning step 'ArmFailSafe'

[1685602497.310564][6351:6356] CHIP:CTL: Arming failsafe (60 seconds)

[1685602497.310572][6351:6356] CHIP:DMG: ICR moving to [AddingComm]

[1685602497.310574][6351:6356] CHIP:DMG: ICR moving to [AddedComma]

[1685602497.310591][6351:6356] CHIP:EM: <<< [E:20531i M:174188701] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)

[1685602497.310605][6351:6356] CHIP:IN: (S) Sending msg 174188701 on secure session with LSID: 47565

[1685602497.310623][6351:6356] CHIP:DMG: ICR moving to [CommandSen]

[1685602497.399080][6351:6356] CHIP:DL: HandlePlatformSpecificBLEEvent 16387

[1685602497.400581][6351:6354] CHIP:DL: Indication received, conn = 0x7fc2c8035180

[1685602497.400695][6351:6356] CHIP:DL: HandlePlatformSpecificBLEEvent 16389

[1685602497.400740][6351:6356] CHIP:EM: >>> [E:20531i M:219572785] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)

[1685602497.400745][6351:6356] CHIP:EM: Found matching exchange: 20531i, Delegate: 0x7fc2c80096a8

[1685602497.400750][6351:6356] CHIP:DMG: ICR moving to [ResponseRe]

[1685602497.400762][6351:6356] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0001

[1685602497.400777][6351:6356] CHIP:CTL: Received ArmFailSafe response errorCode=0

[1685602497.400781][6351:6356] CHIP:CTL: Successfully finished commissioning step 'ArmFailSafe'

[1685602497.400784][6351:6356] CHIP:CTL: No NetworkScan enabled or WiFi/Thread endpoint not specified, skipping ScanNetworks

[1685602497.400786][6351:6356] CHIP:CTL: Commissioning stage next step: 'ArmFailSafe' -> 'ConfigRegulatory'

[1685602497.400789][6351:6356] CHIP:CTL: Performing next commissioning step 'ConfigRegulatory'

[1685602497.400791][6351:6356] CHIP:CTL: Setting Regulatory Config

[1685602497.401036][6351:6356] CHIP:CTL: Device does not support configurable regulatory location

[1685602497.401049][6351:6356] CHIP:DMG: ICR moving to [AddingComm]

[1685602497.401053][6351:6356] CHIP:DMG: ICR moving to [AddedComma]

[1685602497.401072][6351:6356] CHIP:EM: <<< [E:20532i M:174188702] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)

[1685602497.401077][6351:6356] CHIP:IN: (S) Sending msg 174188702 on secure session with LSID: 47565

[1685602497.401092][6351:6356] CHIP:DMG: ICR moving to [CommandSen]

[1685602497.401098][6351:6356] CHIP:DMG: ICR moving to [AwaitingDe]

[1685602497.490790][6351:6354] CHIP:DL: Indication received, conn = 0x7fc2c8035180

[1685602497.490912][6351:6356] CHIP:DL: HandlePlatformSpecificBLEEvent 16387

[1685602497.490974][6351:6356] CHIP:DL: HandlePlatformSpecificBLEEvent 16389

[1685602497.491018][6351:6356] CHIP:EM: >>> [E:20532i M:219572786] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)

[1685602497.491023][6351:6356] CHIP:EM: Found matching exchange: 20532i, Delegate: 0x7fc2bc00a408

[1685602497.491075][6351:6356] CHIP:DMG: ICR moving to [ResponseRe]

[1685602497.491089][6351:6356] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0003

[1685602497.491094][6351:6356] CHIP:CTL: Received SetRegulatoryConfig response errorCode=0

[1685602497.491098][6351:6356] CHIP:CTL: Successfully finished commissioning step 'ConfigRegulatory'

[1685602497.491101][6351:6356] CHIP:CTL: Commissioning stage next step: 'ConfigRegulatory' -> 'SendPAICertificateRequest'

[1685602497.491105][6351:6356] CHIP:CTL: Performing next commissioning step 'SendPAICertificateRequest'

[1685602497.491107][6351:6356] CHIP:CTL: Sending request for PAI certificate

[1685602497.491109][6351:6356] CHIP:CTL: Sending Certificate Chain request to 0x7fc2bc00cbc0 device

[1685602497.491115][6351:6356] CHIP:DMG: ICR moving to [AddingComm]

[1685602497.491118][6351:6356] CHIP:DMG: ICR moving to [AddedComma]

[1685602497.491130][6351:6356] CHIP:EM: <<< [E:20533i M:174188703] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)

[1685602497.491134][6351:6356] CHIP:IN: (S) Sending msg 174188703 on secure session with LSID: 47565

[1685602497.491194][6351:6356] CHIP:DMG: ICR moving to [CommandSen]

[1685602497.491203][6351:6356] CHIP:DMG: ICR moving to [AwaitingDe]

[1685602497.580561][6351:6356] CHIP:DL: HandlePlatformSpecificBLEEvent 16387

[1685602497.583406][6351:6354] CHIP:DL: Indication received, conn = 0x7fc2c8035180

[1685602497.583479][6351:6356] CHIP:DL: HandlePlatformSpecificBLEEvent 16389

[1685602497.672287][6351:6354] CHIP:DL: Indication received, conn = 0x7fc2c8035180

[1685602497.672561][6351:6356] CHIP:DL: HandlePlatformSpecificBLEEvent 16389

[1685602497.760420][6351:6354] CHIP:DL: Indication received, conn = 0x7fc2c8035180

[1685602497.760609][6351:6356] CHIP:DL: HandlePlatformSpecificBLEEvent 16389

[1685602497.760651][6351:6356] CHIP:EM: >>> [E:20533i M:219572787] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)

[1685602497.760679][6351:6356] CHIP:EM: Found matching exchange: 20533i, Delegate: 0x7fc2c80096a8

[1685602497.760688][6351:6356] CHIP:DMG: ICR moving to [ResponseRe]

[1685602497.760703][6351:6356] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0003

[1685602497.760710][6351:6356] CHIP:CTL: Received certificate chain from the device

[1685602497.760716][6351:6356] CHIP:CTL: Successfully finished commissioning step 'SendPAICertificateRequest'

[1685602497.760721][6351:6356] CHIP:CTL: Commissioning stage next step: 'SendPAICertificateRequest' -> 'SendDACCertificateRequest'

[1685602497.760725][6351:6356] CHIP:CTL: Performing next commissioning step 'SendDACCertificateRequest'

[1685602497.760728][6351:6356] CHIP:CTL: Sending request for DAC certificate

[1685602497.760729][6351:6356] CHIP:CTL: Sending Certificate Chain request to 0x7fc2bc00cbc0 device

[1685602497.760741][6351:6356] CHIP:DMG: ICR moving to [AddingComm]

[1685602497.760745][6351:6356] CHIP:DMG: ICR moving to [AddedComma]

[1685602497.760791][6351:6356] CHIP:EM: <<< [E:20534i M:174188704] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)

[1685602497.760802][6351:6356] CHIP:IN: (S) Sending msg 174188704 on secure session with LSID: 47565

[1685602497.760825][6351:6356] CHIP:DMG: ICR moving to [CommandSen]

[1685602497.760832][6351:6356] CHIP:DMG: ICR moving to [AwaitingDe]

[1685602497.849762][6351:6356] CHIP:DL: HandlePlatformSpecificBLEEvent 16387

[1685602497.852498][6351:6354] CHIP:DL: Indication received, conn = 0x7fc2c8035180

[1685602497.852548][6351:6356] CHIP:DL: HandlePlatformSpecificBLEEvent 16389

[1685602497.943206][6351:6354] CHIP:DL: Indication received, conn = 0x7fc2c8035180

[1685602497.943324][6351:6356] CHIP:DL: HandlePlatformSpecificBLEEvent 16389

[1685602498.031252][6351:6354] CHIP:DL: Indication received, conn = 0x7fc2c8035180

[1685602498.031386][6351:6356] CHIP:DL: HandlePlatformSpecificBLEEvent 16389

[1685602498.031429][6351:6356] CHIP:EM: >>> [E:20534i M:219572788] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)

[1685602498.031572][6351:6356] CHIP:EM: Found matching exchange: 20534i, Delegate: 0x7fc2c8035bb8

[1685602498.031581][6351:6356] CHIP:DMG: ICR moving to [ResponseRe]

[1685602498.031593][6351:6356] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0003

[1685602498.031767][6351:6356] CHIP:CTL: Received certificate chain from the device

[1685602498.031775][6351:6356] CHIP:CTL: Successfully finished commissioning step 'SendDACCertificateRequest'

[1685602498.031779][6351:6356] CHIP:CTL: Commissioning stage next step: 'SendDACCertificateRequest' -> 'SendAttestationRequest'

[1685602498.031783][6351:6356] CHIP:CTL: Performing next commissioning step 'SendAttestationRequest'

[1685602498.031785][6351:6356] CHIP:CTL: Sending Attestation Request to the device.

[1685602498.031802][6351:6356] CHIP:CTL: Sending Attestation request to 0x7fc2bc00cbc0 device

[1685602498.031811][6351:6356] CHIP:DMG: ICR moving to [AddingComm]

[1685602498.031813][6351:6356] CHIP:DMG: ICR moving to [AddedComma]

[1685602498.031831][6351:6356] CHIP:EM: <<< [E:20535i M:174188705] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)

[1685602498.031883][6351:6356] CHIP:IN: (S) Sending msg 174188705 on secure session with LSID: 47565

[1685602498.031903][6351:6356] CHIP:DMG: ICR moving to [CommandSen]

[1685602498.031906][6351:6356] CHIP:CTL: Sent Attestation request, waiting for the Attestation Information

[1685602498.031911][6351:6356] CHIP:DMG: ICR moving to [AwaitingDe]

[1685602498.124164][6351:6356] CHIP:DL: HandlePlatformSpecificBLEEvent 16387

[1685602498.173719][6351:6354] CHIP:DL: Indication received, conn = 0x7fc2c8035180

[1685602498.173862][6351:6356] CHIP:DL: HandlePlatformSpecificBLEEvent 16389

[1685602498.257903][6351:6354] CHIP:DL: Indication received, conn = 0x7fc2c8035180

[1685602498.257982][6351:6356] CHIP:DL: HandlePlatformSpecificBLEEvent 16389

[1685602498.355829][6351:6354] CHIP:DL: Indication received, conn = 0x7fc2c8035180

[1685602498.355977][6351:6356] CHIP:DL: HandlePlatformSpecificBLEEvent 16389

[1685602498.356023][6351:6356] CHIP:EM: >>> [E:20535i M:219572789] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)

[1685602498.356029][6351:6356] CHIP:EM: Found matching exchange: 20535i, Delegate: 0x7fc2c8035e78

[1685602498.356035][6351:6356] CHIP:DMG: ICR moving to [ResponseRe]

[1685602498.356051][6351:6356] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0001

[1685602498.356057][6351:6356] CHIP:CTL: Received Attestation Information from the device

[1685602498.356062][6351:6356] CHIP:CTL: Successfully finished commissioning step 'SendAttestationRequest'

[1685602498.356065][6351:6356] CHIP:CTL: AutoCommissioner setting attestationElements buffer size 583/583

[1685602498.356108][6351:6356] CHIP:CTL: Commissioning stage next step: 'SendAttestationRequest' -> 'AttestationVerification'

[1685602498.356114][6351:6356] CHIP:CTL: Performing next commissioning step 'AttestationVerification'

[1685602498.356117][6351:6356] CHIP:CTL: Verifying attestation

[1685602498.363250][6351:6356] CHIP:CTL: Failed in verifying 'Attestation Information' command received from the device: err 601. Look at AttestationVerificationResult enum to understand the errors

[1685602498.363324][6351:6356] CHIP:CTL: Error on commissioning step 'AttestationVerification': '../../src/controller/CHIPDeviceController.cpp:1031: CHIP Error 0x000000AC: Internal error'

[1685602498.363329][6351:6356] CHIP:CTL: Failed to perform commissioning step 8

[1685602498.363331][6351:6356] CHIP:CTL: Going from commissioning step 'AttestationVerification' with lastErr = '../../src/controller/CHIPDeviceController.cpp:1031: CHIP Error 0x000000AC: Internal error' -> 'Cleanup'

[1685602498.363335][6351:6356] CHIP:CTL: Performing next commissioning step 'Cleanup' with completion status = '../../src/controller/CHIPDeviceController.cpp:1031: CHIP Error 0x000000AC: Internal error'

[1685602498.363338][6351:6356] CHIP:CTL: Expiring failsafe on proxy 0x7fc2bc00cbc0

[1685602498.363347][6351:6356] CHIP:DMG: ICR moving to [AddingComm]

[1685602498.363350][6351:6356] CHIP:DMG: ICR moving to [AddedComma]

[1685602498.363366][6351:6356] CHIP:EM: <<< [E:20536i M:174188706] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)

[1685602498.363371][6351:6356] CHIP:IN: (S) Sending msg 174188706 on secure session with LSID: 47565

[1685602498.363501][6351:6356] CHIP:DMG: ICR moving to [CommandSen]

[1685602498.363511][6351:6356] CHIP:DMG: ICR moving to [AwaitingDe]

[1685602498.448106][6351:6354] CHIP:DL: Indication received, conn = 0x7fc2c8035180

[1685602498.448266][6351:6356] CHIP:DL: HandlePlatformSpecificBLEEvent 16387

[1685602498.448396][6351:6356] CHIP:DL: HandlePlatformSpecificBLEEvent 16389

[1685602498.448518][6351:6356] CHIP:EM: >>> [E:20536i M:219572790] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)

[1685602498.448593][6351:6356] CHIP:EM: Found matching exchange: 20536i, Delegate: 0x7fc2c8035fd8

[1685602498.448603][6351:6356] CHIP:DMG: ICR moving to [ResponseRe]

[1685602498.448618][6351:6356] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0001

[1685602498.448624][6351:6356] CHIP:CTL: Failsafe disarmed

[1685602498.448630][6351:6356] CHIP:CTL: Successfully finished commissioning step 'Cleanup'

[1685602498.448640][6351:6356] CHIP:TOO: Device commissioning Failure: ../../src/controller/CHIPDeviceController.cpp:1031: CHIP Error 0x000000AC: Internal error

[1685602498.448713][6351:6356] CHIP:DIS: Closing all BLE connections

[1685602498.448719][6351:6356] CHIP:IN: Clearing BLE pending packets.

[1685602498.448733][6351:6356] CHIP:BLE: Auto-closing end point's BLE connection.

[1685602498.448736][6351:6356] CHIP:DL: Closing BLE GATT connection (con 0x7fc2c8035180)

[1685602498.448743][6351:6356] CHIP:IN: SecureSession[0x7fc2bc00ac90]: MarkForEviction Type:1 LSID:47565

[1685602498.448746][6351:6356] CHIP:SC: SecureSession[0x7fc2bc00ac90]: Moving from state 'kActive' --> 'kPendingEviction'

[1685602498.448768][6351:6356] CHIP:DMG: ICR moving to [AwaitingDe]

[1685602498.449069][6351:6356] CHIP:IN: SecureSession[0x7fc2bc00ac90]: Released - Type:1 LSID:47565

[1685602498.449058][6351:6354] CHIP:DL: BluezDisconnect peer=CC:92:E4:E3:93:7B

[1685602498.449262][6351:6351] CHIP:CTL: Shutting down the commissioner

[1685602498.449266][6351:6351] CHIP:CTL: Stopping commissioning discovery over DNS-SD

[1685602498.449268][6351:6351] CHIP:CTL: Shutting down the controller

[1685602498.449271][6351:6351] CHIP:IN: Expiring all sessions for fabric 0x1!!

[1685602498.449273][6351:6351] CHIP:FP: Forgetting fabric 0x1

[1685602498.449277][6351:6351] CHIP:TS: Pending Last Known Good Time: 2023-05-31T15:55:46

[1685602498.449294][6351:6351] CHIP:TS: Previous Last Known Good Time: 2023-05-31T15:55:46

[1685602498.449296][6351:6351] CHIP:TS: Reverted Last Known Good Time to previous value

[1685602498.449304][6351:6351] CHIP:CTL: Shutting down the commissioner

[1685602498.449305][6351:6351] CHIP:CTL: Stopping commissioning discovery over DNS-SD

[1685602498.449307][6351:6351] CHIP:CTL: Shutting down the controller

[1685602498.449309][6351:6351] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack

[1685602498.450947][6351:6351] CHIP:DMG: IM WH moving to [Uninitialized]

[1685602498.450996][6351:6351] CHIP:DMG: IM WH moving to [Uninitialized]

[1685602498.451000][6351:6351] CHIP:DMG: IM WH moving to [Uninitialized]

[1685602498.451001][6351:6351] CHIP:DMG: IM WH moving to [Uninitialized]

[1685602498.451003][6351:6351] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet

[1685602498.451015][6351:6351] CHIP:BLE: BleConnectionDelegate::CancelConnection is not implemented.

[1685602498.451104][6351:6351] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-52O5hU)

[1685602498.451347][6351:6351] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)

[1685602498.451360][6351:6351] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0)

[1685602498.451364][6351:6351] CHIP:DL: Inet Layer shutdown

[1685602498.451366][6351:6351] CHIP:DL: BLE shutdown

[1685602498.451751][6351:6351] CHIP:DL: System Layer shutdown

[1685602498.451772][6351:6351] CHIP:TOO: Run command failure: ../../src/controller/CHIPDeviceController.cpp:1031: CHIP Error 0x000000AC: Internal error

We've tried to test different repository versions, like it is described on a similar ticket, but we are still getting the same problem. Any idea of how could we solve it?

Thank you,

Candela

Related
Terms of service