unable to pair iOS device with M5 ESP32

[plauric]

Problem

I'm running the all-clusters-app/esp32 example on a M5. The BLE pairing with the iOS device fails with this message:

"E (75968) chip[BLE]: HandleChipConnectionReceived failed, err = 417

iOS version: 15.3.1
Matter repo: 83aac59
esp-idf: v5.0-dev (I also tried v4.4 and v4.3 and had the same issue)

Thank you for any suggestion.

---

I (97) boot: 4 ota_1 OTA app �ets Jul 29 2019 12:21:46

rst:0x1 (POWERON_RESET),boot:0x17 (SPI_FAST_FLASH_BOOT)
configsip: 0, SPIWP:0xee
clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
mode:DIO, clock div:2
load:0x3fff0030,len:6708
load:0x40078000,len:14812
load:0x40080400,len:3792
0x40080400: _init at ??:?

entry 0x40080694
I (27) boot: ESP-IDF v5.0-dev 2nd stage bootloader
I (27) boot: compile time 11:36:10
I (27) boot: chip revision: 3
I (30) boot_comm: chip revision: 3, min. bootloader chip revision: 0
I (37) boot.esp32: SPI Speed : 40MHz
I (42) boot.esp32: SPI Mode : DIO
I (47) boot.esp32: SPI Flash Size : 4MB
I (51) boot: Enabling RNG early entropy source...
I (57) boot: Partition Table:
I (60) boot: ## Label Usage Type ST Offset Length
I (67) boot: 0 nvs WiFi data 01 02 00009000 00006000
I (75) boot: 1 otadata OTA data 01 00 0000f000 00002000
I (82) boot: 2 phy_init RF data 01 01 0001100 00001000
I (90) boot: 3 ota_0 OTA app 00 10 00020000 00177000
I (97) boot: 4 ota_1 OTA app 00 11 001a0000 00177000
I (105) boot: 5 ot_storage Unknown data 01 3a 00317000 00002000
I (112) boot: End of partition table
I (117) boot: No factory image, trying OTA 0
I (121) boot_comm: chip revision: 3, min. application chip revision: 0
I (129) esp_image: segment 0: paddr=00020020 vaddr=3f400020 size=30e60h (200288) map
I (210) esp_image: segment 1: paddr=00050e88 vaddr=3ffbdb60 size=08508h ( 34056) load
I (223) esp_image: segment 2: paddr=00059398 vaddr=40080000 size=06c80h ( 27776) load
I (235) esp_image: segment 3: paddr=00060020 vaddr=400d0020 size=e2bd0h (928720) map
I (571) esp_image: segment 4: paddr=00142bf8 vaddr=40086c80 size=177c4h ( 96196) load
I (611) esp_image: segment 5: paddr=0015a3c4 vaddr=50000000 size=00010h ( 16) load
I (627) boot: Loaded app from partition at offset 0x20000
I (672) boot: Set actual ota_seq=1 in otadata[0]
I (672) boot: Disabling RNG early entropy source...
I (683) cpu_start: Pro cpu up.
I (684) cpu_start: Starting app cpu, entry point is 0x400814bc
0x400814bc: call_start_cpu1 at /home/petru/tools/esp-idf/components/esp_system/port/cpu_start.c:156

I (0) cpu_start: App cpu up.
I (699) cpu_start: Pro cpu start user code
I (700) cpu_start: cpu freq: 160000000
I (700) cpu_start: Application information:
I (704) cpu_start: Project name: chip-all-clusters-app
I (710) cpu_start: App version: test_event_4_2021_07_06-1968-g8
I (717) cpu_start: Compile time: Feb 24 2022 17:25:56
I (723) cpu_start: ELF file SHA256: 630f05ab87f3c167...
I (729) cpu_start: ESP-IDF: v5.0-dev
I (735) heap_init: Initializing. RAM available for dynamic allocation:
I (742) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM
I (748) heap_init: At 3FFB6388 len 00001C78 (7 KiB): DRAM
I (754) heap_init: At 3FFB9A20 len 00004108 (16 KiB): DRAM
I (760) heap_init: At 3FFD7728 len 000088D8 (34 KiB): DRAM
I (766) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (772) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (779) heap_init: At 4009E444 len 00001BBC (6 KiB): IRAM
I (786) spi_flash: detected chip: generic
I (790) spi_flash: flash io: dio
W (794) spi_flash: Detected size(16384k) larger than the size in the binary image header(4096k). Using the size in the binary image header.
I (810) cpu_start: Starting scheduler on PRO CPU.
I (0) cpu_start: Starting scheduler on APP CPU.
I (818) all-clusters-app: All Clusters Demo!
I (828) all-clusters-app: This is ESP32 chip with 2 CPU cores, WiFi/BT/BLE,
I (828) all-clusters-app: silicon revision 3,
I (838) all-clusters-app: 4MB external flash

