search

project-chip / connectedhomeip

Matter (formerly Project CHIP) creates more connections between more objects, simplifying development for manufacturers and increasing compatibility for consumers, guided by the Connectivity Standards Alliance.
https://buildwithmatter.com
Apache License 2.0
7.48k stars 2.01k forks source link

Commissioning over BLE fails on iOS 15.3 and macOS 12.2.1 #15146

Closed dtodor closed 2 years ago

dtodor commented 2 years ago

Commissioning over BLE doesn't seem to work with the current code base. I've tested the following setups:

Controllers

Devices

Here is the output of the iOS app:

2022-02-14 15:14:30.270653+0100 CHIPTool[12159:4753617] CHIPOperationalCredentialsDelegate: No NOC Signer provided, using self managed keys
2022-02-14 15:14:30.276743+0100 CHIPTool[12159:4753617] Found an existing self managed keypair in the keychain
2022-02-14 15:14:30.276817+0100 CHIPTool[12159:4753617] Deserializing the key
2022-02-14 15:14:30.277120+0100 CHIPTool[12159:4753617] CHIPOperationalCredentialsDelegate::init returning ../../../../../../../../../../../Downloads/connectedhomeip.git/src/crypto/CHIPCryptoPALmbedTLS.cpp:761: Success
2022-02-14 15:14:30.277175+0100 CHIPTool[12159:4753617] PersistentStorageDelegate Sync Get Value for Key: com.zigbee.chip.commissioner.device_id
2022-02-14 15:14:30.277288+0100 CHIPTool[12159:4753617] CHIPPersistentStorageDelegate Get Value for Key: com.zigbee.chip.commissioner.device_id, value MZ0Y2ldcHyc=
2022-02-14 15:14:30.277332+0100 CHIPTool[12159:4753617] Found 271f5c57da189d31 node ID for the controller
2022-02-14 15:14:30.294783+0100 CHIPTool[12159:4753617] PersistentStorageDelegate Sync Get Value for Key: MatterCARootCert0
2022-02-14 15:14:30.294891+0100 CHIPTool[12159:4753617] CHIPPersistentStorageDelegate Get Value for Key: MatterCARootCert0, value MIIB2jCCAYCgAwIBAgIBADAKBggqhkjOPQQDAjBEMSAwHgYKKwYBBAGConwBBAwQMDAwMDAwMDAwMDAwMDREMjEgMB4GCisGAQQBgqJ8AQUMEDAwMDAwMDAwMDAwMDAwMDAwHhcNMjIwMjE0MTUxMjA0WhcNMjMwMjE0MTUxMjA0WjBEMSAwHgYKKwYBBAGConwBBAwQMDAwMDAwMDAwMDAwMDREMjEgMB4GCisGAQQBgqJ8AQUMEDAwMDAwMDAwMDAwMDAwMDAwWTATBgcqhkjOPQIBBggqhkjOPQMBBwNCAARkLVBBkyfWjyfeaSHkpxiMHmOY/DF8bqfBVflJnPQgfk+IXDFXwFB/KSIbTFAxLMDoOgHqKmu1gsw3tEaJLEM9o2MwYTAPBgNVHRMBAf8EBTADAQH/MA4GA1UdDwEB/wQEAwIBBjAdBgNVHQ4EFgQUYOEPuKIBPDjFonjgWRDqowCyMKIwHwYDVR0jBBgwFoAUYOEPuKIBPDjFonjgWRDqowCyMKIwCgYIKoZIzj0EAwIDSAAwRQIgR75fUq30PfbeefJOpn9XZzvfW4wAupJGbAFCuBPAk4ECIQC9XqRS0259UN04c8si+ukV7AaEjnhldLRyRo2nj4A8Mw==
2022-02-14 15:14:30.295363+0100 CHIPTool[12159:4753617] [all] šŸ”µ [1644848070295] [12159:4753617] CHIP: [DL] Found user documents directory: file:///var/mobile/Containers/Data/Application/F79BEE14-BE33-4459-BCDB-E7ED986049EC/Documents/
2022-02-14 15:14:30.295419+0100 CHIPTool[12159:4753617] [all] šŸ”µ [1644848070295] [12159:4753617] CHIP: [DL] KVS will be written to: file:///var/mobile/Containers/Data/Application/F79BEE14-BE33-4459-BCDB-E7ED986049EC/Documents/chip.store
2022-02-14 15:14:30.302327+0100 CHIPTool[12159:4753617] [all] šŸŸ¢ [1644848070302] [12159:4753617] CHIP: [DL] _Init
2022-02-14 15:14:30.302421+0100 CHIPTool[12159:4753617] [all] šŸŸ¢ [1644848070302] [12159:4753617] CHIP: [IN] UDP::Init bind&listen port=0
2022-02-14 15:14:30.302543+0100 CHIPTool[12159:4753617] [all] šŸŸ¢ [1644848070302] [12159:4753617] CHIP: [IN] UDP::Init bound to port=59058
2022-02-14 15:14:30.302570+0100 CHIPTool[12159:4753617] [all] šŸŸ¢ [1644848070302] [12159:4753617] CHIP: [IN] UDP::Init bind&listen port=0
2022-02-14 15:14:30.302626+0100 CHIPTool[12159:4753617] [all] šŸŸ¢ [1644848070302] [12159:4753617] CHIP: [IN] UDP::Init bound to port=52379
2022-02-14 15:14:30.302693+0100 CHIPTool[12159:4753617] [all] šŸŸ¢ [1644848070302] [12159:4753617] CHIP: [IN] TransportMgr initialized
2022-02-14 15:14:30.302744+0100 CHIPTool[12159:4753617] [all] šŸŸ¢ [1644848070302] [12159:4753617] CHIP: [DIS] Init fabric pairing table with server storage
2022-02-14 15:14:30.302796+0100 CHIPTool[12159:4753617] PersistentStorageDelegate Sync Get Value for Key: F01/Fabric1
2022-02-14 15:14:30.302838+0100 CHIPTool[12159:4753617] CHIPPersistentStorageDelegate Get Value for Key: F01/Fabric1, value AQAAAAAAAAAxnRjaV1wfJwAAAAAAAAAAAADvAAAA/AAECqLHqK9ufybRQxZNhOndYSxDWXzXexzTCKxD7gZM/1y4pdw01tltQ/ir8KfAP1Gv1666iAeNFuGv+5zOSRUX7srVu+JLQTQIrQuQAhU/y47m3ireZGO/bMlmcniabrunAAAAAAAAAGEAAAAAAAAAFTABAQAkAgE3AyUU0gQkFQAYJgTELZ0pJgVEYX4rNwYlFNIEJBUAGCQHASQIATAJQQRkLVBBkyfWjyfeaSHkpxiMHmOY/DF8bqfBVflJnPQgfk+IXDFXwFB/KSIbTFAxLMDoOgHqKmu1gsw3tEaJLEM9Nwo1ASkBGCQCYDAEFGDhD7iiATw4xaJ44FkQ6qMAsjCiMAUUYOEPuKIBPDjFonjgWRDqowCyMKIYMAtAR75fUq30PfbeefJOpn9XZzvfW4wAupJGbAFCuBPAk4G9XqRS0259UN04c8si+ukV7AaEjnhldLRyRo2nj4A8MxgAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAVMAEBASQCATcDJRTSBCQVABgmBMQtnSkmBURhfis3BiQVACcRMZ0Y2ldcHycYJAcBJAgBMAlBBAqix6ivbn8m0UMWTYTp3WEsQ1l813sc0wisQ+4GTP9cuKXcNNbZbUP4q/CnwD9Rr9euuogHjRbhr/uczkkVF+43CjUBKAEYJAIBNgMEAgQBGDAEFKMKhVx3hHDwFA0hRdYd4to13+EsMAUUYOEPuKIBPDjFonjgWRDqowCyMKIYMAtANIk0uBaAPpyGx1/OzsXRO+Ag/GDQ/yzfftC8/K0qtEDuj03Be1gomR7j95supkcXNQN0YFWidw1tcQKc99UX/BgAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA==
2022-02-14 15:14:30.303135+0100 CHIPTool[12159:4753617] [all] šŸ”µ [1644848070303] [12159:4753617] CHIP: [IN] Loading certs from storage
2022-02-14 15:14:30.303260+0100 CHIPTool[12159:4753617] [all] šŸŸ¢ [1644848070303] [12159:4753617] CHIP: [IN] Generating compressed fabric ID using uncompressed fabric ID 0x0000000000000000 and root pubkey
2022-02-14 15:14:30.303285+0100 CHIPTool[12159:4753617] [all] šŸŸ¢ [1644848070303] [12159:4753617] CHIP: [IN] 0x04, 0x64, 0x2d, 0x50, 0x41, 0x93, 0x27, 0xd6,
2022-02-14 15:14:30.303343+0100 CHIPTool[12159:4753617] [all] šŸŸ¢ [1644848070303] [12159:4753617] CHIP: [IN] 0x8f, 0x27, 0xde, 0x69, 0x21, 0xe4, 0xa7, 0x18,
2022-02-14 15:14:30.303364+0100 CHIPTool[12159:4753617] [all] šŸŸ¢ [1644848070303] [12159:4753617] CHIP: [IN] 0x8c, 0x1e, 0x63, 0x98, 0xfc, 0x31, 0x7c, 0x6e,
2022-02-14 15:14:30.303383+0100 CHIPTool[12159:4753617] [all] šŸŸ¢ [1644848070303] [12159:4753617] CHIP: [IN] 0xa7, 0xc1, 0x55, 0xf9, 0x49, 0x9c, 0xf4, 0x20,
2022-02-14 15:14:30.303402+0100 CHIPTool[12159:4753617] [all] šŸŸ¢ [1644848070303] [12159:4753617] CHIP: [IN] 0x7e, 0x4f, 0x88, 0x5c, 0x31, 0x57, 0xc0, 0x50,
2022-02-14 15:14:30.303420+0100 CHIPTool[12159:4753617] [all] šŸŸ¢ [1644848070303] [12159:4753617] CHIP: [IN] 0x7f, 0x29, 0x22, 0x1b, 0x4c, 0x50, 0x31, 0x2c,
2022-02-14 15:14:30.303438+0100 CHIPTool[12159:4753617] [all] šŸŸ¢ [1644848070303] [12159:4753617] CHIP: [IN] 0xc0, 0xe8, 0x3a, 0x01, 0xea, 0x2a, 0x6b, 0xb5,
2022-02-14 15:14:30.303648+0100 CHIPTool[12159:4753617] [all] šŸŸ¢ [1644848070303] [12159:4753617] CHIP: [IN] 0x82, 0xcc, 0x37, 0xb4, 0x46, 0x89, 0x2c, 0x43,
2022-02-14 15:14:30.303671+0100 CHIPTool[12159:4753617] [all] šŸŸ¢ [1644848070303] [12159:4753617] CHIP: [IN] 0x3d,
2022-02-14 15:14:30.303733+0100 CHIPTool[12159:4753617] [all] šŸŸ¢ [1644848070303] [12159:4753617] CHIP: [IN] Generated compressed fabric ID
2022-02-14 15:14:30.303754+0100 CHIPTool[12159:4753617] [all] šŸŸ¢ [1644848070303] [12159:4753617] CHIP: [IN] 0x0a, 0x99, 0x7f, 0xfc, 0xaf, 0x76, 0x49, 0xf6,
2022-02-14 15:14:30.303778+0100 CHIPTool[12159:4753617] PersistentStorageDelegate Sync Get Value for Key: F02/Fabric2
2022-02-14 15:14:30.303806+0100 CHIPTool[12159:4753617] CHIPPersistentStorageDelegate Get Value for Key: F02/Fabric2, value (null)
2022-02-14 15:14:30.303834+0100 CHIPTool[12159:4753617] PersistentStorageDelegate Sync Get Value for Key: F03/Fabric3
2022-02-14 15:14:30.303862+0100 CHIPTool[12159:4753617] CHIPPersistentStorageDelegate Get Value for Key: F03/Fabric3, value (null)
2022-02-14 15:14:30.303885+0100 CHIPTool[12159:4753617] PersistentStorageDelegate Sync Get Value for Key: F04/Fabric4
2022-02-14 15:14:30.303908+0100 CHIPTool[12159:4753617] CHIPPersistentStorageDelegate Get Value for Key: F04/Fabric4, value (null)
2022-02-14 15:14:30.303932+0100 CHIPTool[12159:4753617] PersistentStorageDelegate Sync Get Value for Key: F05/Fabric5
2022-02-14 15:14:30.303955+0100 CHIPTool[12159:4753617] CHIPPersistentStorageDelegate Get Value for Key: F05/Fabric5, value (null)
2022-02-14 15:14:30.303977+0100 CHIPTool[12159:4753617] PersistentStorageDelegate Sync Get Value for Key: F06/Fabric6
2022-02-14 15:14:30.304001+0100 CHIPTool[12159:4753617] CHIPPersistentStorageDelegate Get Value for Key: F06/Fabric6, value (null)
2022-02-14 15:14:30.304023+0100 CHIPTool[12159:4753617] PersistentStorageDelegate Sync Get Value for Key: F07/Fabric7
2022-02-14 15:14:30.304044+0100 CHIPTool[12159:4753617] CHIPPersistentStorageDelegate Get Value for Key: F07/Fabric7, value (null)
2022-02-14 15:14:30.304066+0100 CHIPTool[12159:4753617] PersistentStorageDelegate Sync Get Value for Key: F08/Fabric8
2022-02-14 15:14:30.304087+0100 CHIPTool[12159:4753617] CHIPPersistentStorageDelegate Get Value for Key: F08/Fabric8, value (null)
2022-02-14 15:14:30.304108+0100 CHIPTool[12159:4753617] PersistentStorageDelegate Sync Get Value for Key: F09/Fabric9
2022-02-14 15:14:30.304128+0100 CHIPTool[12159:4753617] CHIPPersistentStorageDelegate Get Value for Key: F09/Fabric9, value (null)
2022-02-14 15:14:30.304149+0100 CHIPTool[12159:4753617] PersistentStorageDelegate Sync Get Value for Key: F0A/Fabrica
2022-02-14 15:14:30.304215+0100 CHIPTool[12159:4753617] CHIPPersistentStorageDelegate Get Value for Key: F0A/Fabrica, value (null)
2022-02-14 15:14:30.304238+0100 CHIPTool[12159:4753617] PersistentStorageDelegate Sync Get Value for Key: F0B/Fabricb
2022-02-14 15:14:30.304260+0100 CHIPTool[12159:4753617] CHIPPersistentStorageDelegate Get Value for Key: F0B/Fabricb, value (null)
2022-02-14 15:14:30.304283+0100 CHIPTool[12159:4753617] PersistentStorageDelegate Sync Get Value for Key: F0C/Fabricc
2022-02-14 15:14:30.304310+0100 CHIPTool[12159:4753617] CHIPPersistentStorageDelegate Get Value for Key: F0C/Fabricc, value (null)
2022-02-14 15:14:30.304337+0100 CHIPTool[12159:4753617] PersistentStorageDelegate Sync Get Value for Key: F0D/Fabricd
2022-02-14 15:14:30.304358+0100 CHIPTool[12159:4753617] CHIPPersistentStorageDelegate Get Value for Key: F0D/Fabricd, value (null)
2022-02-14 15:14:30.304380+0100 CHIPTool[12159:4753617] PersistentStorageDelegate Sync Get Value for Key: F0E/Fabrice
2022-02-14 15:14:30.304606+0100 CHIPTool[12159:4753617] CHIPPersistentStorageDelegate Get Value for Key: F0E/Fabrice, value (null)
2022-02-14 15:14:30.304631+0100 CHIPTool[12159:4753617] PersistentStorageDelegate Sync Get Value for Key: F0F/Fabricf
2022-02-14 15:14:30.304652+0100 CHIPTool[12159:4753617] CHIPPersistentStorageDelegate Get Value for Key: F0F/Fabricf, value (null)
2022-02-14 15:14:30.304676+0100 CHIPTool[12159:4753617] PersistentStorageDelegate Sync Get Value for Key: F10/Fabric10
2022-02-14 15:14:30.304698+0100 CHIPTool[12159:4753617] CHIPPersistentStorageDelegate Get Value for Key: F10/Fabric10, value (null)
2022-02-14 15:14:30.305873+0100 CHIPTool[12159:4753617] [all] šŸ”µ [1644848070305] [12159:4753617] CHIP: [ZCL] Using ZAP configuration...
2022-02-14 15:14:30.305981+0100 CHIPTool[12159:4753617] [all] šŸŸ¢ [1644848070305] [12159:4753617] CHIP: [CTL] System State Initialized...
2022-02-14 15:14:30.306054+0100 CHIPTool[12159:4753617] [all] šŸ”µ [1644848070306] [12159:4753617] CHIP: [CTL] Intermediate CA is not needed
2022-02-14 15:14:30.306148+0100 CHIPTool[12159:4753617] [all] šŸ”µ [1644848070306] [12159:4753617] CHIP: [DIS] Verifying the received credentials
2022-02-14 15:14:30.314932+0100 CHIPTool[12159:4753617] [all] šŸŸ¢ [1644848070314] [12159:4753617] CHIP: [IN] Generating compressed fabric ID using uncompressed fabric ID 0x0000000000000000 and root pubkey
2022-02-14 15:14:30.314955+0100 CHIPTool[12159:4753617] [all] šŸŸ¢ [1644848070314] [12159:4753617] CHIP: [IN] 0x04, 0x64, 0x2d, 0x50, 0x41, 0x93, 0x27, 0xd6,
2022-02-14 15:14:30.314971+0100 CHIPTool[12159:4753617] [all] šŸŸ¢ [1644848070314] [12159:4753617] CHIP: [IN] 0x8f, 0x27, 0xde, 0x69, 0x21, 0xe4, 0xa7, 0x18,
2022-02-14 15:14:30.314986+0100 CHIPTool[12159:4753617] [all] šŸŸ¢ [1644848070314] [12159:4753617] CHIP: [IN] 0x8c, 0x1e, 0x63, 0x98, 0xfc, 0x31, 0x7c, 0x6e,
2022-02-14 15:14:30.314999+0100 CHIPTool[12159:4753617] [all] šŸŸ¢ [1644848070314] [12159:4753617] CHIP: [IN] 0xa7, 0xc1, 0x55, 0xf9, 0x49, 0x9c, 0xf4, 0x20,
2022-02-14 15:14:30.315014+0100 CHIPTool[12159:4753617] [all] šŸŸ¢ [1644848070315] [12159:4753617] CHIP: [IN] 0x7e, 0x4f, 0x88, 0x5c, 0x31, 0x57, 0xc0, 0x50,
2022-02-14 15:14:30.315028+0100 CHIPTool[12159:4753617] [all] šŸŸ¢ [1644848070315] [12159:4753617] CHIP: [IN] 0x7f, 0x29, 0x22, 0x1b, 0x4c, 0x50, 0x31, 0x2c,
2022-02-14 15:14:30.315044+0100 CHIPTool[12159:4753617] [all] šŸŸ¢ [1644848070315] [12159:4753617] CHIP: [IN] 0xc0, 0xe8, 0x3a, 0x01, 0xea, 0x2a, 0x6b, 0xb5,
2022-02-14 15:14:30.315058+0100 CHIPTool[12159:4753617] [all] šŸŸ¢ [1644848070315] [12159:4753617] CHIP: [IN] 0x82, 0xcc, 0x37, 0xb4, 0x46, 0x89, 0x2c, 0x43,
2022-02-14 15:14:30.315071+0100 CHIPTool[12159:4753617] [all] šŸŸ¢ [1644848070315] [12159:4753617] CHIP: [IN] 0x3d,
2022-02-14 15:14:30.315100+0100 CHIPTool[12159:4753617] [all] šŸŸ¢ [1644848070315] [12159:4753617] CHIP: [IN] Generated compressed fabric ID
2022-02-14 15:14:30.315117+0100 CHIPTool[12159:4753617] [all] šŸŸ¢ [1644848070315] [12159:4753617] CHIP: [IN] 0x0a, 0x99, 0x7f, 0xfc, 0xaf, 0x76, 0x49, 0xf6,
2022-02-14 15:14:30.315138+0100 CHIPTool[12159:4753617] [all] šŸ”µ [1644848070315] [12159:4753617] CHIP: [DIS] Added new fabric at index: 1, Initialized: 1
2022-02-14 15:14:30.315217+0100 CHIPTool[12159:4753617] [all] šŸ”µ [1644848070315] [12159:4753617] CHIP: [DIS] Assigned compressed fabric ID: 0x0A997FFCAF7649F6, node ID: 0x271F5C57DA189D31
2022-02-14 15:14:30.315283+0100 CHIPTool[12159:4753617] [all] šŸ”µ [1644848070315] [12159:4753617] CHIP: [CTL] Joined the fabric at index 1. Compressed fabric ID is: 0x0A997FFCAF7649F6
2022-02-14 15:14:30.315401+0100 CHIPTool[12159:4753635] [all] šŸŸ¢ [1644848070315] [12159:4753635] CHIP: [DL] _OnPlatformEvent
2022-02-14 15:14:30.315461+0100 CHIPTool[12159:4753617] PersistentStorageDelegate Sync Get Value for Key: ListPairedDevices0
2022-02-14 15:14:30.315513+0100 CHIPTool[12159:4753617] CHIPPersistentStorageDelegate Get Value for Key: ListPairedDevices0, value (null)
2022-02-14 15:14:33.878309+0100 CHIPTool[12159:4753617] Payload vendorID 9050
2022-02-14 15:14:33.878527+0100 CHIPTool[12159:4753617] Rendezvous Default
2022-02-14 15:14:33.878739+0100 CHIPTool[12159:4753617] [all] šŸ”µ [1644848073878] [12159:4753617] CHIP: [BLE] NewConnection
2022-02-14 15:14:33.883193+0100 CHIPTool[12159:4753617] [all] šŸ”“ [1644848073883] [12159:4753617] CHIP: [DL] Browse (kDNSServiceErr_NoAuth)
2022-02-14 15:14:33.883297+0100 CHIPTool[12159:4753617] Error(../../../../../../../../../../../Downloads/connectedhomeip.git/src/platform/Darwin/DnssdImpl.cpp:390: CHIP Error 0x000000AC: Internal error): Failure while pairing the device
2022-02-14 15:14:33.895536+0100 CHIPTool[12159:4753760] [all] šŸŸ¢ [1644848073895] [12159:4753760] CHIP: [BLE] CBManagerState: ON
2022-02-14 15:14:33.935160+0100 CHIPTool[12159:4753760] [all] šŸ”µ [1644848073935] [12159:4753760] CHIP: [BLE] Connecting to device with discriminator: 3840
2022-02-14 15:14:34.455678+0100 CHIPTool[12159:4753756] [all] šŸ”“ [1644848074455] [12159:4753756] CHIP: [BLE] Service not found on the device.
2022-02-14 15:14:34.455884+0100 CHIPTool[12159:4753756] [all] šŸ”“ [1644848074455] [12159:4753756] CHIP: [-] ../../../../../../../../../../../Downloads/connectedhomeip.git/src/platform/Darwin/BleConnectionDelegateImpl.mm:221: CHIP Error 0x00000003: Incorrect state at ../../../../../../../../../../../Downloads/connectedho

