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

[SH den]

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]

Hi,

I've picked up your case and I will have a look at the log you've sent. 

In the meanwhile I would recommend you to have a look at this blog/guide written by our Matter developers:  Matter: Testing the nRF Connect platform with Apple, Google and Samsung ecosystems 

This guide should tell you how to add provision our samples to an Apple Matter ecosystem.

Let me know if you've seen this guide before or if it solves your issue!

Kind regards,
Andreas

[CartBlanche]

I also have an outstanding support issue here for the same thing.

 Failing to connect Connecting Light Bulb sample to HomePod Mini, possibly due to 46336 [SVR]Cannot load binding table 

I've had some help and pointers, but it still isn't working 100%. In my thread I've suggested they put together a sample, along with an article or youtube video, to help those new to their tech and Matter to get us up and running quickly. Surely they must be losing business from this, if people just get frustrated and move on?!

[SH den]

Hello Andreas,

I have seen this guide( Matter: Testing the nRF Connect platform with Apple, Google and Samsung ecosystems ) and following it but still not able to add / commission.

Please let me know further steps.

Thank you.

Regards,

Darshan

[AHaug]

CartBlanche said:

I also have an outstanding support issue here for the same thing.

 Failing to connect Connecting Light Bulb sample to HomePod Mini, possibly due to 46336 [SVR]Cannot load binding table 

FYI the support engineer supporting this case has been out of office for the past week and will be for a few more days. I see you have a couple of questions left unanswered there, so I will try to answer them before Marte returns to the office. If not, she will be back in a couple of working days to answer them for you.

I'll get back to you with more details tomorrow.

Edit: Marte is back in office and has answered the questions in the case you've linked.

Kind regards,
Andreas

[AHaug]

Can you describe your procedure in details (all from what modifications you've done to the SDK/samples to how you've proceded to generate the builds and which steps you've performed in the blog) guide so we can try to follow what you're doing? It works on our end, so we need more information from you.

Kind regards,
Andreas