I (898) wifi:wifi driver task: 3ffde4d4, prio:23, stack:6656, core=0
I (898) system_api: Base MAC address is not set
I (898) system_api: read default base MAC address from EFUSE
I (928) wifi:wifi firmware version: f84e709
I (928) wifi:wifi certification version: v7.0
I (928) wifi:config NVS flash: enabled
I (928) wifi:config nano formating: disabled
I (938) wifi:Init data frame dynamic rx buffer num: 32
I (938) wifi:Init management frame dynamic rx buffer num: 32
I (938) wifi:Init management short buffer num: 32
I (948) wifi:Init dynamic tx buffer num: 32
I (948) wifi:Init static rx buffer size: 1600
I (958) wifi:Init static rx buffer num: 10
I (968) wifi:Init dynamic rx buffer num: 32
I (968) wifi_init: rx ba win: 6
I (968) wifi_init: tcpip mbox: 32
I (978) wifi_init: udp mbox: 6
I (978) wifi_init: tcp mbox: 6
I (988) wifi_init: tcp tx win: 5744
I (988) wifi_init: tcp rx win: 5744
I (988) wifi_init: tcp mss: 1440
I (998) wifi_init: WiFi IRAM OP enabled
I (998) wifi_init: WiFi RX IRAM OP enabled
I (1008) chip[DL]: NVS set: chip-counters/reboot-count = 18 (0x12)
I (1008) chip[SVR]: SetupQRCode: [MT:UHFC7VSC00KA0648G00]
I (1008) chip[SVR]: Copy/paste the below URL in a browser to see the QR Code:
https://dhrishi.github.io/connectedhomeip/qrcode.html?data=MT%3AUHFC7VSC00KA0648G00
I (1008) BTDM_INIT: BT controller compile version [078d492]
I (1038) phy_init: phy_version 4670,719f9f6,Feb 18 2021,17:07:07
I (1038) chip[SVR]: Manual pairing code: [34970112332]

I (1438) CHIP[DL]: BLE host-controller synced
I (1938) chip[DL]: Configuring CHIPoBLE advertising (interval 25 ms, connectable, device name MATTER-3840)
I (1938) NimBLE: GAP procedure initiated: advertise;
I (1948) NimBLE: disc_mode=2
I (1948) NimBLE: adv_channel_map=0 own_addr_type=2 adv_filter_policy=0 adv_itvl_min=40 adv_itvl_max=40
I (1968) NimBLE:

I (1968) chip[DL]: CHIPoBLE advertising started
E (1968) chip[DL]: Long dispatch time: 960 ms, for event type 2
I (1978) chip[DL]: Starting ESP WiFi layer
I (1988) wifi:mode : sta (30:c6:f7:15:45:d0)
I (1988) wifi:enable tsf
W (1988) wifi:Haven't to connect to a suitable AP now!
I (1988) chip[DL]: Done driving station state, nothing else to do...
W (2008) wifi:Haven't to connect to a suitable AP now!
I (2008) chip[DL]: Done driving station state, nothing else to do...
I (2018) chip[ZCL]: Using ZAP configuration...
I (2028) chip[ZCL]: Initiating Admin Commissioning cluster.
I (2028) chip[ZCL]: OpCreds: Initiating OpCreds cluster by writing fabrics list from fabric table.
I (2038) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0003', EndPoint ID: '0x00', Attribute ID: '0x0001'
I (2058) app-devicecallbacks: Unhandled cluster ID: 3
I (2058) app-devicecallbacks: Current free heap: 75452

I (2068) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0004', EndPoint ID: '0x00', Attribute ID: '0x0000'
I (2078) app-devicecallbacks: Unhandled cluster ID: 4
I (2078) app-devicecallbacks: Current free heap: 75452