Here is the output of the ESP32 device:

Waiting for the device to reconnect..........................
????Ń„???version: v7.0sion: 7679c42
I (1057) wifi:config NVS flash: enabled
I (1057) wifi:config nano formating: disabled
I (1067) wifi:Init data frame dynamic rx buffer num: 32
I (1067) wifi:Init management frame dynamic rx buffer num: 32
I (1067) wifi:Init management short buffer num: 32
I (1087) wifi:Init dynamic tx buffer num: 32
I (1087) wifi:Init static rx buffer size: 1600
I (1087) wifi:Init static rx buffer num: 10
I (1097) wifi:Init dynamic rx buffer num: 32
I (1097) wifi_init: rx ba win: 6
I (1097) wifi_init: tcpip mbox: 32
I (1107) wifi_init: udp mbox: 6
I (1107) wifi_init: tcp mbox: 6
I (1107) wifi_init: tcp tx win: 5744
I (1117) wifi_init: tcp rx win: 5744
I (1117) wifi_init: tcp mss: 1440
I (1117) wifi_init: WiFi IRAM OP enabled
I (1137) wifi_init: WiFi RX IRAM OP enabled
I (1147) chip[DL]: NVS set: chip-counters/reboot-count = 17 (0x11)
I (1147) chip[DL]: Real time clock set to 946684800 (0100/00/01 00:00:00 UTC)
I (1147) chip[SVR]: SetupQRCode: [MT:C8XA0SRB00KA0648G00]
I (1167) chip[SVR]: Copy/paste the below URL in a browser to see the QR Code:
    https://dhrishi.github.io/connectedhomeip/qrcode.html?data=MT%3AC8XA0SRB00KA0648G00
