NRF 52840 matter light bulb fail commissioning with Apple Home pod mini

Question

Hello,

I am trying to connect to nrf52840 light bulb example to apple home pod mini (support thread border router and matter) but it fails to connect and not able to commission.

I am able to scan QR code and finish all process but at last iphone shows "Unable to add accessory."

Below are versions I am using.

- IOS 16.3.1 , iPhone XS , Home Pod mini 16.3.2

- NRFconnect SDK 2.3.0 / matter/light bulb

will appreciate any help!

Thank you.

I am attaching log from nrf52840 and screen image from apple when it fails.

Fullscreen 3808.failto connect.log Download

I: nRF5 802154 radio initialized
I: 4 Sectors of 4096 bytes
I: alloc wra: 1, df0
I: data wra: 1, 3c4


uart:~$ *** Booting Zephyr OS build v3.2.99-ncs2 ***
I: Init CHIP stack
I: 226 [DL]BLE address: E7:30:08:B0:80:A5
I: 237 [DL]OpenThread started: OK
I: 240 [DL]Setting OpenThread device type to ROUTER
I: 244 [SVR]Server initializing...
I: 248 [TS]Last Known Good Time: 2023-03-08T17:55:10
I: 254 [DMG]AccessControl: initializing
I: 257 [DMG]Examples::AccessControlDelegate::Init
I: 262 [DMG]AccessControl: setting
I: 265 [DMG]DefaultAclStorage: initializing
I: 269 [DMG]DefaultAclStorage: 0 entries loaded
D: 273 [IN]UDP::Init bind&listen port=5540
E: 277 [IN]SO_REUSEPORT failed: 109
D: 280 [IN]UDP::Init bound to port=5540
D: 284 [IN]BLEBase::Init - setting/overriding transport
D: 289 [IN]TransportMgr initialized
I: 299 [ZCL]Using ZAP configuration...
I: 306 [DMG]AccessControlCluster: initializing
I: 311 [ZCL]Initiating Admin Commissioning cluster.
I: 316 [ZCL]On/Off set value: 1 0
I: 319 [ZCL]On/off already set to new value
I: 324 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 254
D: 333 [IN]SecureSession[0x20003568]: Allocated Type:1 LSID:53955
I: 338 [DIS]Updating services using commissioning mode 1
I: 345 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=1
E: 354 [DIS]Failed to advertise commissionable node: 3
E: 359 [DIS]Failed to finalize service update: 1c
I: 363 [DIS]Updating services using commissioning mode 1
I: 369 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=1
E: 378 [DIS]Failed to advertise commissionable node: 3
E: 383 [DIS]Failed to finalize service update: 1c
I: 388 [DIS]Delaying proxy of operational discovery: missing delegate
I: 394 [IN]CASE Server enabling CASE session setups
D: 399 [IN]SecureSession[0x20003620]: Allocated Type:2 LSID:53956
I: 404 [SVR]Joining Multicast groups
I: 408 [SVR]Server Listening...
I: 411 [DL]Device Configuration:
I: 414 [DL]  Serial Number: 11223344556677889900
I: 419 [DL]  Vendor Id: 65521 (0xFFF1)
I: 422 [DL]  Product Id: 32773 (0x8005)
I: 426 [DL]  Hardware Version: 0
I: 430 [DL]  Setup Pin Code (0 for UNKNOWN/ERROR): 20202021
I: 436 [DL]  Setup Discriminator (0xFFFF for UNKNOWN/ERROR): 3840 (0xF00)
I: 443 [DL]  Manufacturing Date: (not set)
I: 447 [DL]  Device Type: 65535 (0xFFFF)
I: 452 [SVR]SetupQRCode: [MT:6FCJ142C00KA0648G00]
I: 456 [SVR]Copy/paste the below URL in a browser to see the QR Code:
I: 462 [SVR]https://project-chip.github.io/connectedhomeip/qrcode.html?data=MT%3A6FCJ142C00KA0648G00
I: 471 [SVR]Manual pairing code: [34970112332]
I: 477 [DL]CHIP task running
I: 481 [DL]CHIPoBLE advertising started
I: 486 [ZCL]Cluster OnOff: attribute OnOff set to 0
I: 491 [ZCL]Cluster LevelControl: attribute CurrentLevel set to 254
I: 499 [DL]NFC Tag emulation started
I: 19264 [DL]BLE connection established (ConnId: 0x00)
I: 19269 [DL]Current number of connections: 1/1
I: 19273 [DL]CHIPoBLE advertising stopped
I: 19277 [DL]NFC Tag emulation stopped
W: Ignoring data for unknown channel ID 0x003a
I: 20235 [BLE]local and remote recv window sizes = 5
I: 20240 [BLE]selected BTP version 4
I: 20243 [BLE]using BTP fragment sizes rx 244 / tx 244.
D: 20415 [IN]BLE EndPoint 0x200124d8 Connection Complete
I: 20420 [DL]CHIPoBLE connection established (ConnId: 0x00, GATT MTU: 247)
I: 20522 [EM]>>> [E:23196r M:372653] (U) Msg RX from 0:CF4070660F722737 [0000] --- Type 0000:20 (SecureChannel:PBKDFParamRequest)
I: 20535 [EM]<<< [E:23196r M:233392356] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:21 (SecureChannel:PBKDFParamResponse)
I: 20546 [IN](U) Sending msg 233392356 to IP address 'BLE'
I: 20702 [EM]>>> [E:23196r M:372654] (U) Msg RX from 0:CF4070660F722737 [0000] --- Type 0000:22 (SecureChannel:PASE_Pake1)
I: 22589 [EM]<<< [E:23196r M:233392357] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:23 (SecureChannel:PASE_Pake2)
I: 22600 [IN](U) Sending msg 233392357 to IP address 'BLE'
E: 22606 [DL]Long dispatch time: 1904 ms, for event type 16388
I: 22742 [EM]>>> [E:23196r M:372655] (U) Msg RX from 0:CF4070660F722737 [0000] --- Type 0000:24 (SecureChannel:PASE_Pake3)
I: 22753 [EM]<<< [E:23196r M:233392358] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
I: 22764 [IN](U) Sending msg 233392358 to IP address 'BLE'
I: 22771 [SC]SecureSession[0x20003568]: Moving from state 'kEstablishing' --> 'kActive'
D: 22779 [IN]SecureSession[0x20003568]: Activated - Type:1 LSID:53955
D: 22785 [IN]New secure session activated for device <FFFFFFFB00000000, 0>, LSID:53955 PSID:61964!
I: 22794 [SVR]Commissioning completed session establishment step
I: 22800 [DIS]Updating services using commissioning mode 0
I: 22807 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=0
E: 22816 [DIS]Failed to advertise extended commissionable node: 3
D: 22822 [DIS]Scheduling extended discovery timeout in 900s
E: 22827 [DIS]Failed to finalize service update: 1c
I: 22832 [SVR]Device completed Rendezvous process
I: 22863 [EM]>>> [E:23197r M:30365919] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D: 22873 [IM]Received Read request
I: 22878 [EM]<<< [E:23197r M:169276862] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I: 22888 [IN](S) Sending msg 169276862 on secure session with LSID: 53955
I: 22983 [EM]>>> [E:23198r M:30365920] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D: 22993 [IM]Received Read request
I: 23000 [EM]<<< [E:23198r M:169276863] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I: 23010 [IN](S) Sending msg 169276863 on secure session with LSID: 53955
I: 23223 [EM]>>> [E:23199r M:30365921] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D: 23233 [IM]Received Read request
I: 23238 [EM]<<< [E:23199r M:169276864] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I: 23248 [IN](S) Sending msg 169276864 on secure session with LSID: 53955
I: 23343 [EM]>>> [E:23200r M:30365922] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D: 23353 [IM]Received Read request
I: 23358 [EM]<<< [E:23200r M:169276865] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I: 23368 [IN](S) Sending msg 169276865 on secure session with LSID: 53955
I: 23463 [EM]>>> [E:23201r M:30365923] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D: 23473 [IM]Received Read request
I: 23480 [EM]<<< [E:23201r M:169276866] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I: 23490 [IN](S) Sending msg 169276866 on secure session with LSID: 53955
I: 23703 [EM]>>> [E:23202r M:30365924] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D: 23713 [IM]Received Read request
I: 23718 [EM]<<< [E:23202r M:169276867] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I: 23728 [IN](S) Sending msg 169276867 on secure session with LSID: 53955
I: 23823 [EM]>>> [E:23203r M:30365925] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D: 23833 [IM]Received Read request
I: 23843 [EM]<<< [E:23203r M:169276868] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I: 23853 [IN](S) Sending msg 169276868 on secure session with LSID: 53955
I: 24063 [EM]>>> [E:23204r M:30365926] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 24074 [FS]GeneralCommissioning: Received ArmFailSafe (60s)
I: 24081 [EM]<<< [E:23204r M:169276869] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 24092 [IN](S) Sending msg 169276869 on secure session with LSID: 53955
I: 24183 [EM]>>> [E:23205r M:30365927] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 24197 [EM]<<< [E:23205r M:169276870] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 24208 [IN](S) Sending msg 169276870 on secure session with LSID: 53955
I: 24303 [EM]>>> [E:23206r M:30365928] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 24314 [ZCL]OpCreds: Certificate Chain request received for PAI
I: 24323 [EM]<<< [E:23206r M:169276871] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 24334 [IN](S) Sending msg 169276871 on secure session with LSID: 53955
I: 24663 [EM]>>> [E:23207r M:30365929] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 24674 [ZCL]OpCreds: Certificate Chain request received for DAC
I: 24683 [EM]<<< [E:23207r M:169276872] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 24694 [IN](S) Sending msg 169276872 on secure session with LSID: 53955
I: 25023 [EM]>>> [E:23208r M:30365930] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 25034 [ZCL]OpCreds: Received an AttestationRequest command
I: 25070 [ZCL]OpCreds: AttestationRequest successful.
I: 25079 [EM]<<< [E:23208r M:169276873] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 25090 [IN](S) Sending msg 169276873 on secure session with LSID: 53955
I: 25443 [EM]>>> [E:23209r M:30365931] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 25454 [FS]GeneralCommissioning: Received ArmFailSafe (60s)
I: 25461 [EM]<<< [E:23209r M:169276874] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 25472 [IN](S) Sending msg 169276874 on secure session with LSID: 53955
I: 27423 [EM]>>> [E:23210r M:30365932] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 27434 [ZCL]OpCreds: Received a CSRRequest command
I: 27625 [ZCL]OpCreds: AllocatePendingOperationalKey succeeded
I: 27661 [ZCL]OpCreds: CSRRequest successful.
I: 27668 [EM]<<< [E:23210r M:169276875] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 27679 [IN](S) Sending msg 169276875 on secure session with LSID: 53955
E: 27686 [DL]Long dispatch time: 265 ms, for event type 16388
I: 28024 [EM]>>> [E:23211r M:30365933] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 28035 [ZCL]OpCreds: Received an AddTrustedRootCertificate command
I: 28098 [ZCL]OpCreds: AddTrustedRootCertificate successful.
I: 28104 [EM]<<< [E:23211r M:169276876] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 28115 [IN](S) Sending msg 169276876 on secure session with LSID: 53955
I: 28324 [EM]>>> [E:23212r M:30365934] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 28335 [ZCL]OpCreds: Received an AddNOC command
I: 28343 [FP]Validating NOC chain
I: 28404 [FP]NOC chain validation successful
I: 28408 [FP]Added new fabric at index: 0x1
I: 28412 [FP]Assigned compressed fabric ID: 0x64363021EF548DF2, node ID: 0x0000000063423C67
I: 28420 [TS]Last Known Good Time: 2023-03-08T17:55:10
I: 28425 [TS]New proposed Last Known Good Time: 2023-03-17T00:50:44
I: 28431 [TS]Updating pending Last Known Good Time to 2023-03-17T00:50:44
I: 28456 [ZCL]OpCreds: ACL entry created for Fabric index 0x1 CASE Admin Subject 0x19BC2F7F10C4B1E6
I: 28465 [DIS]Advertise operational node 64363021EF548DF2-0000000063423C67
I: 28471 [ZCL]OpCreds: successfully created fabric index 0x1 via AddNOC
I: 28479 [EM]<<< [E:23212r M:169276877] (S) Msg TX to 1:FFFFFFFB00000000 [8DF2] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 28490 [IN](S) Sending msg 169276877 on secure session with LSID: 53955
E: 28497 [DL]Long dispatch time: 175 ms, for event type 16388
I: 28563 [EM]>>> [E:23213r M:30365935] (S) Msg RX from 1:FFFFFFFB00000000 [8DF2] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 28580 [EM]<<< [E:23213r M:169276878] (S) Msg TX to 1:FFFFFFFB00000000 [8DF2] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 28591 [IN](S) Sending msg 169276878 on secure session with LSID: 53955
I: 28683 [EM]>>> [E:23214r M:30365936] (S) Msg RX from 1:FFFFFFFB00000000 [8DF2] --- Type 0001:08 (IM:InvokeCommandRequest)
I: 34664 [DL]SRP Client was started, detected server: fd34:bb1a:d920:0000:3c04:149e:dafc:011e
I: 34677 [EM]<<< [E:23214r M:169276879] (S) Msg TX to 1:FFFFFFFB00000000 [8DF2] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 34688 [IN](S) Sending msg 169276879 on secure session with LSID: 53955
I: 34695 [DIS]Advertise operational node 64363021EF548DF2-0000000063423C67
I: 34702 [SVR]Operational advertising enabled
I: 35128 [DIS]Setting operational delegate post init
I: 35136 [SWU]Stopping the watchdog timer
I: 35140 [SWU]Starting the periodic query timer, timeout: 86400 seconds
I: 35146 [DIS]Updating services using commissioning mode 0
I: 35152 [DIS]Advertise operational node 64363021EF548DF2-0000000063423C67
I: 35159 [DL]advertising srp service: 64363021EF548DF2-0000000063423C67._matter._tcp
I: 35168 [DIS]Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=0
I: 35177 [DL]advertising srp service: DD77A0E0FEDB0694._matterc._udp

AHaug · Accepted Answer

Hi, I've had a chat with the developers and have the following information and questions for you: 
 We've tested our samples in apple fabric multiple times now and the results are still the same (NCS v2.3.0 and same iOS/Homepod revisions you list). Everything passes smoothly. 
 We can't say much based on the logs. It looks like CASE session was not initialized by the controller, but without logs from the controller (which we can't get since it is Apple proprietary) we can't see why it has happened. We're aware of one problem with Apple and CASE that is tracked in this github issue, however it's too early for me to say if it can be the same problem or not: https://github.com/project-chip/connectedhomeip/issues/25421 
 Questions 
 Could you try with another sample such as the door lock? I have suspicion that light bulb may be some special case, as it's Thread router, while door lock is a SED. 
 It would also be good to know if you have any other devices in the same wifi network that are used by the iPhone and Homepod. We observed some problems in the past if we used several different ecosystem hubs in the one Wi-FI network. As a starter the developers would recommend to create separate Wi-Fi network for testing purposes (e.g. using hotspot). This way we would be able to exclude at least part of potential problems. 
 Let me know about these items, 
 Kind regards, Andreas

NRF 52840 matter light bulb fail commissioning with Apple Home pod mini

Top Replies