I (2088) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0028', EndPoint ID: '0x00', Attribute ID: '0x0001'
I (2098) app-devicecallbacks: Unhandled cluster ID: 40
I (2108) app-devicecallbacks: Current free heap: 75452

I (2108) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0028', EndPoint ID: '0x00', Attribute ID: '0x0002'
I (2118) app-devicecallbacks: Unhandled cluster ID: 40
I (2128) app-devicecallbacks: Current free heap: 75452

I (2128) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0028', EndPoint ID: '0x00', Attribute ID: '0x0003'
I (2138) app-devicecallbacks: Unhandled cluster ID: 40
I (2158) app-devicecallbacks: Current free heap: 75452

I (2158) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0028', EndPoint ID: '0x00', Attribute ID: '0x0004'
I (2168) app-devicecallbacks: Unhandled cluster ID: 40
I (2178) app-devicecallbacks: Current free heap: 75452

I (2178) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0028', EndPoint ID: '0x00', Attribute ID: '0x0008'
I (2188) app-devicecallbacks: Unhandled cluster ID: 40
I (2198) app-devicecallbacks: Current free heap: 75452

I (2208) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0028', EndPoint ID: '0x00', Attribute ID: '0x0007'
I (2218) app-devicecallbacks: Unhandled cluster ID: 40
I (2228) app-devicecallbacks: Current free heap: 75452

I (2228) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0028', EndPoint ID: '0x00', Attribute ID: '0x000a'
I (2238) app-devicecallbacks: Unhandled cluster ID: 40
I (2238) app-devicecallbacks: Current free heap: 75452

I (2248) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0028', EndPoint ID: '0x00', Attribute ID: '0x0009'
I (2268) app-devicecallbacks: Unhandled cluster ID: 40
I (2268) app-devicecallbacks: Current free heap: 74972

I (2278) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0028', EndPoint ID: '0x00', Attribute ID: '0x000f'
I (2288) app-devicecallbacks: Unhandled cluster ID: 40
I (2288) app-devicecallbacks: Current free heap: 74972

I (2298) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0003', EndPoint ID: '0x01', Attribute ID: '0x0001'
I (2318) app-devicecallbacks: Unhandled cluster ID: 3
I (2318) app-devicecallbacks: Current free heap: 74972

I (2328) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0004', EndPoint ID: '0x01', Attribute ID: '0x0000'
I (2338) app-devicecallbacks: Unhandled cluster ID: 4
I (2338) app-devicecallbacks: Current free heap: 74972

I (2348) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0005', EndPoint ID: '0x01', Attribute ID: '0x0000'
I (2368) app-devicecallbacks: Unhandled cluster ID: 5
I (2368) app-devicecallbacks: Current free heap: 76892

I (2378) chip[ZCL]: Window Covering Cluster init
I (2378) chip[ZCL]: Initialize PCC Server Cluster [EP:1]
I (2378) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0300', EndPoint ID: '0x01', Attribute ID: '0x0007'
I (2388) app-devicecallbacks: Unhandled cluster ID: 768
I (2398) app-devicecallbacks: Current free heap: 76892

I (2398) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0300', EndPoint ID: '0x01', Attribute ID: '0x0008'
I (2418) app-devicecallbacks: Unhandled cluster ID: 768
I (2428) app-devicecallbacks: Current free heap: 76892

I (2428) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0300', EndPoint ID: '0x01', Attribute ID: '0x4001'
I (2438) app-devicecallbacks: Unhandled cluster ID: 768
I (2448) app-devicecallbacks: Current free heap: 76892

I (2448) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0406', EndPoint ID: '0x01', Attribute ID: '0x0001'
I (2468) app-devicecallbacks: Unhandled cluster ID: 1030
I (2478) app-devicecallbacks: Current free heap: 76892

I (2478) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0406', EndPoint ID: '0x01', Attribute ID: '0x0002'
I (2488) app-devicecallbacks: Unhandled cluster ID: 1030
I (2498) app-devicecallbacks: Current free heap: 76892

I (2498) chip[ZCL]: WARNING: ATTRIBUTES ARE NOT BEING STORED IN FLASH!
I (2508) chip[ZCL]: DEVICE WILL NOT FUNCTION PROPERLY AFTER REBOOTING!!
I (2518) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0500', EndPoint ID: '0x01', Attribute ID: '0x0001'
I (2528) app-devicecallbacks: Unhandled cluster ID: 1280
I (2538) app-devicecallbacks: Current free heap: 76892