I (1157) BTDM_INIT: BT controller compile version [6a07b06]
I (1177) chip[SVR]: Manual pairing code: [34970112332]
I (1187) phy_init: phy_version 4670,719f9f6,Feb 18 2021,17:07:07
I (1187) chip[SVR]: Long manual pairing code: [749701123309050177298]
I (1577) CHIP[DL]: BLE host-controller synced
I (2077) chip[DL]: Configuring CHIPoBLE advertising (interval 25 ms, connectable, device name MATTER-3840)
I (2087) NimBLE: GAP procedure initiated: advertise; 
I (2097) NimBLE: disc_mode=2
I (2097) NimBLE:  adv_channel_map=0 own_addr_type=2 adv_filter_policy=0 adv_itvl_min=40 adv_itvl_max=40
I (2107) NimBLE: 

I (2107) chip[DL]: CHIPoBLE advertising started
E (2107) chip[DL]: Long dispatch time: 961 ms, for event type 2
I (2127) chip[DL]: Starting ESP WiFi layer
I (2127) wifi:mode : sta (24:0a:c4:96:5d:08)
I (2127) wifi:enable tsf
W (2127) wifi:Haven't to connect to a suitable AP now!
I (2127) chip[DL]: Attempting to connect WiFi station interface
I (2147) chip[DL]: WiFi station state change: NotConnected -> Connecting
I (2147) chip[DL]: Done driving station state, nothing else to do...
I (2157) chip[ZCL]: Using ZAP configuration...
I (2167) chip[SVR]: Retrieved from server storage: a/1/8/0
I (2187) chip[ZCL]: Initiating Admin Commissioning cluster.
I (2187) chip[ZCL]: Door Lock server initialized
I (2187) chip[ZCL]: OpCreds: Initiating OpCreds cluster by writing fabrics list from fabric table.
I (2197) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0003', EndPoint ID: '0x00', Attribute ID: '0x0001'
I (2207) app-devicecallbacks: Current free heap: 92280

