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

chip-tool pairing ble-wifi failed #75

Closed
sidhoo2 opened this issue Oct 28, 2022 · 9 comments
Closed

chip-tool pairing ble-wifi failed #75

sidhoo2 opened this issue Oct 28, 2022 · 9 comments

Comments

@sidhoo2
Copy link

sidhoo2 commented Oct 28, 2022

i meet this issue too. can u help me
details:

ubuntu 20.04 on vitual meachine
device is esp32c3,

  1. flash the manufacturing binary https://github.com/espressif/esp-matter/tree/main/tools/mfg_tool#readme,

  2. run device, log:
    ESP-ROM:esp32c3-api1-20210207
    Build:Feb 7 2021
    rst:0x1 (POWERON),boot:0xd (SPI_FAST_FLASH_BOOT)
    SPIWP:0xee
    mode:DIO, clock div:1
    load:0x3fcd6100,len:0x16b4
    load:0x403ce000,len:0x930
    load:0x403d0000,len:0x2d28
    entry 0x403ce000
    I (30) boot: ESP-IDF v4.4.2 2nd stage bootloader
    I (30) boot: compile time 14:24:49
    I (30) boot: chip revision: 3I (37) boot.esp32c3: SPI Mode : DIO
    I (41) boot.esp32c3: SPI Flash Size : 4MB
    I (46) boot: Enabling RNG early entropy source...
    I (52) boot: Partition Table:
    I (55) boot: ## Label Usage Type ST Offset Length
    I (62) boot: 0 sec_cert unknown 3f 06 0000d000 00003000
    I (70) boot: 1 nvs WiFi data 01 02 00010000 00006000
    I (77) boot: 2 otadata OTA data 01 00 00016000 00002000
    I (85) boot: 3 phy_init RF data 01 01 00018000 00001000
    I (92) boot: 4 ota_0 OTA app 00 10 00020000 001e0000
    I (100) boot: 5 ota_1 OTA app 00 11 00200000 001e0000
    I (107) boot: 6 fctry WiFi data 01 02 003e0000 00006000
    I (115) boot: End of partition table
    I (119) esp_image: segment 0: paddr=00020020 vaddr=3c100020 size=2f3f8h (193528) map
    I (158) esp_image: segment 1: paddr=0004f420 vaddr=3fc90400 size=00bf8h ( 3064) load
    I (159) esp_image: segment 2: paddr=00050020 vaddr=42000020 size=fb500h (1029376) map
    I (324) esp_image: segment 3: paddr=0014b528 vaddr=3fc90ff8 size=02ad0h ( 10960) load
    I (327) esp_image: segment 4: paddr=0014e000 vaddr=40380000 size=1033ch ( 66364) load
    I (342) esp_image: segment 5: paddr=0015e344 vaddr=50000010 size=00010h ( 16) load
    I (348) boot: Loaded app from partition at offset 0x20000
    I (348) boot: Disabling RNG early entropy source...
    I (363) cpu_start: Pro cpu up.
    I (371) cpu_start: Pro cpu start user code
    I (371) cpu_start: cpu freq: 160000000
    I (371) cpu_start: Application information:
    I (374) cpu_start: Project name: light
    I (379) cpu_start: App version: v1.0
    I (383) cpu_start: Compile time: Oct 28 2022 16:11:32
    I (389) cpu_start: ELF file SHA256: e7c0ddc45aab754c...
    I (395) cpu_start: ESP-IDF: v4.4.2
    I (400) heap_init: Initializing. RAM available for dynamic allocation:
    I (407) heap_init: At 3FCA46E0 len 0001B920 (110 KiB): DRAM
    I (414) heap_init: At 3FCC0000 len 0001F060 (124 KiB): STACK/DRAM
    I (420) heap_init: At 50000020 len 00001FE0 (7 KiB): RTCRAM0;32mI (427) spi_flash: detected chip: generic
    I (432) spi_flash: flash io: dio
    I (437) sleep: Configure to isolate all GPIO pins in sleep state
    I (442) sleep: Enable automatic switching of GPIO sleep configuration
    I (450) coexist: coexist rom version 9387209
    I (454) cpu_start: Starting scheduler.
    I (467) led_driver_ws2812: Initializing light driver
    I (467) gpio: GPIO[9]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0
    I (487) app_main: Light created with endpoint_id 1
    E (487) esp_matter_core: Command 0x0047 on cluster 0x0300 already exists. Not creating again.
    I (497) pp: pp rom version: 9387209
    I (497) net80211: net80211 rom version: 9387209
    I (507) wifi:wifi driver task: 3fcb0920, prio:23, stack:6656, core=0
    I (507) system_api: Base MAC address is not set
    I (517) system_api: read default base MAC address from EFUSE
    I (517) wifi:wifi firmware version: eeaa27d
    I (527) wifi:wifi certification version: v7.0
    I (527) wifi:config NVS flash: enabled
    I (527) wifi:config nano formating: disabled
    I (537) wifi:Init data frame dynamic rx buffer num: 32
    I (537) wifi:Init management frame dynamic rx buffer num: 32
    I (547) wifi:Init management short buffer num: 32
    I (547) wifi:Init dynamic tx buffer num: 32
    I (557) wifi:Init static tx FG buffer num: 2
    I (557) wifi:Init static rx buffer size: 1600
    I (557) wifi:Init static rx buffer num: 10
    I (567) wifi:Init dynamic rx buffer num: 32
    I (567) wifi_init: rx ba win: 6
    I (577) wifi_init: tcpip mbox: 32
    I (577) wifi_init: udp mbox: 6
    I (577) wifi_init: tcp mbox: 6
    I (587) wifi_init: tcp tx win: 5744
    I (587) wifi_init: tcp rx win: 5744
    I (587) wifi_init: tcp mss: 1440
    I (597) wifi_init: WiFi IRAM OP enabled
    I (597) wifi_init: WiFi RX IRAM OP enabled
    I (617) chip[DL]: NVS set: chip-counters/reboot-count = 20 (0x14)
    I (617) chip[DL]: Real time clock set to 946684800 (0100/00/01 00:00:00 UTC)
    W (617) BTDM_INIT: esp_bt_controller_mem_release not implemented, return OK
    I (627) BTDM_INIT: BT controller compile version [05195c9]
    I (637) phy_init: phy_version 912,d001756,Jun 2 2022,16:28:07
    I (667) BTDM_INIT: Bluetooth MAC: 7c:df:a1:c1:e0:52
    I (677) NimBLE: GAP procedure initiated: stop advertising.
    I (677) CHIP[DL]: BLE host-controller synced
    I (1177) chip[DL]: Configuring CHIPoBLE advertising (interval 25 ms, connectable, device name MATTER-2481)
    I (1177) NimBLE: GAP procedure initiated: advertise;
    I (1177) NimBLE: disc_mode=2
    I (1177) NimBLE: adv_channel_map=0 own_addr_type=1 adv_filter_policy=0 adv_itvl_min=40 adv_itvl_max=40
    I (1197) NimBLE:
    I (1197) chip[DL]: CHIPoBLE advertising started
    E (1197) chip[DL]: Long dispatch time: 580 ms, for event type 2
    I (1207) chip[DL]: Starting ESP WiFi layer
    I (1217) wifi:mode : sta (7c:df:a1:c1:e0:50)
    I (1217) wifi:enable tsf
    W (1217) wifi:Haven't to connect to a suitable AP now!
    I (1227) chip[DL]: Done driving station state, nothing else to do...
    I (1227) phy: chan:1,max_power:80
    I (1237) phy: chan:2,max_power:80
    I (1237) phy: chan:3,max_power:80
    I (1237) phy: chan:4,max_power:80
    I (1247) phy: chan:5,max_power:80
    I (1247) phy: chan:6,max_power:80
    I (1257) phy: chan:7,max_power:80
    I (1257) phy: chan:8,max_power:80
    I (1257) phy: chan:9,max_power:80
    I (1267) phy: chan:10,max_power:80
    I (1267) phy: chan:11,max_power:80
    I (1277) phy: chan:12,max_power:80
    I (1277) phy: chan:13,max_power:80
    I (1277) phy: chan:14,max_power:80
    W (1287) wifi:Haven't to connect to a suitable AP now!
    I (1287) chip[DL]: Done driving station state, nothing else to do...
    I (1297) phy: chan:1,max_power:80
    I (1297) phy: chan:2,max_power:80
    I (1307) phy: chan:3,max_power:80
    I (1307) phy: chan:4,max_power:80
    I (1317) phy: chan:5,max_power:80
    I (1317) phy: chan:6,max_power:80
    I (1317) phy: chan:7,max_power:80
    I (1327) phy: chan:8,max_power:80
    I (1327) phy: chan:9,max_power:80
    I (1337) phy: chan:10,max_power:80
    I (1337) phy: chan:11,max_power:80
    I (1337) phy: chan:12,max_power:80
    I (1347) phy: chan:13,max_power:80
    I (1347) phy: chan:14,max_power:80
    I (1357) chip[SVR]: Server initializing...
    I (1357) chip[TS]: Last Known Good Time: 2022-10-28T16:14:15
    I (1367) chip[DMG]: AccessControl: initializing
    I (1367) chip[DMG]: Examples::AccessControlDelegate::Init
    I (1377) chip[DMG]: AccessControl: setting
    I (1377) chip[DMG]: DefaultAclStorage: initializing
    I (1387) chip[DMG]: DefaultAclStorage: 0 entries loaded
    I (1407) chip[ZCL]: Using ZAP configuration...
    I (1407) esp_matter_cluster: Cluster plugin init common callback
    I (1407) chip[DMG]: AccessControlCluster: initializing
    I (1417) chip[ZCL]: 0x3c109058ep 0 clus 0x0000_0030 attr 0x0000_0000 not supported
    I (1417) chip[ZCL]: Initiating Admin Commissioning cluster.
    E (1427) chip[ZCL]: Duplicate attribute override registration failed
    I (1437) chip[DIS]: Updating services using commissioning mode 1
    I (1447) chip[DIS]: CHIP minimal mDNS started advertising.
    I (1447) chip[DIS]: Advertise commission parameter vendorID=65521 productID=32768 discriminator=2481/09 cm=1
    I (1457) chip[DIS]: CHIP minimal mDNS configured as 'Commissionable node device'; instance name: 3A53D3BC3C05C5E0.
    I (1467) chip[DIS]: mDNS service published: _matterc._udp
    I (1477) chip[IN]: CASE Server enabling CASE session setups
    I (1487) chip[SVR]: Joining Multicast groups
    I (1487) chip[SVR]: Server Listening...
    I (1497) esp_matter_core: Dynamic endpoint 0 added
    I (1497) esp_matter_attribute: ********** Endpoint 0x0001's Cluster 0x0003's Attribute 0x0001 is 0 **********
    I (1507) esp_matter_attribute: ********** Endpoint 0x0001's Cluster 0x0004's Attribute 0x0000 is 128 **********
    I (1517) esp_matter_attribute: ********** Endpoint 0x0001's Cluster 0x0004's Attribute 0xFFFC is <invalid type: 0> **********
    I (1527) esp_matter_attribute: ********** Endpoint 0x0001's Cluster 0x0005's Attribute 0x0000 is 0 **********
    I (1537) esp_matter_attribute: ********** Endpoint 0x0001's Cluster 0x0006's Attribute 0xFFFC is 1 **********
    I (1547) esp_matter_attribute: ********** Endpoint 0x0001's Cluster 0x0006's Attribute 0x4003 is 1 **********
    I (1557) esp_matter_attribute: ********** Endpoint 0x0001's Cluster 0x0006's Attribute 0x0000 is 1 **********
    I (1577) chip[ZCL]: On/Off set value: 1 1
    I (1577) esp_matter_attribute: ********** Endpoint 0x0001's Cluster 0x0006's Attribute 0x0000 is 1 **********
    I (1587) chip[ZCL]: On/off already set to new value
    I (1597) esp_matter_attribute: ********** Endpoint 0x0001's Cluster 0x0008's Attribute 0x0002 is 1 **********
    I (1607) esp_matter_attribute: ********** Endpoint 0x0001's Cluster 0x0008's Attribute 0x0003 is 254 **********
    I (1617) esp_matter_attribute: ********** Endpoint 0x0001's Cluster 0x0008's Attribute 0xFFFC is 3 **********
    I (1627) esp_matter_attribute: ********** Endpoint 0x0001's Cluster 0x0008's Attribute 0x0000 is 64 **********
    I (1637) esp_matter_attribute: ********** Endpoint 0x0001's Cluster 0x0008's Attribute 0x4000 is 64 **********
    I (1647) esp_matter_attribute: ********** Endpoint 0x0001's Cluster 0x0008's Attribute 0x0000 is 64 **********
    I (1657) led_driver_ws2812: led set r:0, g:0, b:0
    I (1667) esp_matter_attribute: ********** Endpoint 0x0001's Cluster 0x0300's Attribute 0x4010 is 250 **********
    I (1677) esp_matter_attribute: ********** Endpoint 0x0001's Cluster 0x0300's Attribute 0x0007 is 250 **********
    I (1687) esp_matter_attribute: ********** Endpoint 0x0001's Cluster 0x0300's Attribute 0x400B is 0 **********
    I (1697) esp_matter_attribute: ********** Endpoint 0x0001's Cluster 0x0300's Attribute 0x400C is 65279 **********
    I (1707) esp_matter_attribute: ********** Endpoint 0x0001's Cluster 0x0300's Attribute 0x0007 is 250 **********
    I (1717) led_driver_ws2812: led set r:0, g:0, b:0
    I (1727) esp_matter_attribute: ********** Endpoint 0x0001's Cluster 0x0300's Attribute 0x0008 is 2 **********
    I (1737) esp_matter_attribute: ********** Endpoint 0x0001's Cluster 0x0300's Attribute 0x4001 is 2 **********
    I (1747) esp_matter_core: Dynamic endpoint 1 added
    E (1747) chip[DL]: Long dispatch time: 396 ms, for event type 2
    I (1757) chip[DL]: WIFI_EVENT_STA_START
    I (1757) phy: chan:1,max_power:80
    I (1767) phy: chan:2,max_power:80
    I (1767) phy: chan:3,max_power:80
    I (1767) phy: chan:4,max_power:80
    I (1777) phy: chan:5,max_power:80
    I (1777) phy: chan:6,max_power:80
    I (1787) phy: chan:7,max_power:80
    I (1787) phy: chan:8,max_power:80
    I (1787) phy: chan:9,max_power:80
    I (1797) phy: chan:10,max_power:80
    I (1797) phy: chan:11,max_power:80
    I (1807) phy: chan:12,max_power:80
    I (1807) phy: chan:13,max_power:80
    I (1807) phy: chan:14,max_power:80
    W (1817) wifi:Haven't to connect to a suitable AP now!
    I (1817) chip[DL]: Done driving station state, nothing else to do...
    I (1827) chip[DL]: Configuring CHIPoBLE advertising (interval 25 ms, connectable, device name MATTER-2481)
    I (1837) chip[DL]: Device already advertising, stop active advertisement and restart
    I (1847) NimBLE: GAP procedure initiated: stop advertising.
    I (1857) NimBLE: GAP procedure initiated: advertise;
    I (1857) NimBLE: disc_mode=2
    I (1867) NimBLE: adv_channel_map=0 own_addr_type=1 adv_filter_policy=0 adv_itvl_min=40 adv_itvl_max=40
    I (1877) NimBLE:
    I (1877) app_main: Commissioning window opened
    I (1877) led_driver_ws2812: led set r:0, g:0, b:0
    I (1887) led_driver_ws2812: led set r:0, g:0, b:0
    I (1887) led_driver_ws2812: led set r:25, g:20, b:16
    I (31447) chip[DL]: Configuring CHIPoBLE advertising (interval 500 ms, connectable, device name MATTER-2481)
    I (31447) chip[DL]: Device alrea32mI (31457) NimBLE: GAP procedure initiated: stop advertising.
    I (31467) NimBLE: GAP procedure initiated: advertise;
    I (31467) NimBLE: disc_mode=2
    I (31467) NimBLE: adv_channel_map=0 own_addr_type=1 adv_filter_policy=0 adv_itvl_min=800 adv_itvl_max=800
    I (31477) NimBLE:

  3. run chip-tool cmd :./chip-tool pairing ble-wifi 1234 Redmi_huan 87654321 38802273 2481