I (2538) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0500', EndPoint ID: '0x01', Attribute ID: '0x0002'
I (2548) app-devicecallbacks: Unhandled cluster ID: 1280
I (2558) app-devicecallbacks: Current free heap: 76892

I (2568) chip[ZCL]: Failed to send IAS Zone update. Err 0x70
I (2578) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0004', EndPoint ID: '0x02', Attribute ID: '0x0000'
I (2588) app-devicecallbacks: Unhandled cluster ID: 4
I (2588) app-devicecallbacks: Current free heap: 76892

I (2588) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0406', EndPoint ID: '0x02', Attribute ID: '0x0001'
I (2598) app-devicecallbacks: Unhandled cluster ID: 1030
I (2608) app-devicecallbacks: Current free heap: 76892

I (2618) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0406', EndPoint ID: '0x02', Attribute ID: '0x0002'
I (2628) app-devicecallbacks: Unhandled cluster ID: 1030
I (2638) app-devicecallbacks: Current free heap: 76892

I (2348) all-clusters-app: Display initialized (height 240, width 320)
I (2648) all-clusters-app: Display awake but will switch off automatically in 30 seconds
I (2658) chip[DL]: NVS set: chip-counters/GlobalMCTR = 18000 (0x4650)
I (2688) chip[DL]: NVS set: chip-counters/debug-eidc = 786432 (0xC0000)
I (2688) chip[DL]: NVS set: chip-counters/info-eidc = 786432 (0xC0000)
I (2688) chip[DL]: NVS set: chip-counters/crit-eidc = 786432 (0xC0000)
I (2848) chip[DIS]: CHIP minimal mDNS started advertising.
I (2848) chip[DIS]: Failed to find a valid admin pairing. Node ID unknown
I (2858) chip[DIS]: Start dns-sd server - no current nodeId
I (2858) chip[DIS]: Advertise commission parameter vendorID=9050 productID=65277 discriminator=3840/15
I (2878) chip[DIS]: CHIP minimal mDNS configured as 'Commissionable node device'.
I (2878) chip[IN]: CASE Server enabling CASE session setups
I (2888) chip[SVR]: Server Listening...
I (2888) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0402', EndPoint ID: '0x01', Attribute ID: '0x0000'
I (2908) app-devicecallbacks: Unhandled cluster ID: 1026
I (2908) app-devicecallbacks: Current free heap: 73980

I (2918) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0101', EndPoint ID: '0x01', Attribute ID: '0x0000'
I (2928) app-devicecallbacks: Unhandled cluster ID: 257
I (2928) app-devicecallbacks: Current free heap: 72800

I (2948) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0008', EndPoint ID: '0x01', Attribute ID: '0x0000'
I (2938) all-clusters-app: Display awake but will switch off automatically in 30 seconds
I (2958) app-devicecallbacks: Current free heap: 73012

I (2968) chip[ZCL]: 0x3f408331ep 2 clus 0x0000_0008 attr 0x0000_0000 not supported
E (2968) chip[DL]: Long dispatch time: 950 ms, for event type 2
I (2978) app-devicecallbacks: Current free heap: 73012

I (2988) chip[DL]: WIFI_EVENT_STA_START
W (2998) wifi:Haven't to connect to a suitable AP now!
I (2998) chip[DL]: Done driving station state, nothing else to do...
I (2998) app-devicecallbacks: Current free heap: 73012

I (3008) chip[DL]: Configuring CHIPoBLE advertising (interval 25 ms, connectable, device name MATTER-3840)
I (3018) chip[DL]: Device already advertising, stop active advertisement and restart
I (3028) NimBLE: GAP procedure initiated: stop advertising.

I (3038) NimBLE: GAP procedure initiated: advertise;
I (3038) NimBLE: disc_mode=2
I (3038) NimBLE: adv_channel_map=0 own_addr_type=2 adv_filter_policy=0 adv_itvl_min=40 adv_itvl_max=40
I (3058) NimBLE:

I (6358) all-clusters-app: Display awake but will switch off automatically in 30 seconds
I (6548) all-clusters-app: Display awake but will switch off automatically in 30 seconds
I (7048) all-clusters-app: Display awake but will switch off automatically in 30 seconds
I (7238) all-clusters-app: Display awake but will switch off automatically in 30 seconds
I (7838) all-clusters-app: Display awake but will switch off automatically in 30 seconds
I (7838) all-clusters-app: Opening QR code screen
I (7848) all-clusters-app: QR CODE Text: 'MT:UHFC7VSC00KA0648G00'
I (7848) all-clusters-app: Setup discriminator: 3840 (0xf00)
I (7858) all-clusters-app: Setup PIN code: 20202021 (0x1344225)
I (8138) all-clusters-app: Display awake but will switch off automatically in 30 seconds
I (32848) chip[DL]: Configuring CHIPoBLE advertising (interval 500 ms, connectable, device name MATTER-3840)
I (32848) chip[DL]: Device already advertising, stop active advertisement and restart
I (32858) NimBLE: GAP procedure initiated: stop advertising.

I (32878) NimBLE: GAP procedure initiated: advertise;
I (32878) NimBLE: disc_mode=2
I (32878) NimBLE: adv_channel_map=0 own_addr_type=2 adv_filter_policy=0 adv_itvl_min=800 adv_itvl_max=800
I (32888) NimBLE:

I (38138) all-clusters-app: Display going to sleep...

I (67738) all-clusters-app: Display awake but will switch off automatically in 30 seconds
I (67938) all-clusters-app: Display awake but will switch off automatically in 30 seconds
I (75298) chip[DL]: BLE GAP connection established (con 0)
I (75298) chip[DL]: CHIPoBLE advertising stopped
I (75308) app-devicecallbacks: Current free heap: 72820

I (75948) CHIP[DL]: Write request received for CHIPoBLE RX characteristic con 0 12
I (75948) chip[BLE]: Releasing end point's BLE connection back to application.
E (75968) chip[BLE]: HandleChipConnectionReceived failed, err = 417
E (75968) chip[BLE]: failed handle new chip BLE connection, status = 417
I (76128) chip[DL]: Write request/command received for CHIPoBLE TX CCCD characteristic (con 0 ) indicate = 0 notify = 1
I (76128) chip[DL]: CHIPoBLE subscribe received
E (76128) chip[BLE]: no endpoint for sub recvd
I (76148) app-devicecallbacks: CHIPoBLE connection established
I (76158) app-devicecallbacks: Current free heap: 72820

I (90948) chip[DL]: Write request/command received for CHIPoBLE TX CCCD characteristic (con 0 ) indicate = 0 notify = 0
I (90948) chip[DL]: CHIPoBLE unsubscribe received
E (90948) chip[BLE]: no endpoint for unsub recvd
I (90968) chip[DL]: Configuring CHIPoBLE advertising (interval 25 ms, connectable, device name MATTER-3840)
I (90978) NimBLE: GAP procedure initiated: advertise;
I (90978) NimBLE: disc_mode=2
I (90978) NimBLE: adv_channel_map=0 own_addr_type=2 adv_filter_policy=0 adv_itvl_min=40 adv_itvl_max=40
I (90988) NimBLE:

I (90998) chip[DL]: CHIPoBLE advertising started
I (91008) app-devicecallbacks: Current free heap: 72820

I (91038) chip[DL]: BLE GAP connection terminated (con 0 reason 0x13)
I (91038) app-devicecallbacks: CHIPoBLE disconnected
I (91048) app-devicecallbacks: Current free heap: 72820

I (91058) chip[DL]: Configuring CHIPoBLE advertising (interval 25 ms, connectable, device name MATTER-3840)
I (91068) chip[DL]: Device already advertising, stop active advertisement and restart
I (91068) NimBLE: GAP procedure initiated: stop advertising.

I (91088) NimBLE: GAP procedure initiated: advertise;
I (91088) NimBLE: disc_mode=2
I (91088) NimBLE: adv_channel_map=0 own_addr_type=2 adv_filter_policy=0 adv_itvl_min=40 adv_itvl_max=40
I (91098) NimBLE:

I (97938) all-clusters-app: Display going to sleep...

Proposed Solution

<suggested fix, suggested enhancement>

[dhrishi]

Hi @plauric Can you please check if #15299 is related, specifically: #15299 (comment)

[plauric]

@dhrishi Thank you very much! That was it - the iOS device must run 15.4 developer beta.