I (2217) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0004', EndPoint ID: '0x00', Attribute ID: '0x0000'
I (2227) app-devicecallbacks: Unhandled cluster ID: 4
I (2237) app-devicecallbacks: Current free heap: 92280

E (2237) chip[ZCL]: Trying to write invalid Calendar Type
E (2247) chip[ZCL]: Failed to write calendar type with error: 0x87
I (2247) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0003', EndPoint ID: '0x01', Attribute ID: '0x0001'
I (2267) app-devicecallbacks: Current free heap: 92280

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

I (2297) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0005', EndPoint ID: '0x01', Attribute ID: '0x0000'
I (2307) app-devicecallbacks: Unhandled cluster ID: 5
I (2317) app-devicecallbacks: Current free heap: 92280

I (2317) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0008', EndPoint ID: '0x01', Attribute ID: '0x0000'
I (2327) app-devicecallbacks: Current free heap: 92280

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

I (2367) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0300', EndPoint ID: '0x01', Attribute ID: '0x0008'
I (2377) app-devicecallbacks: Unhandled cluster ID: 768
I (2387) app-devicecallbacks: Current free heap: 92280

I (2397) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0300', EndPoint ID: '0x01', Attribute ID: '0x4001'
I (2407) app-devicecallbacks: Unhandled cluster ID: 768
I (2417) app-devicecallbacks: Current free heap: 92280

