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

Unable to connect chip tool to simulated device #22312

Closed
ep1cman opened this issue Aug 31, 2022 · 3 comments · Fixed by #22332
Closed

Unable to connect chip tool to simulated device #22312

ep1cman opened this issue Aug 31, 2022 · 3 comments · Fixed by #22332

Comments

@ep1cman
Copy link

ep1cman commented Aug 31, 2022

I have build the simulated device but when I try to comission it using chip-tool as per the docs here:https://github.com/project-chip/connectedhomeip/blob/master/docs/guides/simulated_device_linux.md

In one terminal I run the simulated device:

adlink@comhpcalt:~/connectedhomeip$ ./out/simulated/chip-app1
[1661960804.352568][3887:3887] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs
[1661960804.355161][3887:3887] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs
[1661960804.355183][3887:3887] CHIP:DL: ChipLinuxStorage::Init: Attempt to re-initialize with KVS config file: /tmp/chip_kvs
[1661960804.355319][3887:3887] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini
[1661960804.355410][3887:3887] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini
[1661960804.355452][3887:3887] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini
[1661960804.355614][3887:3887] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-OLXa57)
[1661960804.355825][3887:3887] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1661960804.355845][3887:3887] CHIP:DL: NVS set: chip-counters/reboot-count = 13 (0xD)
[1661960804.356284][3887:3887] CHIP:DL: Got Ethernet interface: enP4p4s0
[1661960804.356590][3887:3887] CHIP:DL: Found the primary Ethernet interface:enP4p4s0
[1661960804.356933][3887:3887] CHIP:DL: Failed to get WiFi interface
[1661960804.356943][3887:3887] CHIP:DL: Failed to reset WiFi statistic counts
[1661960804.356957][3887:3887] CHIP:SPT: *** WARNING: Using temporary passcode 20202021 due to no neither --passcode or --spake2p-verifier-base64 given on command line. This is temporary and will disappear. Please update your scripts to explicitly configure onboarding credentials. ***
[1661960804.356969][3887:3887] CHIP:SPT: *** WARNING: Using temporary test discriminator 3840 due to --discriminator not given on command line. This is temporary and will disappear. Please update your scripts to explicitly configure discriminator. ***
[1661960804.356977][3887:3887] CHIP:SPT: PASE PBKDF iterations set to 1000
[1661960804.356987][3887:3887] CHIP:SPT: LinuxCommissionableDataProvider didn't get a PASE salt, generating one.
[1661960804.359202][3887:3887] CHIP:DL: Device Configuration:
[1661960804.359219][3887:3887] CHIP:DL:   Serial Number: TEST_SN
[1661960804.359227][3887:3887] CHIP:DL:   Vendor Id: 65521 (0xFFF1)
[1661960804.359244][3887:3887] CHIP:DL:   Product Id: 32769 (0x8001)
[1661960804.359252][3887:3887] CHIP:DL:   Hardware Version: 0
[1661960804.359257][3887:3887] CHIP:DL:   Setup Pin Code (0 for UNKNOWN/ERROR): 20202021
[1661960804.359264][3887:3887] CHIP:DL:   Setup Discriminator (0xFFFF for UNKNOWN/ERROR): 3840 (0xF00)
[1661960804.359280][3887:3887] CHIP:DL:   Manufacturing Date: (not set)
[1661960804.359284][3887:3887] CHIP:DL:   Device Type: 65535 (0xFFFF)
[1661960804.359287][3887:3887] CHIP:-: ==== Onboarding payload for Standard Commissioning Flow ====
[1661960804.359300][3887:3887] CHIP:SVR: SetupQRCode: [MT:-24J0AFN00KA0648G00]
[1661960804.359309][3887:3887] CHIP:SVR: Copy/paste the below URL in a browser to see the QR Code:
[1661960804.359314][3887:3887] CHIP:SVR: https://project-chip.github.io/connectedhomeip/qrcode.html?data=MT%3A-24J0AFN00KA0648G00
[1661960804.359325][3887:3887] CHIP:SVR: Manual pairing code: [34970112332]
[1661960804.359329][3887:3887] CHIP:-: ==== Onboarding payload for Custom Commissioning Flows ====
[1661960804.359344][3887:3887] CHIP:SVR: SetupQRCode: [MT:-24J029Q00KA0648G00]
[1661960804.359351][3887:3887] CHIP:SVR: Copy/paste the below URL in a browser to see the QR Code:
[1661960804.359354][3887:3887] CHIP:SVR: https://project-chip.github.io/connectedhomeip/qrcode.html?data=MT%3A-24J029Q00KA0648G00
[1661960804.359366][3887:3887] CHIP:SVR: Manual pairing code: [749701123365521327694]
[1661960804.359377][3887:3887] CHIP:SVR: Server initializing...
[1661960804.359384][3887:3887] CHIP:FP: Initializing FabricTable from persistent storage
[1661960804.359414][3887:3887] CHIP:TS: Last Known Good Time: 2022-08-24T14:32:22
[1661960804.359429][3887:3887] CHIP:DMG: AccessControl: initializing
[1661960804.359435][3887:3887] CHIP:DMG: Examples::AccessControlDelegate::Init
[1661960804.359443][3887:3887] CHIP:DMG: AccessControl: setting
[1661960804.359449][3887:3887] CHIP:DMG: DefaultAclStorage: initializing
[1661960804.359453][3887:3887] CHIP:DMG: DefaultAclStorage: 0 entries loaded
[1661960804.359463][3887:3887] CHIP:IN: UDP::Init bind&listen port=5543
[1661960804.359493][3887:3887] CHIP:IN: UDP::Init bound to port=5543
[1661960804.359499][3887:3887] CHIP:IN: UDP::Init bind&listen port=5543
[1661960804.359515][3887:3887] CHIP:IN: UDP::Init bound to port=5543
[1661960804.359520][3887:3887] CHIP:IN: TransportMgr initialized
[1661960804.359601][3887:3887] CHIP:DL: writing settings to file (/tmp/chip_kvs-NgedY6)
[1661960804.359763][3887:3887] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs)
[1661960804.359807][3887:3887] CHIP:DL: writing settings to file (/tmp/chip_kvs-x3Twy7)
[1661960804.359903][3887:3887] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs)
[1661960804.360902][3887:3887] CHIP:DL: writing settings to file (/tmp/chip_kvs-3iUKp5)
[1661960804.361050][3887:3887] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs)
[1661960804.361066][3887:3887] CHIP:ZCL: Using ZAP configuration...
[1661960804.361103][3887:3887] CHIP:DMG: Failed to read stored attribute (0, 0x0000_0028, 0x0000_0005: ../../examples/placeholder/linux/third_party/connectedhomeip/src/platform/Linux/KeyValueStoreManagerImpl.cpp:53: CHIP Error 0x000000A0: Value not found in the persisted storage
[1661960804.361130][3887:3887] CHIP:DMG: Failed to read stored attribute (0, 0x0000_0028, 0x0000_0010: ../../examples/placeholder/linux/third_party/connectedhomeip/src/platform/Linux/KeyValueStoreManagerImpl.cpp:53: CHIP Error 0x000000A0: Value not found in the persisted storage
[1661960804.361176][3887:3887] CHIP:DMG: Failed to read stored attribute (0, 0x0000_0102, 0x0000_0003: ../../examples/placeholder/linux/third_party/connectedhomeip/src/platform/Linux/KeyValueStoreManagerImpl.cpp:53: CHIP Error 0x000000A0: Value not found in the persisted storage
[1661960804.361189][3887:3887] CHIP:DMG: Failed to read stored attribute (0, 0x0000_0102, 0x0000_0004: ../../examples/placeholder/linux/third_party/connectedhomeip/src/platform/Linux/KeyValueStoreManagerImpl.cpp:53: CHIP Error 0x000000A0: Value not found in the persisted storage
[1661960804.361213][3887:3887] CHIP:DMG: Failed to read stored attribute (0, 0x0000_0102, 0x0000_0008: ../../examples/placeholder/linux/third_party/connectedhomeip/src/platform/Linux/KeyValueStoreManagerImpl.cpp:53: CHIP Error 0x000000A0: Value not found in the persisted storage
[1661960804.361226][3887:3887] CHIP:DMG: Failed to read stored attribute (0, 0x0000_0102, 0x0000_0009: ../../examples/placeholder/linux/third_party/connectedhomeip/src/platform/Linux/KeyValueStoreManagerImpl.cpp:53: CHIP Error 0x000000A0: Value not found in the persisted storage
[1661960804.361241][3887:3887] CHIP:DMG: Failed to read stored attribute (0, 0x0000_0102, 0x0000_000E: ../../examples/placeholder/linux/third_party/connectedhomeip/src/platform/Linux/KeyValueStoreManagerImpl.cpp:53: CHIP Error 0x000000A0: Value not found in the persisted storage
[1661960804.361254][3887:3887] CHIP:DMG: Failed to read stored attribute (0, 0x0000_0102, 0x0000_000F: ../../examples/placeholder/linux/third_party/connectedhomeip/src/platform/Linux/KeyValueStoreManagerImpl.cpp:53: CHIP Error 0x000000A0: Value not found in the persisted storage
[1661960804.361267][3887:3887] CHIP:DMG: Failed to read stored attribute (0, 0x0000_0102, 0x0000_0010: ../../examples/placeholder/linux/third_party/connectedhomeip/src/platform/Linux/KeyValueStoreManagerImpl.cpp:53: CHIP Error 0x000000A0: Value not found in the persisted storage
[1661960804.361279][3887:3887] CHIP:DMG: Failed to read stored attribute (0, 0x0000_0102, 0x0000_0011: ../../examples/placeholder/linux/third_party/connectedhomeip/src/platform/Linux/KeyValueStoreManagerImpl.cpp:53: CHIP Error 0x000000A0: Value not found in the persisted storage
[1661960804.361293][3887:3887] CHIP:DMG: Failed to read stored attribute (0, 0x0000_0102, 0x0000_0012: ../../examples/placeholder/linux/third_party/connectedhomeip/src/platform/Linux/KeyValueStoreManagerImpl.cpp:53: CHIP Error 0x000000A0: Value not found in the persisted storage
[1661960804.361305][3887:3887] CHIP:DMG: Failed to read stored attribute (0, 0x0000_0102, 0x0000_0013: ../../examples/placeholder/linux/third_party/connectedhomeip/src/platform/Linux/KeyValueStoreManagerImpl.cpp:53: CHIP Error 0x000000A0: Value not found in the persisted storage
[1661960804.361318][3887:3887] CHIP:DMG: Failed to read stored attribute (0, 0x0000_0102, 0x0000_0017: ../../examples/placeholder/linux/third_party/connectedhomeip/src/platform/Linux/KeyValueStoreManagerImpl.cpp:53: CHIP Error 0x000000A0: Value not found in the persisted storage
[1661960804.361386][3887:3887] CHIP:DMG: Failed to read stored attribute (1, 0x0000_0028, 0x0000_0005: ../../examples/placeholder/linux/third_party/connectedhomeip/src/platform/Linux/KeyValueStoreManagerImpl.cpp:53: CHIP Error 0x000000A0: Value not found in the persisted storage
[1661960804.361402][3887:3887] CHIP:DMG: Failed to read stored attribute (1, 0x0000_0028, 0x0000_0010: ../../examples/placeholder/linux/third_party/connectedhomeip/src/platform/Linux/KeyValueStoreManagerImpl.cpp:53: CHIP Error 0x000000A0: Value not found in the persisted storage
[1661960804.361424][3887:3887] CHIP:DMG: Endpoint 0, Cluster 0x0000_0030 update version to 204ad517
[1661960804.361445][3887:3887] CHIP:ZCL: GeneralDiagnostics: OnDeviceReboot
[1661960804.361451][3887:3887] CHIP:DMG: Endpoint 0, Cluster 0x0000_0033 update version to c19a22c0
[1661960804.361486][3887:3887] CHIP:EVL: LogEvent event number: 0x0000000000050000 priority: 2, endpoint id:  0x0 cluster id: 0x0000_0033 event id: 0x3 Sys timestamp: 0x0000000001107320
[1661960804.361498][3887:3887] CHIP:ZCL: Initiating Admin Commissioning cluster.
[1661960804.361504][3887:3887] CHIP:ZCL: Initialize PCC Plugin Server Cluster.
[1661960804.361517][3887:3887] CHIP:ZCL: ModeSelect: Skipped initializing CurrentMode by StartUpMode because one of them is volatile
[1661960804.361524][3887:3887] CHIP:ZCL: Window Covering Cluster init
[1661960804.361571][3887:3887] CHIP:DL: writing settings to file (/tmp/chip_kvs-m5oX94)
[1661960804.361690][3887:3887] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs)
[1661960804.361704][3887:3887] CHIP:DMG: Endpoint 0, Cluster 0x0000_0102 update version to ea3994a2
[1661960804.361712][3887:3887] CHIP:ZCL: WC POST ATTRIBUTE=7
[1661960804.361720][3887:3887] CHIP:ZCL: ConfigStatus 0x1B Operational=1 OnlineReserved=1
[1661960804.361726][3887:3887] CHIP:ZCL: Lift(PA=1 Encoder=0 Reversed=0) Tilt(PA=1 Encoder=0)
[1661960804.361735][3887:3887] CHIP:ZCL: Initialize PCC Server Cluster [EP:0]
[1661960804.361743][3887:3887] CHIP:ZCL: Constant Pressure Supported
[1661960804.361749][3887:3887] CHIP:ZCL: PCC Server: Constant Proportional Pressure Supported
[1661960804.361755][3887:3887] CHIP:ZCL: PCC Server: Constant Flow Supported
[1661960804.361762][3887:3887] CHIP:ZCL: PCC Server: Constant Temperature Supported
[1661960804.361769][3887:3887] CHIP:ZCL: PCC Server: Constant Speed Supported
[1661960804.361778][3887:3887] CHIP:DMG: Endpoint 1, Cluster 0x0000_0004 update version to 318af711
[1661960804.361786][3887:3887] CHIP:DMG: Endpoint 1, Cluster 0x0000_0004 update version to 318af712
[1661960804.361793][3887:3887] CHIP:DMG: Endpoint 1, Cluster 0x0000_0005 update version to 3b1b80fc
[1661960804.361847][3887:3887] CHIP:IN: SecureSession[0xaaaafaab1e00]: Allocated Type:1 LSID:29230
[1661960804.361860][3887:3887] CHIP:SC: Assigned local session key ID 29230
[1661960804.361867][3887:3887] CHIP:SC: Waiting for PBKDF param request
[1661960804.361872][3887:3887] CHIP:DIS: Updating services using commissioning mode 1
[1661960804.362784][3887:3887] CHIP:DIS: CHIP minimal mDNS started advertising.
[1661960804.363315][3887:3887] CHIP:DL: Using wifi MAC for hostname
[1661960804.363347][3887:3887] CHIP:DIS: Advertise commission parameter vendorID=65521 productID=32769 discriminator=3840/15 cm=1
[1661960804.363659][3887:3887] CHIP:DIS: Responding with _matterc._udp.local
[1661960804.363668][3887:3887] CHIP:DIS: Responding with F006D559D9E6B61D._matterc._udp.local
[1661960804.363674][3887:3887] CHIP:DIS: Responding with 0030643D12DA0000.local
[1661960804.363679][3887:3887] CHIP:DIS: Responding with 0030643D12DA0000.local
[1661960804.363687][3887:3887] CHIP:DIS: Responding with _V65521._sub._matterc._udp.local
[1661960804.363695][3887:3887] CHIP:DIS: Responding with _S15._sub._matterc._udp.local
[1661960804.363702][3887:3887] CHIP:DIS: Responding with _L3840._sub._matterc._udp.local
[1661960804.363708][3887:3887] CHIP:DIS: Responding with _CM._sub._matterc._udp.local
[1661960804.363721][3887:3887] CHIP:DIS: Responding with F006D559D9E6B61D._matterc._udp.local
[1661960804.363726][3887:3887] CHIP:DIS: CHIP minimal mDNS configured as 'Commissionable node device'.
[1661960804.364605][3887:3887] CHIP:DIS: Broadcasting mDns reply for query from 172.16.0.178
[1661960804.365336][3887:3887] CHIP:DIS: Broadcasting mDns reply for query from 172.17.0.1
[1661960804.366008][3887:3887] CHIP:DIS: Broadcasting mDns reply for query from fe80::230:64ff:fe3d:12da
[1661960804.366056][3887:3887] CHIP:DIS: mDNS service published: _matterc._udp
[1661960804.366066][3887:3887] CHIP:DIS: Updating services using commissioning mode 1
[1661960804.366905][3887:3887] CHIP:DIS: CHIP minimal mDNS started advertising.
[1661960804.367772][3887:3887] CHIP:DIS: Broadcasting mDns reply for query from 172.16.0.178
[1661960804.368428][3887:3887] CHIP:DIS: Broadcasting mDns reply for query from 172.17.0.1
[1661960804.369082][3887:3887] CHIP:DIS: Broadcasting mDns reply for query from fe80::230:64ff:fe3d:12da
[1661960804.369443][3887:3887] CHIP:DL: Using wifi MAC for hostname
[1661960804.369475][3887:3887] CHIP:DIS: Advertise commission parameter vendorID=65521 productID=32769 discriminator=3840/15 cm=1
[1661960804.369768][3887:3887] CHIP:DIS: Responding with _matterc._udp.local
[1661960804.369776][3887:3887] CHIP:DIS: Responding with F006D559D9E6B61D._matterc._udp.local
[1661960804.369780][3887:3887] CHIP:DIS: Responding with 0030643D12DA0000.local
[1661960804.369784][3887:3887] CHIP:DIS: Responding with 0030643D12DA0000.local
[1661960804.369791][3887:3887] CHIP:DIS: Responding with _V65521._sub._matterc._udp.local
[1661960804.369796][3887:3887] CHIP:DIS: Responding with _S15._sub._matterc._udp.local
[1661960804.369804][3887:3887] CHIP:DIS: Responding with _L3840._sub._matterc._udp.local
[1661960804.369809][3887:3887] CHIP:DIS: Responding with _CM._sub._matterc._udp.local
[1661960804.369819][3887:3887] CHIP:DIS: Responding with F006D559D9E6B61D._matterc._udp.local
[1661960804.369824][3887:3887] CHIP:DIS: CHIP minimal mDNS configured as 'Commissionable node device'.
[1661960804.370649][3887:3887] CHIP:DIS: Broadcasting mDns reply for query from 172.16.0.178
[1661960804.371281][3887:3887] CHIP:DIS: Broadcasting mDns reply for query from 172.17.0.1
[1661960804.371906][3887:3887] CHIP:DIS: Broadcasting mDns reply for query from fe80::230:64ff:fe3d:12da
[1661960804.371941][3887:3887] CHIP:DIS: mDNS service published: _matterc._udp
[1661960804.371953][3887:3887] CHIP:IN: CASE Server enabling CASE session setups
[1661960804.371975][3887:3887] CHIP:IN: SecureSession[0xaaaafaab1ba0]: Allocated Type:2 LSID:29231
[1661960804.371986][3887:3887] CHIP:SC: Allocated SecureSession (0xaaaafaab1ba0) - waiting for Sigma1 msg
[1661960804.371994][3887:3887] CHIP:SVR: Joining Multicast groups
[1661960804.372002][3887:3887] CHIP:ZCL: Emitting StartUp event
[1661960804.372020][3887:3887] CHIP:EVL: LogEvent event number: 0x0000000000050001 priority: 2, endpoint id:  0x0 cluster id: 0x0000_0028 event id: 0x0 Sys timestamp: 0x000000000110732A
[1661960804.372034][3887:3887] CHIP:EVL: LogEvent event number: 0x0000000000050002 priority: 2, endpoint id:  0x1 cluster id: 0x0000_0028 event id: 0x0 Sys timestamp: 0x000000000110732A
[1661960804.372041][3887:3887] CHIP:SVR: Server Listening...
[1661960804.372044][3887:3887] CHIP:DL: Device Configuration:
[1661960804.372057][3887:3887] CHIP:DL:   Serial Number: TEST_SN
[1661960804.372071][3887:3887] CHIP:DL:   Vendor Id: 65521 (0xFFF1)
[1661960804.372081][3887:3887] CHIP:DL:   Product Id: 32769 (0x8001)
[1661960804.372089][3887:3887] CHIP:DL:   Hardware Version: 0
[1661960804.372094][3887:3887] CHIP:DL:   Setup Pin Code (0 for UNKNOWN/ERROR): 20202021
[1661960804.372099][3887:3887] CHIP:DL:   Setup Discriminator (0xFFFF for UNKNOWN/ERROR): 3840 (0xF00)
[1661960804.372107][3887:3887] CHIP:DL:   Manufacturing Date: (not set)
[1661960804.372112][3887:3887] CHIP:DL:   Device Type: 65535 (0xFFFF)
[1661960804.372122][3887:3887] CHIP:SVR: SetupQRCode: [MT:-24J029Q00KA0648G00]
[1661960804.372129][3887:3887] CHIP:SVR: Copy/paste the below URL in a browser to see the QR Code:
[1661960804.372134][3887:3887] CHIP:SVR: https://project-chip.github.io/connectedhomeip/qrcode.html?data=MT%3A-24J029Q00KA0648G00
[1661960804.372145][3887:3887] CHIP:SVR: Manual pairing code: [749701123365521327694]

In the other terminal I run chip-tool

adlink@comhpcalt:~/connectedhomeip$ ./out/debug/standalone/chip-tool pairing ethernet 0x654321 20202021 3842 ::1 5542
[1661960819.832435][3892:3892] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs
[1661960819.832623][3892:3892] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini
[1661960819.832660][3892:3892] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini
[1661960819.832685][3892:3892] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini
[1661960819.832794][3892:3892] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-0mKq0s)
[1661960819.832963][3892:3892] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1661960819.832978][3892:3892] CHIP:DL: NVS set: chip-counters/reboot-count = 14 (0xE)
[1661960819.833385][3892:3892] CHIP:DL: Got Ethernet interface: enP4p4s0
[1661960819.833641][3892:3892] CHIP:DL: Found the primary Ethernet interface:enP4p4s0
[1661960819.833925][3892:3892] CHIP:DL: Failed to get WiFi interface
[1661960819.833932][3892:3892] CHIP:DL: Failed to reset WiFi statistic counts
[1661960819.833947][3892:3892] CHIP:IN: UDP::Init bind&listen port=0
[1661960819.833973][3892:3892] CHIP:IN: UDP::Init bound to port=34468
[1661960819.833980][3892:3892] CHIP:IN: UDP::Init bind&listen port=0
[1661960819.833995][3892:3892] CHIP:IN: UDP::Init bound to port=59974
[1661960819.834001][3892:3892] CHIP:IN: BLEBase::Init - setting/overriding transport
[1661960819.834004][3892:3892] CHIP:IN: TransportMgr initialized
[1661960819.834019][3892:3892] CHIP:FP: Initializing FabricTable from persistent storage
[1661960819.834073][3892:3892] CHIP:TS: Last Known Good Time: 2022-08-24T14:45:13
[1661960819.834265][3892:3892] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0xDB5B12DF4DA275BD, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1
[1661960819.834739][3892:3892] CHIP:ZCL: Using ZAP configuration...
[1661960819.835687][3892:3892] CHIP:CTL: System State Initialized...
[1661960819.835725][3892:3892] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1661960819.835745][3892:3892] CHIP:CTL: Setting attestation nonce to random value
[1661960819.835758][3892:3892] CHIP:CTL: Setting CSR nonce to random value
[1661960819.835888][3892:3897] CHIP:DL: CHIP task running
[1661960819.836039][3892:3897] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1661960819.836062][3892:3897] CHIP:CTL: Setting attestation nonce to random value
[1661960819.836102][3892:3897] CHIP:CTL: Setting CSR nonce to random value
[1661960819.838221][3892:3897] CHIP:CTL: Generating NOC
[1661960819.838962][3892:3897] CHIP:FP: Validating NOC chain
[1661960819.840889][3892:3897] CHIP:FP: NOC chain validation successful
[1661960819.841008][3892:3897] CHIP:FP: Updated fabric at index: 0x1, Node ID: 0x000000000001B669
[1661960819.841021][3892:3897] CHIP:TS: Last Known Good Time: 2022-08-24T14:45:13
[1661960819.841030][3892:3897] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00
[1661960819.841038][3892:3897] CHIP:TS: Retaining current Last Known Good Time
[1661960819.841748][3892:3897] CHIP:FP: Metadata for Fabric 0x1 persisted to storage.
[1661960819.842270][3892:3897] CHIP:TS: Committing Last Known Good Time to storage: 2022-08-24T14:45:13
[1661960819.842726][3892:3897] CHIP:CTL: Joined the fabric at index 1. Compressed fabric ID is: 0x0000000000000000
[1661960819.845690][3892:3897] CHIP:IN: SecureSession[0xffff98020ee0]: Allocated Type:1 LSID:57397
[1661960819.845709][3892:3897] CHIP:SC: Assigned local session key ID 57397
[1661960819.845734][3892:3897] CHIP:SC: Including MRP parameters in PBKDF param request
[1661960819.845760][3892:3897] CHIP:IN: Prepared unauthenticated message 0xaaaad13706d8 to 0x0000000000000000 (0)  of type 0x20 and protocolId (0, 0) on exchange 46211i with MessageCounter:14668386.
[1661960819.845773][3892:3897] CHIP:IN: Sending unauthenticated msg 0xaaaad13706d8 with MessageCounter:14668386 to 0x0000000000000000 at monotonic time: 000000000110AF9C msec
[1661960819.845844][3892:3897] CHIP:SC: Sent PBKDF param request
[1661960819.845855][3892:3897] CHIP:CTL: Setting attestation nonce to random value
[1661960819.845863][3892:3897] CHIP:CTL: Setting CSR nonce to random value
[1661960819.845872][3892:3897] CHIP:CTL: Commission called for node ID 0x0000000000654321
[1661960825.241385][3892:3897] CHIP:EM: Retransmitting MessageCounter:14668386 on exchange 46211i Send Cnt 1
[1661960825.241459][3892:3897] CHIP:IN: Sending unauthenticated msg 0xaaaad13706d8 with MessageCounter:14668386 to 0x0000000000000000 at monotonic time: 000000000110C4B0 msec
[1661960825.241571][3892:3897] CHIP:CSM: UpdatePeerAddress: No existing OperationalSessionSetup instance found
[1661960825.241599][3892:3897] CHIP:CTL: OperationalSessionSetup[0:0000000000000000]: State change 1 --> 2
[1661960825.241620][3892:3897] CHIP:CTL: PerformAddressUpdate could not perform lookup
[1661960830.490145][3892:3897] CHIP:EM: Retransmitting MessageCounter:14668386 on exchange 46211i Send Cnt 2
[1661960830.490212][3892:3897] CHIP:IN: Sending unauthenticated msg 0xaaaad13706d8 with MessageCounter:14668386 to 0x0000000000000000 at monotonic time: 000000000110D931 msec
[1661960838.124972][3892:3897] CHIP:EM: Retransmitting MessageCounter:14668386 on exchange 46211i Send Cnt 3
[1661960838.125045][3892:3897] CHIP:IN: Sending unauthenticated msg 0xaaaad13706d8 with MessageCounter:14668386 to 0x0000000000000000 at monotonic time: 000000000110F703 msec
[1661960851.110207][3892:3897] CHIP:EM: Retransmitting MessageCounter:14668386 on exchange 46211i Send Cnt 4
[1661960851.110294][3892:3897] CHIP:IN: Sending unauthenticated msg 0xaaaad13706d8 with MessageCounter:14668386 to 0x0000000000000000 at monotonic time: 00000000011129BD msec
[1661960869.846093][3892:3897] CHIP:SC: PASESession timed out while waiting for a response from the peer. Expected message type was 33
[1661960869.846138][3892:3897] CHIP:IN: SecureSession[0xffff98020ee0]: Released - Type:1 LSID:57397
[1661960869.846164][3892:3897] CHIP:TOO: Secure Pairing Failed
[1661960869.846215][3892:3897] CHIP:TOO: Pairing Failure: ../../src/protocols/secure_channel/PASESession.cpp:245: CHIP Error 0x00000032: Timeout
[1661960869.846394][3892:3892] CHIP:CTL: Shutting down the commissioner
[1661960869.846434][3892:3892] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1661960869.846450][3892:3892] CHIP:CTL: Shutting down the controller
[1661960869.846463][3892:3892] CHIP:IN: Expiring all sessions for fabric 0x1!!
[1661960869.846479][3892:3892] CHIP:FP: Forgetting fabric 0x1
[1661960869.846493][3892:3892] CHIP:TS: Pending Last Known Good Time: 2022-08-24T14:45:13
[1661960869.846566][3892:3892] CHIP:TS: Previous Last Known Good Time: 2022-08-24T14:45:13
[1661960869.846575][3892:3892] CHIP:TS: Reverted Last Known Good Time to previous value
[1661960869.846599][3892:3892] CHIP:CTL: Shutting down the commissioner
[1661960869.846607][3892:3892] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1661960869.846612][3892:3892] CHIP:CTL: Shutting down the controller
[1661960869.846618][3892:3892] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack
[1661960869.846705][3892:3892] CHIP:DMG: IM WH moving to [Uninitialized]
[1661960869.846715][3892:3892] CHIP:DMG: IM WH moving to [Uninitialized]
[1661960869.846720][3892:3892] CHIP:DMG: IM WH moving to [Uninitialized]
[1661960869.846725][3892:3892] CHIP:DMG: IM WH moving to [Uninitialized]
[1661960869.846734][3892:3892] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet
[1661960869.846758][3892:3892] CHIP:BLE: BleConnectionDelegate::CancelConnection is not implemented.
[1661960869.846894][3892:3892] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-jILahw)
[1661960869.847120][3892:3892] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1661960869.847143][3892:3892] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0)
[1661960869.847153][3892:3892] CHIP:DL: Inet Layer shutdown
[1661960869.847160][3892:3892] CHIP:DL: BLE shutdown
[1661960869.847165][3892:3892] CHIP:DL: System Layer shutdown
[1661960869.847199][3892:3892] CHIP:TOO: Run command failure: ../../src/protocols/secure_channel/PASESession.cpp:245: CHIP Error 0x00000032: Timeout
adlink@comhpcalt:~/connectedhomeip$
@bzbarsky-apple
Copy link
Contributor

bzbarsky-apple commented Aug 31, 2022 •
edited
Loading

From the simulated device log:

[1661960804.359463][3887:3887] CHIP:IN: UDP::Init bind&listen port=5543

But the chip-tool command is connecting to port 5542:

adlink@comhpcalt:~/connectedhomeip$ ./out/debug/standalone/chip-tool pairing ethernet 0x654321 20202021 3842 ::1 5542

I don't know where this chip-tool command came from, but I strongly recommend using pairing code instead of pairing ethernet, so you don't have to get the IPs and ports right manually.

@ep1cman
Copy link
Author

ep1cman commented Aug 31, 2022

To answer your question of where did this come from: https://github.com/project-chip/connectedhomeip/blob/master/docs/guides/simulated_device_linux.md

@bzbarsky-apple
Copy link
Contributor

Looks like #15801 changed the code but not the documentation.... We should fix the docs.

@bzbarsky-apple bzbarsky-apple reopened this Sep 1, 2022
bzbarsky-apple added a commit to bzbarsky-apple/connectedhomeip that referenced this issue Sep 1, 2022
@bzbarsky-apple
Fix documentation for chip-app1 commisioning.
f928543 
"pairing code" to avoid problems like that.

Fixes project-chip#22312
bzbarsky-apple added a commit to bzbarsky-apple/connectedhomeip that referenced this issue Sep 1, 2022
@bzbarsky-apple
Fix documentation for chip-app1 commisioning.
37f82b5 
use "pairing code" to avoid problems like that.

Fixes project-chip#22312
bzbarsky-apple added a commit to bzbarsky-apple/connectedhomeip that referenced this issue Sep 1, 2022
@bzbarsky-apple
Fix documentation for chip-app1 commisioning.
c481ddd 
PR project-chip#15801 changed the port to 5543, but the documentation was not updated. Just
use "pairing code" to avoid problems like that.

Fixes project-chip#22312
@bzbarsky-apple bzbarsky-apple mentioned this issue Sep 1, 2022
Merged
bzbarsky-apple added a commit to bzbarsky-apple/connectedhomeip that referenced this issue Sep 1, 2022
@bzbarsky-apple
Fix documentation for chip-app1 commisioning.
034a79e 
PR project-chip#15801 changed the port to 5543, but the documentation was not updated. Just
use "pairing code" to avoid problems like that.

Fixes project-chip#22312
andy31415 pushed a commit that referenced this issue Sep 1, 2022
@bzbarsky-apple
Fix documentation for chip-app1 commisioning. (#22332)
f011e5a 
* Fix documentation for chip-app1 commisioning.

PR #15801 changed the port to 5543, but the documentation was not updated. Just
use "pairing code" to avoid problems like that.

Fixes #22312

* Fix review comments: add missing node id.
isiu-apple pushed a commit to isiu-apple/connectedhomeip that referenced this issue Sep 16, 2022
@bzbarsky-apple @isiu-apple
Fix documentation for chip-app1 commisioning. (project-chip#22332)
9039565 
* Fix documentation for chip-app1 commisioning.

PR project-chip#15801 changed the port to 5543, but the documentation was not updated. Just
use "pairing code" to avoid problems like that.

Fixes project-chip#22312

* Fix review comments: add missing node id.
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

Successfully merging a pull request may close this issue.

Fix documentation for chip-app1 commisioning. bzbarsky-apple/connectedhomeip
2 participants
@ep1cman @bzbarsky-apple