@jonsmirl
Copy link
Contributor

Your device is failing to attach to your wifi router.

I (1807) phy: chan:14,max_power:80
W (1817) wifi:Haven't to connect to a suitable AP now!

@sidhoo2
Copy link
Author

sidhoo2 commented Oct 30, 2022

@jonsmirl yes, but chip-tool report the same error on a ubuntu meachine,here it is
image

@jonsmirl
Copy link
Contributor

I can not get chip pairing to work on my Ubuntu machine unless I add a second USB Bluetooth adapter and tell chip-tool to use it. This is because the Ubuntu Bluetooth code has control of the first adapter. Some people can get it working with just one, but I am unable to get it working solo.

BTW, the screen shot cuts off before any error is visible.

@dhrishi
Copy link
Collaborator

dhrishi commented Oct 31, 2022

@sidhoo-root Can you upload/attach the complete chip-tool logs. The screenshot does not seem to show the required errors

@sidhoo2
Copy link
Author

sidhoo2 commented Oct 31, 2022

@dhrishi ok. is this issue related to my desktop ubuntu meachine ?

logs:
efsz@lipeiquan-pcub:~/esp/esp-matter/connectedhomeip/connectedhomeip/chip_tool$ ./chip-tool pairing ble-wifi 1234 Redmi_huan 87654321 38802273 2481
[1667114262.217646][58592:58592] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs
[1667114262.217754][58592:58592] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini
[1667114262.217773][58592:58592] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini
[1667114262.217785][58592:58592] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini
[1667114262.217867][58592:58592] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-yS6iCG)
[1667114262.217946][58592:58592] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1667114262.217954][58592:58592] CHIP:DL: NVS set: chip-counters/reboot-count = 13 (0xD)
[1667114262.218155][58592:58592] CHIP:DL: Got Ethernet interface: enp3s0
[1667114262.218387][58592:58592] CHIP:DL: Found the primary Ethernet interface:enp3s0
[1667114262.218550][58592:58592] CHIP:DL: Failed to get WiFi interface
[1667114262.218553][58592:58592] CHIP:DL: Failed to reset WiFi statistic counts
[1667114262.218566][58592:58592] CHIP:IN: UDP::Init bind&listen port=0
[1667114262.218597][58592:58592] CHIP:IN: UDP::Init bound to port=44644
[1667114262.218599][58592:58592] CHIP:IN: UDP::Init bind&listen port=0
[1667114262.218608][58592:58592] CHIP:IN: UDP::Init bound to port=33567
[1667114262.218609][58592:58592] CHIP:IN: BLEBase::Init - setting/overriding transport
[1667114262.218610][58592:58592] CHIP:IN: TransportMgr initialized
[1667114262.218616][58592:58592] CHIP:FP: Initializing FabricTable from persistent storage
[1667114262.218623][58592:58592] CHIP:TS: Last Known Good Time: [unknown]
[1667114262.218625][58592:58592] CHIP:TS: Setting Last Known Good Time to firmware build time 2022-10-30T14:59:44
[1667114262.223003][58592:58592] CHIP:ZCL: Using ZAP configuration...
[1667114262.223290][58592:58592] CHIP:CTL: System State Initialized...
[1667114262.223300][58592:58592] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1667114262.223308][58592:58592] CHIP:CTL: Setting attestation nonce to random value
[1667114262.223337][58592:58592] CHIP:CTL: Setting CSR nonce to random value
[1667114262.223345][58592:58592] CHIP:IN: UDP::Init bind&listen port=5550
[1667114262.223352][58592:58592] CHIP:IN: UDP::Init bound to port=5550
[1667114262.223354][58592:58592] CHIP:IN: UDP::Init bind&listen port=5550
[1667114262.223361][58592:58592] CHIP:IN: UDP::Init bound to port=5550
[1667114262.223363][58592:58592] CHIP:IN: TransportMgr initialized
[1667114262.223445][58592:58597] CHIP:DL: CHIP task running
[1667114262.223555][58592:58597] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1667114262.223562][58592:58597] CHIP:CTL: Setting attestation nonce to random value
[1667114262.223570][58592:58597] CHIP:CTL: Setting CSR nonce to random value
[1667114262.223625][58592:58597] CHIP:CTL: Couldn't get ExampleOpCredsCAKey from storage: ../examples/chip-tool/config/PersistentStorage.cpp:85: CHIP Error 0x000000A0: Value not found in the persisted storage
[1667114262.224337][58592:58597] CHIP:CTL: Couldn't get ExampleOpCredsICAKey from storage: ../examples/chip-tool/config/PersistentStorage.cpp:85: CHIP Error 0x000000A0: Value not found in the persisted storage
[1667114262.224506][58592:58597] CHIP:CTL: Generating RCAC
[1667114262.224632][58592:58597] CHIP:CTL: Generating ICAC
[1667114262.224739][58592:58597] CHIP:CTL: Generating NOC
[1667114262.224861][58592:58597] CHIP:FP: Validating NOC chain
[1667114262.225162][58592:58597] CHIP:FP: NOC chain validation successful
[1667114262.225196][58592:58597] CHIP:FP: Added new fabric at index: 0x1
[1667114262.225199][58592:58597] CHIP:FP: Assigned compressed fabric ID: 0x8ED7A56E6C4F421C, node ID: 0x000000000001B669
[1667114262.225201][58592:58597] CHIP:TS: Last Known Good Time: 2022-10-30T14:59:44
[1667114262.225203][58592:58597] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00
[1667114262.225205][58592:58597] CHIP:TS: Retaining current Last Known Good Time
[1667114262.225328][58592:58597] CHIP:FP: Metadata for Fabric 0x1 persisted to storage.
[1667114262.225536][58592:58597] CHIP:TS: Committing Last Known Good Time to storage: 2022-10-30T14:59:44
[1667114262.225725][58592:58597] CHIP:CTL: Joined the fabric at index 1. Compressed fabric ID is: 0x0000000000000000
[1667114262.225755][58592:58597] CHIP:IN: UDP::Init bind&listen port=5550
[1667114262.225763][58592:58597] CHIP:IN: UDP::Init bound to port=5550
[1667114262.225764][58592:58597] CHIP:IN: UDP::Init bind&listen port=5550
[1667114262.225769][58592:58597] CHIP:IN: UDP::Init bound to port=5550
[1667114262.225770][58592:58597] CHIP:IN: TransportMgr initialized
[1667114262.227663][58592:58597] CHIP:IN: SecureSession[0x7fdcac01dbb0]: Allocated Type:1 LSID:53257
[1667114262.227670][58592:58597] CHIP:SC: Assigned local session key ID 53257
[1667114262.227679][58592:58597] CHIP:SC: Including MRP parameters in PBKDF param request
[1667114262.227705][58592:58597] CHIP:EM: <<< [E:41872i M:237146974] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:20 (SecureChannel:PBKDFParamRequest)
[1667114262.227711][58592:58597] CHIP:IN: (U) Sending msg 237146974 to IP address 'BLE'
[1667114262.227714][58592:58597] CHIP:IN: Message appended to BLE send queue
[1667114262.227717][58592:58597] CHIP:SC: Sent PBKDF param request
[1667114262.227720][58592:58597] CHIP:CTL: Setting wifi credentials from parameters
[1667114262.227722][58592:58597] CHIP:CTL: Setting attestation nonce to random value
[1667114262.227725][58592:58597] CHIP:CTL: Setting CSR nonce to random value
[1667114262.227728][58592:58597] CHIP:CTL: Commission called for node ID 0x00000000000004D2
[1667114262.227776][58592:58595] CHIP:DL: TRACE: Bus acquired for name C-e4e0
[1667114262.227789][58592:58598] CHIP:DL: TRACE: Bluez mainloop starting Thread
[1667114287.233432][58592:58595] CHIP:DL: FAIL: Error getting object manager client: Error calling StartServiceByName for org.bluez: Timeout was reached
[1667114287.233539][58592:58597] CHIP:DL: PlatformBlueZInit init success
[1667114287.233575][58592:58597] CHIP:IN: Clearing BLE pending packets.
[1667114287.233598][58592:58597] CHIP:IN: BleConnection Error: ../examples/chip-tool/third_party/connectedhomeip/src/platform/Linux/BLEManagerImpl.cpp:655: CHIP Error 0x00000003: Incorrect state
[1667114287.233610][58592:58597] CHIP:BLE: No adapter available for new connection establishment
[1667114287.233625][58592:58597] CHIP:DL: Long dispatch time: 25006 ms, for event type 2
[1667114292.232020][58592:58597] CHIP:SC: PASESession timed out while waiting for a response from the peer. Expected message type was 33
[1667114292.232067][58592:58597] CHIP:IN: SecureSession[0x7fdcac01dbb0]: Released - Type:1 LSID:53257
[1667114292.232082][58592:58597] CHIP:TOO: Secure Pairing Failed
[1667114292.232109][58592:58597] CHIP:DIS: Closing all BLE connections
[1667114292.232139][58592:58597] CHIP:TOO: Pairing Failure: ../examples/chip-tool/third_party/connectedhomeip/src/protocols/secure_channel/PASESession.cpp:245: CHIP Error 0x00000032: Timeout
[1667114292.232359][58592:58592] CHIP:CTL: Shutting down the commissioner
[1667114292.232391][58592:58592] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1667114292.232459][58592:58592] CHIP:CTL: Shutting down the controller
[1667114292.232476][58592:58592] CHIP:IN: Expiring all sessions for fabric 0x1!!
[1667114292.232487][58592:58592] CHIP:FP: Forgetting fabric 0x1
[1667114292.232506][58592:58592] CHIP:TS: Pending Last Known Good Time: 2022-10-30T14:59:44
[1667114292.232628][58592:58592] CHIP:TS: Previous Last Known Good Time: 2022-10-30T14:59:44
[1667114292.232641][58592:58592] CHIP:TS: Reverted Last Known Good Time to previous value
[1667114292.232678][58592:58592] CHIP:CTL: Shutting down the commissioner
[1667114292.232688][58592:58592] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1667114292.232738][58592:58592] CHIP:CTL: Shutting down the controller
[1667114292.232749][58592:58592] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack
[1667114292.232804][58592:58592] CHIP:DMG: IM WH moving to [Uninitialized]
[1667114292.232815][58592:58592] CHIP:DMG: IM WH moving to [Uninitialized]
[1667114292.232820][58592:58592] CHIP:DMG: IM WH moving to [Uninitialized]
[1667114292.232825][58592:58592] CHIP:DMG: IM WH moving to [Uninitialized]
[1667114292.232833][58592:58592] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet
[1667114292.232864][58592:58592] CHIP:BLE: BleConnectionDelegate::CancelConnection is not implemented.
[1667114292.233064][58592:58592] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-YOtN5D)
[1667114292.233374][58592:58592] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1667114292.233410][58592:58592] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0)
[1667114292.233423][58592:58592] CHIP:DL: Inet Layer shutdown
[1667114292.233433][58592:58592] CHIP:DL: BLE shutdown
[1667114292.233444][58592:58592] CHIP:DL: System Layer shutdown
[1667114292.233482][58592:58592] CHIP:TOO: Run command failure: ../examples/chip-tool/third_party/connectedhomeip/src/protocols/secure_channel/PASESession.cpp:245: CHIP Error 0x00000032: Timeout