I (2417) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0406', EndPoint ID: '0x01', Attribute ID: '0x0001'
I (2427) app-devicecallbacks: Unhandled cluster ID: 1030
I (2437) app-devicecallbacks: Current free heap: 92280

I (2447) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0406', EndPoint ID: '0x01', Attribute ID: '0x0002'
I (2457) app-devicecallbacks: Unhandled cluster ID: 1030
I (2457) app-devicecallbacks: Current free heap: 92280

I (2467) chip[ZCL]: WARNING: ATTRIBUTES ARE NOT BEING STORED IN FLASH! 
I (2477) chip[ZCL]: DEVICE WILL NOT FUNCTION PROPERLY AFTER REBOOTING!!
I (2477) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0500', EndPoint ID: '0x01', Attribute ID: '0x0001'
I (2497) app-devicecallbacks: Unhandled cluster ID: 1280
I (2507) app-devicecallbacks: Current free heap: 92280

I (2507) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0500', EndPoint ID: '0x01', Attribute ID: '0x0002'
I (2517) app-devicecallbacks: Unhandled cluster ID: 1280
I (2517) app-devicecallbacks: Current free heap: 92280

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

I (2557) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0406', EndPoint ID: '0x02', Attribute ID: '0x0001'
I (2567) app-devicecallbacks: Unhandled cluster ID: 1030
I (2577) app-devicecallbacks: Current free heap: 92280

