Skip to content
New issue

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

Sign up for GitHub

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

Already on GitHub? Sign in to your account

Jump to bottom

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

Closed
caubut-charter opened this issue Mar 11, 2022 · 2 comments
Closed

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

caubut-charter opened this issue Mar 11, 2022 · 2 comments

Comments

@caubut-charter
Copy link

caubut-charter commented Mar 11, 2022 •
edited
Loading

Seeing the same issue as with the IOS chiptool that was fixed yesterday but on the python controller: #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<L
\x1e\x18L\x9b\xd1\x15\xb6G\x8ep((\xfc\xe1\x92|\x82s\xcb\xbe\xe0\x98\xa8X^\x91l:?\xeec\\\x9dP\x18'
2022-03-11 16:22:39 raspberrypi root[100091] INFO SetSdkKey: f/1/o = b"\x15$\x00\x010\x01a\x04;\x1e%o\x96\xaf\x0b\xc4N\xa7E\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\xb1\x83\xde\xc4\x01\xde'u\xb6\x7f\xb3\xec\x04\x85\x8b'A\x8f\xbd\xaf\x00{\xcd\xd8\xaa\xf4\xc9\xe5W7$i\xb9\x18"
2022-03-11 16:22:39 raspberrypi root[100091] INFO SetSdkKey: f/1/m = b'\x15%\x00\x80\x82,\x01\x00\x18'
2022-03-11 16:22:39 raspberrypi chip.DIS[100091] INFO Fabric (1) persisted to storage. Calling OnFabricPersistedToStorage
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 chip.CTL[100091] INFO Joined the fabric at index 1. Compressed fabric ID is: 0x5BE37BE27B14065B
2022-03-11 16:22:39 raspberrypi chip.DIS[100091] INFO Advertise operational node 5BE37BE27B14065B-0000000000000001
2022-03-11 16:22:39 raspberrypi chip.DL[100091] INFO PublishService 5BE37BE27B14065B-0000000000000001._matter._tcp34016.-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 ChipBLEMgr[100091] DEBUG add adapter signal
Chip Device Controller Shell

chip-device-ctrl > 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
Copy link

dtodor commented Mar 14, 2022

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->.

vijs added a commit to vijs/connectedhomeip that referenced this issue Mar 21, 2022
@vijs
Implemented PR project-chip#16124 review comments
e9320c7
vijs added a commit to vijs/connectedhomeip that referenced this issue Mar 21, 2022
@vijs
Implemented PR project-chip#16124 review comments
a417e46
@caubut-charter
Copy link
Author

No longer having this issue.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@dtodor @caubut-charter