@sidhoo2 sidhoo2 changed the title chip-tool pairing failed chip-tool pairing ble-wifi failed Oct 31, 2022
@dhrishi
Copy link
Collaborator

dhrishi commented Oct 31, 2022

@sidhoo-root Yes, it looks like the issue related to BLE on your host machine. See the below in your logs:

[1667114287.233598][58592:58597] CHIP:IN: BleConnection Error: ../examples/chip-tool/third_party/connectedhomeip/src/platform/Linux/BLEManagerImpl.cpp:655: CHIP Error 0x00000003: Incorrect state
[1667114287.233610][58592:58597] CHIP:BLE: No adapter available for new connection establishment

@sidhoo2
Copy link
Author

sidhoo2 commented Nov 1, 2022

@dhrishi Thanks , i am trying to pair the device with another laptop computer

@jonsmirl
Copy link
Contributor

jonsmirl commented Nov 1, 2022

I just stick a $2 USB Bluetooth adapter into the computer and then use '--ble-adapter 1' on chip-tool.

This is kind of hit or miss. Some of my computers work ok without the extra adapter, some need it. This is not anything to do with Matter, I think it is a function of the Bluetooth hardware in the computers. Some computers have very minimal BT hardware which is not capable of being shared.

@sidhoo2
Copy link
Author

sidhoo2 commented Nov 3, 2022

@jonsmirl @dhrishi thank you . it works within the laptop computer, the device can be pairing now. but it comes anther problem, the device can not be control by chiptool. i will open another issue to push the log

@sidhoo2 sidhoo2 closed this as completed Nov 3, 2022
@kurisaW kurisaW mentioned this issue May 6, 2023
Closed
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
3 participants
@jonsmirl @dhrishi @sidhoo2