I (2577) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0406', EndPoint ID: '0x02', Attribute ID: '0x0002'
I (2597) app-devicecallbacks: Unhandled cluster ID: 1030
I (2607) app-devicecallbacks: Current free heap: 92280

I (2627) chip[DL]: NVS set: chip-counters/GlobalMCTR = 17000 (0x4268)
I (2637) chip[DL]: NVS set: chip-counters/global-eidc = 1114112 (0x110000)
I (2767) chip[DIS]: CHIP minimal mDNS started advertising.
I (2767) chip[DIS]: Failed to find a valid admin pairing. Node ID unknown
I (2767) chip[DIS]: Start dns-sd server - no current nodeId
I (2777) chip[DIS]: Advertise commission parameter vendorID=9050 productID=17729 discriminator=3840/15
I (2787) chip[DIS]: CHIP minimal mDNS configured as 'Commissionable node device'.
I (2797) chip[IN]: CASE Server enabling CASE session setups
I (2807) chip[SVR]: Adding Multicast groups
I (2807) chip[SVR]: Server Listening...
I (2807) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0402', EndPoint ID: '0x01', Attribute ID: '0x0000'
I (2817) app-devicecallbacks: Unhandled cluster ID: 1026
I (2837) app-devicecallbacks: Current free heap: 90252

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

I (2857) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0406', EndPoint ID: '0x01', Attribute ID: '0x0000'
I (2877) app-devicecallbacks: Unhandled cluster ID: 1030
I (2877) app-devicecallbacks: Current free heap: 89180

I (2887) app-devicecallbacks: PostAttributeChangeCallback - Cluster ID: '0x0045', EndPoint ID: '0x01', Attribute ID: '0x0000'
I (2897) app-devicecallbacks: Unhandled cluster ID: 69
I (2897) app-devicecallbacks: Current free heap: 89060

