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.42k stars 1.99k forks source link

Commissioning with python chip-device-ctrl fails due to network information not provided #16124

Closed caubut-charter closed 2 years ago

caubut-charter commented 2 years ago

Seeing the same issue as with the IOS chiptool that was fixed yesterday but on the python controller: https://github.com/project-chip/connectedhomeip/issues/16053

Relevant Log Section

2022-03-11 16:22:56 raspberrypi chip.CTL[100091] INFO Operational credentials provisioned on device 0x7f840278e0
2022-03-11 16:22:56 raspberrypi chip.CTL[100091] ERROR Required network information not provided in commissioning parameters
2022-03-11 16:22:56 raspberrypi chip.CTL[100091] ERROR Parameters supplied: wifi (no) thread (no)
2022-03-11 16:22:56 raspberrypi chip.CTL[100091] ERROR Device supports: wifi (no) thread(yes)
2022-03-11 16:22:56 raspberrypi chip.CTL[100091] INFO Rendezvous cleanup
Failed to commission: 47
Full Logs ``` [1647015758.943802][100091:100091] CHIP:CTL: Setting attestation nonce to random value [1647015758.944058][100091:100091] CHIP:CTL: Setting CSR nonce to random value [1647015758.949122][100091:100091] CHIP:DL: writing settings to file (/tmp/chip_kvs-JQ2UeC) [1647015758.951069][100091:100091] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1647015758.951413][100091:100091] CHIP:DL: writing settings to file (/tmp/chip_factory.ini-WmEh4z) [1647015758.951531][100091:100091] CHIP:DL: renamed tmp file to file (/tmp/chip_factory.ini) [1647015758.951674][100091:100091] CHIP:DL: writing settings to file (/tmp/chip_config.ini-zjylJD) [1647015758.951771][100091:100091] CHIP:DL: renamed tmp file to file (/tmp/chip_config.ini) [1647015758.951915][100091:100091] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-H4Ca5z) [1647015758.952034][100091:100091] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1647015758.952384][100091:100091] CHIP:DL: writing settings to file (/tmp/chip_factory.ini-6gezfD) [1647015758.952868][100091:100091] CHIP:DL: renamed tmp file to file (/tmp/chip_factory.ini) [1647015758.952942][100091:100091] CHIP:DL: NVS set: chip-factory/unique-id = "B41DDA0033533E9D" [1647015758.953201][100091:100091] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-hNY7QD) [1647015758.953618][100091:100091] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1647015758.953736][100091:100091] CHIP:DL: NVS set: chip-counters/reboot-count = 1 (0x1) [1647015758.953961][100091:100091] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-yi9TkC) [1647015758.954433][100091:100091] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1647015758.954500][100091:100091] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0) [1647015758.954710][100091:100091] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-p0trSA) [1647015758.955108][100091:100091] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1647015758.955174][100091:100091] CHIP:DL: NVS set: chip-counters/boot-reason = 0 (0x0) [1647015758.955342][100091:100091] CHIP:DL: writing settings to file (/tmp/chip_config.ini-Vbpq0A) [1647015758.955759][100091:100091] CHIP:DL: renamed tmp file to file (/tmp/chip_config.ini) [1647015758.955867][100091:100091] CHIP:DL: NVS set: chip-config/regulatory-location = 0 (0x0) [1647015758.956062][100091:100091] CHIP:DL: writing settings to file (/tmp/chip_config.ini-xRCEuA) [1647015758.956512][100091:100091] CHIP:DL: renamed tmp file to file (/tmp/chip_config.ini) [1647015758.956579][100091:100091] CHIP:DL: NVS set: chip-config/location-capability = 0 (0x0) [1647015758.957135][100091:100091] CHIP:DL: Got Ethernet interface: eth0 [1647015758.957454][100091:100091] CHIP:DL: Found the primary Ethernet interface:eth0 [1647015758.957843][100091:100091] CHIP:DL: Got WiFi interface: wlan0 [1647015758.957923][100091:100091] CHIP:DL: Failed to reset WiFi statistic counts [1647015758.958190][100091:100096] CHIP:DL: Platform main loop started. 2022-03-11 16:22:39 raspberrypi root[100091] ERROR [Errno 2] No such file or directory: '/tmp/chip-device-ctrl-storage.json' 2022-03-11 16:22:39 raspberrypi root[100091] WARNING Could not load configuration from /tmp/chip-device-ctrl-storage.json - resetting configuration... 2022-03-11 16:22:39 raspberrypi chip.IN[100091] INFO Loading from storage for fabric index 1 2022-03-11 16:22:39 raspberrypi chip.IN[100091] INFO Loading from storage for fabric index 2 2022-03-11 16:22:39 raspberrypi chip.IN[100091] INFO Loading from storage for fabric index 3 2022-03-11 16:22:39 raspberrypi chip.IN[100091] INFO Loading from storage for fabric index 4 2022-03-11 16:22:39 raspberrypi chip.IN[100091] INFO Loading from storage for fabric index 5 2022-03-11 16:22:39 raspberrypi chip.IN[100091] INFO Loading from storage for fabric index 6 2022-03-11 16:22:39 raspberrypi chip.IN[100091] INFO Loading from storage for fabric index 7 2022-03-11 16:22:39 raspberrypi chip.IN[100091] INFO Loading from storage for fabric index 8 2022-03-11 16:22:39 raspberrypi chip.IN[100091] INFO Loading from storage for fabric index 9 2022-03-11 16:22:39 raspberrypi chip.IN[100091] INFO Loading from storage for fabric index 10 2022-03-11 16:22:39 raspberrypi chip.IN[100091] INFO Loading from storage for fabric index 11 2022-03-11 16:22:39 raspberrypi chip.IN[100091] INFO Loading from storage for fabric index 12 2022-03-11 16:22:39 raspberrypi chip.IN[100091] INFO Loading from storage for fabric index 13 2022-03-11 16:22:39 raspberrypi chip.IN[100091] INFO Loading from storage for fabric index 14 2022-03-11 16:22:39 raspberrypi chip.IN[100091] INFO Loading from storage for fabric index 15 2022-03-11 16:22:39 raspberrypi chip.IN[100091] INFO Loading from storage for fabric index 16 2022-03-11 16:22:39 raspberrypi chip.DL[100091] INFO writing settings to file (/tmp/chip_counters.ini-K6JYpA) 2022-03-11 16:22:39 raspberrypi chip.DL[100091] ERROR renamed tmp file to file (/tmp/chip_counters.ini) 2022-03-11 16:22:39 raspberrypi chip.DL[100091] INFO NVS set: chip-counters/GlobalMCTR = 1000 (0x3E8) 2022-03-11 16:22:39 raspberrypi root[100091] INFO SetSdkKey: gcc = b'\xe8\x03\x00\x00' 2022-03-11 16:22:39 raspberrypi root[100091] INFO SetSdkKey: gdc = b'\xe8\x03\x00\x00' 2022-03-11 16:22:39 raspberrypi chip.ZCL[100091] INFO Using ZAP configuration... 2022-03-11 16:22:39 raspberrypi chip.DL[100091] INFO Avahi client registered 2022-03-11 16:22:39 raspberrypi chip.IN[100091] INFO CASE Server enabling CASE session setups 2022-03-11 16:22:39 raspberrypi chip.DIS[100091] INFO Failed to find a valid admin pairing. Node ID unknown 2022-03-11 16:22:39 raspberrypi chip.DIS[100091] INFO Start dns-sd server - no current nodeId 2022-03-11 16:22:39 raspberrypi chip.DIS[100091] INFO Advertise commission parameter vendorID=65521 productID=32769 discriminator=3840/15 2022-03-11 16:22:39 raspberrypi chip.DL[100091] INFO PublishService 85455FD9C3339E75._matterc._udp34016.-1 2022-03-11 16:22:39 raspberrypi chip.DIS[100091] INFO mDNS service published: _matterc._udp 2022-03-11 16:22:39 raspberrypi chip.DIS[100091] INFO Advertise commission parameter vendorID=65521 productID=32769 discriminator=3840/15 2022-03-11 16:22:39 raspberrypi chip.DL[100091] INFO PublishService 85455FD9C3339E75._matterd._udp5550.-1 2022-03-11 16:22:39 raspberrypi chip.DIS[100091] INFO mDNS service published error: ../../src/platform/Linux/DnssdImpl.cpp:482: CHIP Error 0x000000AC: Internal error 2022-03-11 16:22:39 raspberrypi chip.DIS[100091] ERROR Failed to advertise commissioner: ../../src/platform/Linux/DnssdImpl.cpp:482: CHIP Error 0x000000AC: Internal error New FabricAdmin: FabricId: 1(1) 2022-03-11 16:22:39 raspberrypi chip.CTL[100091] INFO Couldn't get ExampleOpCredsCAKey from storage: ../../src/controller/python/ChipDeviceController-StorageDelegate.cpp:97: CHIP Error 0x000000A0: Value not found in the per sisted storage 2022-03-11 16:22:39 raspberrypi root[100091] INFO SetSdkKey: ExampleOpCredsCAKey1 = b'\x04\x05\xb1wi\xf0\xc9\xcc\x8f+\xa7\xfc\xcd}\xcdU:\x9c\xc79)\x06H\x81.^\xb8y_\xeb\x85\x8a\xc8^\xc7f\xcf\xceV)m=M\x80\xbf\t\x1c#\xe6\xadR\ xba\x06\x86\xecKs\xe3Nb\x9f\xf8%\xcd\xbb{\xab)Y\xd2\xaeY\xd0\x05\xb1\ny8\xc0\xe6\x86\x19\xf1\xf8\x15\x16\x15\x82K\xd7T\xa3\x87\xca\xf5\xd7V' 2022-03-11 16:22:39 raspberrypi chip.CTL[100091] INFO Couldn't get ExampleOpCredsICAKey from storage: ../../src/controller/python/ChipDeviceController-StorageDelegate.cpp:97: CHIP Error 0x000000A0: Value not found in the pe rsisted storage 2022-03-11 16:22:39 raspberrypi root[100091] INFO SetSdkKey: ExampleOpCredsICAKey1 = b'\x04.\xd2bv\x84\xca\x95x5{dv\xbd\xdf\xf2\xfb\x00\x92\n,\x07\x13Ix\xa3\xbf\x04H?\xde\xf5\x90\xff\xf4%\xc8\x99\x8c\x89d\xb4s\x81\x1e\xafO\ xfe\x90\xb2>0N\x83=\xdb\xd3\xd0\xcd\x91\xd1\xe7\x11z\xd9-\xbbl\xa7\x8a\xef\x03\x19\x07G\xc96%q\xa1\x15\x83u\xcb\xf0\xe3Nf\xaa\x11\xb1VT\x11\xf0d\t' 2022-03-11 16:22:39 raspberrypi root[100091] INFO SetReplKey: fabricAdmins = {'1': {'fabricId': 1}} 2022-03-11 16:22:39 raspberrypi root[100091] INFO SetReplKey: fabricAdmins = {'1': {'fabricId': 1}} Allocating new controller with FabricId: 1(1), NodeId: 1 2022-03-11 16:22:39 raspberrypi chip.CTL[100091] INFO Setting attestation nonce to random value 2022-03-11 16:22:39 raspberrypi chip.CTL[100091] INFO Setting CSR nonce to random value 2022-03-11 16:22:39 raspberrypi chip.CTL[100091] INFO Generating NOC 2022-03-11 16:22:39 raspberrypi chip.CTL[100091] INFO Generating ICAC 2022-03-11 16:22:39 raspberrypi root[100091] INFO SetSdkKey: ExampleCAIntermediateCert1 = b'0\x82\x01\x960\x82\x01<\xa0\x03\x02\x01\x02\x02\x01\x000\n\x06\x08*\x86H\xce=\x04\x03\x020"1 0\x1e\x06\n+\x06(0 results) [140/1837] x01\x04\x0c\x1000000000000000000\x1e\x17\r210101000000Z\x17\r301230000000Z0"1 0\x1e\x06\n+\x06\x01\x04\x01\x82\xa2|\x01\x03\x0c\x1000000000000000010Y0\x13\x06\x07*\x86H\xce=\x02\x01\x06\x08*\x86H\xce=\x03\x01\x07\x03B\x00\x 04.\xd2bv\x84\xca\x95x5{dv\xbd\xdf\xf2\xfb\x00\x92\n,\x07\x13Ix\xa3\xbf\x04H?\xde\xf5\x90\xff\xf4%\xc8\x99\x8c\x89d\xb4s\x81\x1e\xafO\xfe\x90\xb2>0N\x83=\xdb\xd3\xd0\xcd\x91\xd1\xe7\x11z\xd9\xa3c0a0\x0f\x06\x03U\x1d\x13\x01 \x01\xff\x04\x050\x03\x01\x01\xff0\x0e\x06\x03U\x1d\x0f\x01\x01\xff\x04\x04\x03\x02\x01\x060\x1d\x06\x03U\x1d\x0e\x04\x16\x04\x14\xf7\xeb\xf7\xa0D\x85\xfe\x90\xf9\x9d\x84@\xa6N\x87WP\xa7\xa9<0\x1f\x06\x03U\x1d#\x04\x180\x16 \x80\x14\xd9\xb4\xb8v\xd3o\xe0W\x85Cx\x7f\xbf\xb8FW\x94\x05*j0\n\x06\x08*\x86H\xce=\x04\x03\x02\x03H\x000E\x02!\x00\xf2\xd1_\x93\x12\xe1\xebV\xf0;\xde\x04&\xa1XLg\xafU;\xa2\x05h\xe6#\x98\xbeH\xdb4\x0b\xd2\x02 \x02y\xbe\xef\ x84}\xb1\xbe\xd1\xa1\xb0\x1e\xf4\xddh \x10]Y\xc0\xab\xa5\xa0\x9aKX\x83vJ}\xd2\x96' 2022-03-11 16:22:39 raspberrypi chip.CTL[100091] INFO Generating RCAC 2022-03-11 16:22:39 raspberrypi root[100091] INFO SetSdkKey: ExampleCARootCert1 = b'0\x82\x01\x970\x82\x01<\xa0\x03\x02\x01\x02\x02\x01\x000\n\x06\x08*\x86H\xce=\x04\x03\x020"1 0\x1e\x06\n+\x06\x01\x04\x01\x82\xa2|\x01\x04\ x0c\x1000000000000000000\x1e\x17\r210101000000Z\x17\r301230000000Z0"1 0\x1e\x06\n+\x06\x01\x04\x01\x82\xa2|\x01\x04\x0c\x1000000000000000000Y0\x13\x06\x07*\x86H\xce=\x02\x01\x06\x08*\x86H\xce=\x03\x01\x07\x03B\x00\x04\x05\x b1wi\xf0\xc9\xcc\x8f+\xa7\xfc\xcd}\xcdU:\x9c\xc79)\x06H\x81.^\xb8y_\xeb\x85\x8a\xc8^\xc7f\xcf\xceV)m=M\x80\xbf\t\x1c#\xe6\xadR\xba\x06\x86\xecKs\xe3Nb\x9f\xf8%\xcd\xbb\xa3c0a0\x0f\x06\x03U\x1d\x13\x01\x01\xff\x04\x050\x03\x 01\x01\xff0\x0e\x06\x03U\x1d\x0f\x01\x01\xff\x04\x04\x03\x02\x01\x060\x1d\x06\x03U\x1d\x0e\x04\x16\x04\x14\xd9\xb4\xb8v\xd3o\xe0W\x85Cx\x7f\xbf\xb8FW\x94\x05*j0\x1f\x06\x03U\x1d#\x04\x180\x16\x80\x14\xd9\xb4\xb8v\xd3o\xe0W\ x85Cx\x7f\xbf\xb8FW\x94\x05*j0\n\x06\x08*\x86H\xce=\x04\x03\x02\x03I\x000F\x02!\x00\xc4p;f\x8ep\xd5\x88\x1b\xaf\xbb\x114\xcf\xe8\xe0\xb8#\x9eC\x9c\xca\xa7\xff|:-gD\x0bSm\x02!\x00\xd5\xd8)\x1a\xa3\x7f_\x81\xeb\xf0\x91\x1e\xb 3\x8fb`fZ\xbe\xd5\x9b=|o\xbd\xf7u\x06[\x8b\x15\x0f' 2022-03-11 16:22:39 raspberrypi chip.IN[100091] INFO Loading from storage for fabric index 1 2022-03-11 16:22:39 raspberrypi chip.IN[100091] INFO Loading from storage for fabric index 2 2022-03-11 16:22:39 raspberrypi chip.IN[100091] INFO Loading from storage for fabric index 3 2022-03-11 16:22:39 raspberrypi chip.IN[100091] INFO Loading from storage for fabric index 4 2022-03-11 16:22:39 raspberrypi chip.IN[100091] INFO Loading from storage for fabric index 5 2022-03-11 16:22:39 raspberrypi chip.IN[100091] INFO Loading from storage for fabric index 6 2022-03-11 16:22:39 raspberrypi chip.IN[100091] INFO Loading from storage for fabric index 7 2022-03-11 16:22:39 raspberrypi chip.IN[100091] INFO Loading from storage for fabric index 8 2022-03-11 16:22:39 raspberrypi chip.IN[100091] INFO Loading from storage for fabric index 9 2022-03-11 16:22:39 raspberrypi chip.IN[100091] INFO Loading from storage for fabric index 10 2022-03-11 16:22:39 raspberrypi chip.IN[100091] INFO Loading from storage for fabric index 11 2022-03-11 16:22:39 raspberrypi chip.IN[100091] INFO Loading from storage for fabric index 12 2022-03-11 16:22:39 raspberrypi chip.IN[100091] INFO Loading from storage for fabric index 13 2022-03-11 16:22:39 raspberrypi chip.IN[100091] INFO Loading from storage for fabric index 14 2022-03-11 16:22:39 raspberrypi chip.IN[100091] INFO Loading from storage for fabric index 15 2022-03-11 16:22:39 raspberrypi chip.IN[100091] INFO Loading from storage for fabric index 16 2022-03-11 16:22:39 raspberrypi chip.IN[100091] INFO Loading from storage for fabric index 1 2022-03-11 16:22:39 raspberrypi chip.DIS[100091] INFO Verifying the received credentials 2022-03-11 16:22:39 raspberrypi chip.DIS[100091] INFO Added new fabric at index: 1, Initialized: 1 2022-03-11 16:22:39 raspberrypi chip.DIS[100091] INFO Assigned compressed fabric ID: 0x5BE37BE27B14065B, node ID: 0x0000000000000001 2022-03-11 16:22:39 raspberrypi chip.DIS[100091] INFO Fabric (1) loaded from storage. Calling OnFabricRetrievedFromStorage 2022-03-11 16:22:39 raspberrypi root[100091] INFO SetSdkKey: f/1/r = b'\x150\x01\x01\x00$\x02\x017\x03$\x14\x00\x18&\x04\x80"\x81\'&\x05\x80%M:7\x06$\x14\x00\x18$\x07\x01$\x08\x010\tA\x04\x05\xb1wi\xf0\xc9\xcc\x8f+\xa7\xfc\ xcd}\xcdU:\x9c\xc79)\x06H\x81.^\xb8y_\xeb\x85\x8a\xc8^\xc7f\xcf\xceV)m=M\x80\xbf\t\x1c#\xe6\xadR\xba\x06\x86\xecKs\xe3Nb\x9f\xf8%\xcd\xbb7\n5\x01)\x01\x18$\x02`0\x04\x14\xd9\xb4\xb8v\xd3o\xe0W\x85Cx\x7f\xbf\xb8FW\x94\x05*j0 \x05\x14\xd9\xb4\xb8v\xd3o\xe0W\x85Cx\x7f\xbf\xb8FW\x94\x05*j\x180\x0b@\xc4p;f\x8ep\xd5\x88\x1b\xaf\xbb\x114\xcf\xe8\xe0\xb8#\x9eC\x9c\xca\xa7\xff|:-gD\x0bSm\xd5\xd8)\x1a\xa3\x7f_\x81\xeb\xf0\x91\x1e\xb3\x8fb`fZ\xbe\xd5\x9b =|o\xbd\xf7u\x06[\x8b\x15\x0f\x18' 2022-03-11 16:22:39 raspberrypi root[100091] INFO SetSdkKey: f/1/i = b'\x150\x01\x01\x00$\x02\x017\x03$\x14\x00\x18&\x04\x80"\x81\'&\x05\x80%M:7\x06$\x13\x01\x18$\x07\x01$\x08\x010\tA\x04.\xd2bv\x84\xca\x95x5{dv\xbd\xdf\xf2 \xfb\x00\x92\n,\x07\x13Ix\xa3\xbf\x04H?\xde\xf5\x90\xff\xf4%\xc8\x99\x8c\x89d\xb4s\x81\x1e\xafO\xfe\x90\xb2>0N\x83=\xdb\xd3\xd0\xcd\x91\xd1\xe7\x11z\xd97\n5\x01)\x01\x18$\x02`0\x04\x14\xf7\xeb\xf7\xa0D\x85\xfe\x90\xf9\x9d\x 84@\xa6N\x87WP\xa7\xa9<0\x05\x14\xd9\xb4\xb8v\xd3o\xe0W\x85Cx\x7f\xbf\xb8FW\x94\x05*j\x180\x0b@\xf2\xd1_\x93\x12\xe1\xebV\xf0;\xde\x04&\xa1XLg\xafU;\xa2\x05h\xe6#\x98\xbeH\xdb4\x0b\xd2\x02y\xbe\xef\x84}\xb1\xbe\xd1\xa1\xb0\ x1e\xf4\xddh \x10]Y\xc0\xab\xa5\xa0\x9aKX\x83vJ}\xd2\x96\x18' 2022-03-11 16:22:39 raspberrypi root[100091] INFO SetSdkKey: f/1/n = b'\x150\x01\x01\x01$\x02\x017\x03$\x13\x01\x18&\x04\x80"\x81\'&\x05\x80%M:7\x06$\x15\x01$\x11\x01\x18$\x07\x01$\x08\x010\tA\x04;\x1e%o\x96\xaf\x0b\xc4N\xa 7E\xf0\xfc\x90t\x8d\xdc\x8ej\xcdc\xab\xfa\x0b\xe8\x0cA\x8d\xab\x87\x86\xc0\x7fp\xa4(\x1b)er\xfc|a+\xfc\xa5\x7f\x8ay\x88k\xed\x99\x99\xe0\xf3\xb8\xf5\xf3\x9f\r\x18k\xb17\n5\x01(\x01\x18$\x02\x016\x03\x04\x02\x04\x01\x180\x04 \x14A\x9bo\xd9#\x86\xees\x91l\xc0u\x06\x13\x065\t\xf5\xc5\xac0\x05\x14\xf7\xeb\xf7\xa0D\x85\xfe\x90\xf9\x9d\x84@\xa6N\x87WP\xa7\xa9<\x180\x0b@\xc0\x13\x82\x005\xd4\xf4p<\xa1\xc6\x1c\x16\xa3wXQ\x98z\xc0r\xed\x8es\x12jz\xf0 2022-03-11 16:22:40 raspberrypi chip.DL[100091] INFO Avahi group established chip-device-ctrl > set-pairing-thread-credential 0e080000000000010000000300001035060004001fffe00208881ba1493b1046330708fd8af464ab239bb00510791f0b9ea4df2daef7efdb39887871ef030d4d79537065637472756d50616e0102485e0410c17666b9f7 b13d0c3f59ccd66d4577990c0402a0fff8 chip-device-ctrl > chip-device-ctrl > connect -ble 3840 20202021 123456 2022-03-11 16:22:48 raspberrypi root[100091] WARNING /home/pi/matter-rpi4-nRF52840-dongle/third_party/connectedhomeip/out/python_env/bin/chip-device-ctrl:600: DeprecationWarning:This method is being deprecated. Please use the DeviceController.[ConnectBLE|CommissionIP] methods directly in the REPL Device is assigned with nodeid = 123456 2022-03-11 16:22:48 raspberrypi chip.IN[100091] INFO Prepared unauthenticated message 0x7f977fbe38 to 0x0000000000000000 (0) of type 0x20 and protocolId (0, 0) on exchange 59478i with MessageCounter:1517111520. 2022-03-11 16:22:48 raspberrypi chip.IN[100091] INFO Sending unauthenticated msg 0x7f977fbe38 with MessageCounter:1517111520 to 0x0000000000000000 at monotonic time: 000000000E7C15EB msec 2022-03-11 16:22:48 raspberrypi chip.CTL[100091] INFO Setting thread operational dataset from parameters 2022-03-11 16:22:48 raspberrypi chip.CTL[100091] INFO Setting attestation nonce to random value 2022-03-11 16:22:48 raspberrypi chip.CTL[100091] INFO Setting CSR nonce to random value 2022-03-11 16:22:48 raspberrypi chip.CTL[100091] INFO Commission called for node ID 0x000000000001E240 2022-03-11 16:22:48 raspberrypi chip.BLE[100091] INFO BLE removing known devices. 2022-03-11 16:22:48 raspberrypi chip.BLE[100091] INFO BLE initiating scan. 2022-03-11 16:22:48 raspberrypi chip.BLE[100091] INFO New device scanned: DE:7D:82:15:EB:96 2022-03-11 16:22:48 raspberrypi chip.BLE[100091] INFO Device discriminator match. Attempting to connect. 2022-03-11 16:22:48 raspberrypi chip.BLE[100091] INFO Scan complete notification without an active scan. 2022-03-11 16:22:50 raspberrypi chip.BLE[100091] INFO subscribe complete, ep = 0x7f9eed4d00 2022-03-11 16:22:50 raspberrypi chip.BLE[100091] INFO peripheral chose BTP version 4; central expected between 4 and 4 2022-03-11 16:22:50 raspberrypi chip.BLE[100091] INFO using BTP fragment sizes rx 244 / tx 244. 2022-03-11 16:22:50 raspberrypi chip.BLE[100091] INFO local and remote recv window size = 5 2022-03-11 16:22:50 raspberrypi chip.EM[100091] INFO Received message of type 0x21 with protocolId (0, 0) and MessageCounter:2937866294 on exchange 59478i 2022-03-11 16:22:50 raspberrypi chip.IN[100091] INFO Prepared unauthenticated message 0x7f977fc338 to 0x0000000000000000 (0) of type 0x22 and protocolId (0, 0) on exchange 59478i with MessageCounter:1517111521. 2022-03-11 16:22:50 raspberrypi chip.IN[100091] INFO Sending unauthenticated msg 0x7f977fc338 with MessageCounter:1517111521 to 0x0000000000000000 at monotonic time: 000000000E7C1F0E msec 2022-03-11 16:22:52 raspberrypi chip.EM[100091] INFO Received message of type 0x23 with protocolId (0, 0) and MessageCounter:2937866295 on exchange 59478i 2022-03-11 16:22:52 raspberrypi chip.IN[100091] INFO Prepared unauthenticated message 0x7f977fc658 to 0x0000000000000000 (0) of type 0x24 and protocolId (0, 0) on exchange 59478i with MessageCounter:1517111522. 2022-03-11 16:22:52 raspberrypi chip.IN[100091] INFO Sending unauthenticated msg 0x7f977fc658 with MessageCounter:1517111522 to 0x0000000000000000 at monotonic time: 000000000E7C2702 msec 2022-03-11 16:22:52 raspberrypi chip.EM[100091] INFO Received message of type 0x40 with protocolId (0, 0) and MessageCounter:2937866296 on exchange 59478i 2022-03-11 16:22:52 raspberrypi chip.CTL[100091] INFO Sending request for commissioning information 2022-03-11 16:22:52 raspberrypi chip.IN[100091] INFO Prepared secure message 0x7f977fb028 to 0x000000000001E240 (1) of type 0x2 and protocolId (0, 1) on exchange 59479i with MessageCounter:11872737. 2022-03-11 16:22:52 raspberrypi chip.IN[100091] INFO Sending encrypted msg 0x7f977fb028 with MessageCounter:11872737 to 0x000000000001E240 (1) at monotonic time: 000000000E7C2761 msec 2022-03-11 16:22:53 raspberrypi chip.EM[100091] INFO Received message of type 0x5 with protocolId (0, 1) and MessageCounter:109780 on exchange 59479i 2022-03-11 16:22:53 raspberrypi chip.CTL[100091] INFO Arming failsafe (60 seconds) 2022-03-11 16:22:53 raspberrypi chip.IN[100091] INFO Prepared secure message 0x7f977fabd8 to 0x000000000001E240 (1) of type 0x8 and protocolId (0, 1) on exchange 59480i with MessageCounter:11872738. 2022-03-11 16:22:53 raspberrypi chip.IN[100091] INFO Sending encrypted msg 0x7f977fabd8 with MessageCounter:11872738 to 0x000000000001E240 (1) at monotonic time: 000000000E7C2826 msec 2022-03-11 16:22:53 raspberrypi chip.EM[100091] INFO Received message of type 0x9 with protocolId (0, 1) and MessageCounter:109781 on exchange 59480i 2022-03-11 16:22:53 raspberrypi chip.DMG[100091] INFO Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0001 2022-03-11 16:22:53 raspberrypi chip.CTL[100091] INFO Received ArmFailSafe response 2022-03-11 16:22:53 raspberrypi chip.CTL[100091] INFO Setting Regulatory Config 2022-03-11 16:22:53 raspberrypi chip.CTL[100091] INFO Device does not support configurable regulatory location 2022-03-11 16:22:53 raspberrypi chip.CTL[100091] ERROR Unable to find country code, defaulting to XX 2022-03-11 16:22:53 raspberrypi chip.IN[100091] INFO Prepared secure message 0x7f977fa508 to 0x000000000001E240 (1) of type 0x8 and protocolId (0, 1) on exchange 59481i with MessageCounter:11872739. 2022-03-11 16:22:53 raspberrypi chip.IN[100091] INFO Sending encrypted msg 0x7f977fa508 with MessageCounter:11872739 to 0x000000000001E240 (1) at monotonic time: 000000000E7C288C msec 2022-03-11 16:22:53 raspberrypi chip.EM[100091] INFO Received message of type 0x9 with protocolId (0, 1) and MessageCounter:109782 on exchange 59481i 2022-03-11 16:22:53 raspberrypi chip.DMG[100091] INFO Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0003 2022-03-11 16:22:53 raspberrypi chip.CTL[100091] INFO Received SetRegulatoryConfig response 2022-03-11 16:22:53 raspberrypi chip.CTL[100091] INFO Sending request for PAI certificate 2022-03-11 16:22:53 raspberrypi chip.IN[100091] INFO Prepared secure message 0x7f977fa468 to 0x000000000001E240 (1) of type 0x8 and protocolId (0, 1) on exchange 59482i with MessageCounter:11872740. 2022-03-11 16:22:53 raspberrypi chip.IN[100091] INFO Sending encrypted msg 0x7f977fa468 with MessageCounter:11872740 to 0x000000000001E240 (1) at monotonic time: 000000000E7C2919 msec 2022-03-11 16:22:53 raspberrypi chip.EM[100091] INFO Received message of type 0x9 with protocolId (0, 1) and MessageCounter:109783 on exchange 59482i 2022-03-11 16:22:53 raspberrypi chip.DMG[100091] INFO Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0003 2022-03-11 16:22:53 raspberrypi chip.CTL[100091] INFO Received certificate chain from the device 2022-03-11 16:22:53 raspberrypi chip.CTL[100091] INFO Sending request for DAC certificate 2022-03-11 16:22:53 raspberrypi chip.IN[100091] INFO Prepared secure message 0x7f977fa408 to 0x000000000001E240 (1) of type 0x8 and protocolId (0, 1) on exchange 59483i with MessageCounter:11872741. 2022-03-11 16:22:53 raspberrypi chip.IN[100091] INFO Sending encrypted msg 0x7f977fa408 with MessageCounter:11872741 to 0x000000000001E240 (1) at monotonic time: 000000000E7C2A3D msec 2022-03-11 16:22:53 raspberrypi chip.EM[100091] INFO Received message of type 0x9 with protocolId (0, 1) and MessageCounter:109784 on exchange 59483i 2022-03-11 16:22:53 raspberrypi chip.DMG[100091] INFO Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0003 2022-03-11 16:22:53 raspberrypi chip.CTL[100091] INFO Received certificate chain from the device 2022-03-11 16:22:53 raspberrypi chip.CTL[100091] INFO Sending Attestation Request to the device. 2022-03-11 16:22:53 raspberrypi chip.IN[100091] INFO Prepared secure message 0x7f977fa3b8 to 0x000000000001E240 (1) of type 0x8 and protocolId (0, 1) on exchange 59484i with MessageCounter:11872742. 2022-03-11 16:22:53 raspberrypi chip.IN[100091] INFO Sending encrypted msg 0x7f977fa3b8 with MessageCounter:11872742 to 0x000000000001E240 (1) at monotonic time: 000000000E7C2B62 msec 2022-03-11 16:22:54 raspberrypi chip.EM[100091] INFO Received message of type 0x9 with protocolId (0, 1) and MessageCounter:109785 on exchange 59484i 2022-03-11 16:22:54 raspberrypi chip.DMG[100091] INFO Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0001 2022-03-11 16:22:54 raspberrypi chip.CTL[100091] INFO Received Attestation Information from the device 2022-03-11 16:22:54 raspberrypi chip.CTL[100091] INFO Verifying attestation 2022-03-11 16:22:54 raspberrypi chip.CTL[100091] INFO Successfully validated 'Attestation Information' command received from the device. 2022-03-11 16:22:54 raspberrypi chip.IN[100091] INFO Prepared secure message 0x7f977f8558 to 0x000000000001E240 (1) of type 0x8 and protocolId (0, 1) on exchange 59485i with MessageCounter:11872743. 2022-03-11 16:22:54 raspberrypi chip.IN[100091] INFO Sending encrypted msg 0x7f977f8558 with MessageCounter:11872743 to 0x000000000001E240 (1) at monotonic time: 000000000E7C2CFC msec 2022-03-11 16:22:54 raspberrypi chip.EM[100091] INFO Received message of type 0x9 with protocolId (0, 1) and MessageCounter:109786 on exchange 59485i 2022-03-11 16:22:54 raspberrypi chip.DMG[100091] INFO Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0005 2022-03-11 16:22:54 raspberrypi chip.CTL[100091] INFO Received certificate signing request from the device 2022-03-11 16:22:54 raspberrypi chip.CTL[100091] INFO Getting certificate chain for the device from the issuer 2022-03-11 16:22:54 raspberrypi chip.CTL[100091] INFO Verifying Certificate Signing Request 2022-03-11 16:22:54 raspberrypi chip.CTL[100091] INFO Generating NOC 2022-03-11 16:22:54 raspberrypi chip.CTL[100091] INFO Providing certificate chain to the commissioner 2022-03-11 16:22:54 raspberrypi chip.CTL[100091] INFO Received callback from the CA for NOC Chain generation. Status ../../src/controller/ExampleOperationalCredentialsIssuer.cpp:229: Success 2022-03-11 16:22:54 raspberrypi chip.CTL[100091] INFO Sending root certificate to the device 2022-03-11 16:22:54 raspberrypi chip.IN[100091] INFO Prepared secure message 0x7f977f8538 to 0x000000000001E240 (1) of type 0x8 and protocolId (0, 1) on exchange 59486i with MessageCounter:11872744. 2022-03-11 16:22:54 raspberrypi chip.IN[100091] INFO Sending encrypted msg 0x7f977f8538 with MessageCounter:11872744 to 0x000000000001E240 (1) at monotonic time: 000000000E7C2F0E msec 2022-03-11 16:22:54 raspberrypi chip.CTL[100091] INFO Sent root certificate to the device 2022-03-11 16:22:55 raspberrypi chip.EM[100091] INFO Received message of type 0x9 with protocolId (0, 1) and MessageCounter:109787 on exchange 59486i 2022-03-11 16:22:55 raspberrypi chip.DMG[100091] INFO Received Command Response Status for Endpoint=0 Cluster=0x0000_003E Command=0x0000_000B Status=0x0 2022-03-11 16:22:55 raspberrypi chip.CTL[100091] INFO Device confirmed that it has received the root certificate 2022-03-11 16:22:55 raspberrypi chip.CTL[100091] INFO Sending operational certificate chain to the device 2022-03-11 16:22:55 raspberrypi chip.IN[100091] INFO Prepared secure message 0x7f977fa418 to 0x000000000001E240 (1) of type 0x8 and protocolId (0, 1) on exchange 59487i with MessageCounter:11872745. 2022-03-11 16:22:55 raspberrypi chip.IN[100091] INFO Sending encrypted msg 0x7f977fa418 with MessageCounter:11872745 to 0x000000000001E240 (1) at monotonic time: 000000000E7C2FBE msec 2022-03-11 16:22:55 raspberrypi chip.CTL[100091] INFO Sent operational certificate to the device 2022-03-11 16:22:56 raspberrypi chip.EM[100091] INFO Received message of type 0x9 with protocolId (0, 1) and MessageCounter:109788 on exchange 59487i 2022-03-11 16:22:56 raspberrypi chip.DMG[100091] INFO Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0008 2022-03-11 16:22:56 raspberrypi chip.CTL[100091] INFO Device returned status 0 on receiving the NOC 2022-03-11 16:22:56 raspberrypi chip.CTL[100091] INFO Operational credentials provisioned on device 0x7f840278e0 2022-03-11 16:22:56 raspberrypi chip.CTL[100091] ERROR Required network information not provided in commissioning parameters 2022-03-11 16:22:56 raspberrypi chip.CTL[100091] ERROR Parameters supplied: wifi (no) thread (no) 2022-03-11 16:22:56 raspberrypi chip.CTL[100091] ERROR Device supports: wifi (no) thread(yes) 2022-03-11 16:22:56 raspberrypi chip.CTL[100091] INFO Rendezvous cleanup Failed to commission: 47 Device temporary node id (**this does not match spec**): 123456 ```
dtodor commented 2 years ago

Not sure about the Python controller, but we are using a custom CommissioningDelegate and the same error occurs after the latest changes. The fix is pretty simple inside the CHIPDeviceController.cpp:

CHIP_ERROR DeviceCommissioner::Commission(NodeId remoteDeviceId, CommissioningParameters & params)
{
    ReturnErrorOnFailure(mAutoCommissioner.SetCommissioningParameters(params));
    return Commission(remoteDeviceId);
}

i.e. replace mAutoCommissioner. with mDefaultCommissioner->.

caubut-charter commented 2 years ago

No longer having this issue.