E (2897) chip[DL]: Long dispatch time: 741 ms, for event type 2
I (2917) app-devicecallbacks: Current free heap: 89060

I (2917) chip[DL]: WIFI_EVENT_STA_START
W (2927) wifi:Haven't to connect to a suitable AP now!
I (2927) chip[DL]: Attempting to connect WiFi station interface
E (2937) wifi:sta is connecting, return error
E (2937) chip[DL]: esp_wifi_connect() failed: ESP_ERR_WIFI_CONN
I (2937) app-devicecallbacks: Current free heap: 89060

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

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

I (5287) chip[DL]: WIFI_EVENT_STA_DISCONNECTED
I (5287) chip[DL]: WiFi station state change: Connecting -> Connecting_Failed
W (5287) wifi:Haven't to connect to a suitable AP now!
I (5297) chip[DL]: WiFi station state change: Connecting_Failed -> NotConnected
I (5297) chip[DL]: Next WiFi station reconnect in 5000 ms
I (5307) chip[DL]: Done driving station state, nothing else to do...
I (5317) app-devicecallbacks: Current free heap: 89092

W (10307) wifi:Haven't to connect to a suitable AP now!
I (10317) chip[DL]: Attempting to connect WiFi station interface
I (10317) chip[DL]: WiFi station state change: NotConnected -> Connecting
I (10327) chip[DL]: Done driving station state, nothing else to do...
I (10957) chip[DL]: BLE GAP connection established (con 0)
I (10957) chip[DL]: CHIPoBLE advertising stopped
I (10957) app-devicecallbacks: Current free heap: 89068

I (13457) chip[DL]: WIFI_EVENT_STA_DISCONNECTED
I (13457) chip[DL]: WiFi station state change: Connecting -> Connecting_Failed
W (13457) wifi:Haven't to connect to a suitable AP now!
I (13467) chip[DL]: WiFi station state change: Connecting_Failed -> NotConnected
I (13467) chip[DL]: Next WiFi station reconnect in 5000 ms
I (13477) chip[DL]: Done driving station state, nothing else to do...
I (13487) app-devicecallbacks: Current free heap: 89092

It seems that the BLE connection is established, but the service discovery fails.

dhrishi commented 2 years ago

It seems that the BLE connection is established, but the service discovery fails.

Service discovery fails as the device is not able to successfully connect to the Wi-Fi network. See the logs:

I (5287) chip[DL]: WiFi station state change: Connecting -> Connecting_Failed
W (5287) wifi:Haven't to connect to a suitable AP now!
I (5297) chip[DL]: WiFi station state change: Connecting_Failed -> NotConnected

Can you please confirm if the AP SSID/passphrase is correct or the AP is in range?

dtodor commented 2 years ago

The BLE service discovery fails:

2022-02-14 15:14:34.455678+0100 CHIPTool[12159:4753756] [all] šŸ”“ [1644848074455] [12159:4753756] CHIP: [BLE] Service not found on the device.

The WiFi data is configured in the app, the WiFi credentials are not being provisioned. Not even a PASE session is established.

dhrishi commented 2 years ago

The device side logs show a Wi-Fi STA connection being initiated and unsuccessful, and may be that's why the BLE related stuff isn't initialized. If the regular BLE Wi-Fi commissioning is to be carried out from the iOS CHIPTool app, then can you please erase-flash on the ESP32 side and try again

dtodor commented 2 years ago

After erasing the flash and installing the application again, the behaviour is the same. According to the docs, the default Rendezvous mode for ESP32 is BLE. You can also see in the logs that the BLE advertisement has been started:

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

I (3150) NimBLE: GAP procedure initiated: advertise; 
I (3160) NimBLE: disc_mode=2
I (3160) NimBLE:  adv_channel_map=0 own_addr_type=2 adv_filter_policy=0 adv_itvl_min=40 adv_itvl_max=40
I (3170) NimBLE:
dtodor commented 2 years ago

I'm building the python controller for Linux, will try to pair the device using it.

dtodor commented 2 years ago

So, I can confirm that pairing with the Linux python controller (Debian 11) works fine. So this should be Darwin related.

Am I the only one experiencing this error? No one else is using a Mac for development?

dhrishi commented 2 years ago

I'm building the python controller for Linux, will try to pair the device using it. It should work fine with Linux chip-tool as well.

Also, if it is Monterey then there were some issues related to BLE AFAIK cc @vivien-apple

danh-geo commented 2 years ago

I updated to Monterey 12.2.1 today and seeing the same issue. It was working yesterday on Big Sur.

Log attached of attempting to pair with standalone CHIP tool: chip-tool-log.txt

tlykkeberg-grundfos commented 2 years ago

This is most likely due to iOS (>=15.1) and macOS (>=12.2.1) somehow "swallowing" the Bluetooth Service UUID 0xFFF6 and not letting it onto the application layer. I have tried to change the UUID in both the DUT software and the CHIP stack to something else (i.e. 0x0FF6), which makes it work on iOS and macOS.

danh-geo commented 2 years ago

@tlykkeberg-grundfos which files do I specifically need to update (and where) for me to try this? Thanks

tlykkeberg-grundfos commented 2 years ago

@tlykkeberg-grundfos which files do I specifically need to update (and where) for me to try this? Thanks

First you need to change the Service UUID which the chip-tool is looking for. This is specified in src/ble/BleUUID.cpp in line 31, which holds the CHIP_BLE_SVC_ID. I changed it to 0x00, 0x00, 0x0F, 0xF6, 0x00 ....

Then you would need to change it for your particular platform (mine is CC2652R7 from TI), but the files you would need to change is in the src/platform/.... directory. For the TI platform it is: src/platform/cc13x2_26x2/chipOBleProfile.h in which I changed the CHIPOBLE_SERV_UUID from 0xFFF6 to 0x0FF6.

danh-geo commented 2 years ago

Thanks for the quick reply @tlykkeberg-grundfos

I tried your suggestion (although perhaps I did something wrong). 

modified:   ../../../src/ble/BleUUID.cpp

Modified line 31, which holds the CHIP_BLE_SVC_ID. I changed it to 0x00, 0x00, 0x0F, 0xF6, 0x00

modified:   ../../../src/platform/Ameba/BLEManagerImpl.cpp
modified:   ../../../src/platform/CYW30739/cycfg_gatt_db.h
modified:   ../../../src/platform/ESP32/nimble/BLEManagerImpl.cpp
modified:   ../../../src/platform/Linux/BLEManagerImpl.cpp
modified:   ../../../src/platform/Linux/bluez/Helper.cpp
modified:   ../../../src/platform/P6/cycfg_gatt_db.h
modified:   ../../../src/platform/Zephyr/BLEManagerImpl.cpp
modified:   ../../../src/platform/cc13x2_26x2/chipOBleProfile.h
modified:   ../../../src/platform/mbed/BLEManagerImpl.cpp
modified:   ../../../src/platform/nxp/k32w/k32w0/gatt_uuid128.h

I'll be honest, I wasn't sure which file to modify, so I modified all the files in the src/platform/.... directory which mentioned 0xFFF6 to 0x0FF6

I then went through the following:

cd ${HOME}/tools/esp-idf
. ./export.sh
cd ~/Desktop/connectedhomeip
source ./scripts/bootstrap.sh
source ./scripts/activate.sh
cd ~/Desktop/connectedhomeip/examples/all-clusters-app/esp32
idf.py set-target esp32
idf.py build
idf.py -p /dev/cu.SLAB_USBtoUART erase_flash
idf.py -p /dev/cu.SLAB_USBtoUART flash monitor

And then finally attempted pairing again:

cd ~/Desktop/connectedhomeip/examples/chip-tool
./out/debug/chip-tool pairing ble-wifi 112233 {ssid} {pw} 20202021 3840

But still the pairing is failing on Monterey 12.2.1. As mentioned, it works fine on my laptop which is using Big Sur.

Log attached of the pairing: log.txt

tlykkeberg-grundfos commented 2 years ago

@danh-geo It is a different error you see now. But perhaps this is because you have failed to setup the Service UUID (both long and short). You are using the Espressif platform (ESP32), but there are 2 variants, I noticed, in the src/platform/ESP32 directory.

src/platform/ESP32/nimble/BLEManagerImpl.cpp:

const ble_uuid16_t ShortUUID_CHIPoBLEService = { BLE_UUID_TYPE_16, 0xFFF6 };

This must be changed to 0x0FF6.

Or perhaps in: src/platform/ESP32/bluedroid/BLEManagerImpl.cpp:

const uint8_t UUID_CHIPoBLEService[]       = { 0xFB, 0x34, 0x9B, 0x5F, 0x80, 0x00, 0x00, 0x80,
                                         0x00, 0x10, 0x00, 0x00, 0xF6, 0xFF, 0x00, 0x00 };
const uint8_t ShortUUID_CHIPoBLEService[]  = { 0xF6, 0xFF };

There you would need to change both the long (128-bit) and the short (16-bit) UUID.

danh-geo commented 2 years ago

@tlykkeberg-grundfos

So the first change you mentioned for src/platform/ESP32/nimble/BLEManagerImpl.cpp I had already changed and was part of my modified files in my last comment.

I then modified src/platform/ESP32/bluedroid/BLEManagerImpl.cpp as you suggested. This is what I changed it too:

const uint8_t UUID_CHIPoBLEService[]       = { 0xFB, 0x34, 0x9B, 0x5F, 0x80, 0x00, 0x00, 0x80,
                                         0x00, 0x10, 0x00, 0x00, 0xF6, 0x0F, 0x00, 0x00 };
const uint8_t ShortUUID_CHIPoBLEService[]  = { 0xF6, 0x0F };

However the pairing still failed. Appreciating the help thus far.

Log attached. log.txt

dtodor commented 2 years ago

Same here, after the changes I'm getting the same error with an ESP32 device.

dtodor commented 2 years ago

OK, but now I'm getting the same error also on Linux. I've reverted all the BLE changes, but there seems to be a problem with the all-clusters-app.

dtodor commented 2 years ago

Maybe problem related to https://github.com/project-chip/connectedhomeip/commit/907b0f36d3b528250d7efa17ae46e9fd103679e7?

s-mcclain commented 2 years ago

@dtodor have you resolved this problem or still having issues with macOS chip-tool?

dtodor commented 2 years ago

I think I need to update to macOS 12.3, haven't done this yet. On Linux the ESP32 problem has gone with the recent commits.

dtodor commented 2 years ago

After updating to macOS 12.3, pairing over BLE works.