Open Peugot206 opened 1 year ago
bzbarsky-apple
commented
1 year ago From the Matter device:
[00:28:43.099][info ][EM] >>> [E:46123r S:0 M:252510018] (U) Msg RX from 0:D43656EF5AC382A9 [0000] --- Type 0000:20 (SecureChannel:PBKDFParamRequest)but then it never sends a response. You should look into why it's not doing that.
Peugot206
commented
1 year ago Thanks for your reply @bzbarsky-apple !
I have some interestings finds, but I am not sure whether this behaviour is expected. Since I was able to commission the device once, I was in the impression that I could either just re-commission it, or it would throw out an error that it was already commissioned. After a few days I was not able to send a cluster command nor unpair the Matter device, I think this is because I changed the Thread network credentials on both devices (even though the Thread credentials on both devices still match (ot-ctl dataset active -x and ot-ctl dataset set active and they are still connected ot-ctl state!).
Then I tried to factory reset (with the OT CLI) the Matter device and OTBR, still no luck. Then I completely erased the MCU memory flash of the Matter device, re-uploaded the Matter program and tried commissioning again, and it worked right away! I then changed the Thread credentials again on both devices, while they are still in the same Thread network(!), and I was unable to unpair the device nor send cluster commands, thus the device would get 'stuck' (since I can't unpair, nor commission).
Is this behaviour expected/known? Or is there going something wrong on my side?
ReneJosefsen
commented
1 year ago Do you reuse the same node id when doing the next commissioning attempts? Could you provide a full log from the EFR32?
bzbarsky-apple
commented
1 year ago I then changed the Thread credentials again on both devices, while they are still in the same Thread network(!), and I was unable to unpair the device nor send cluster commands
So it I understand correctly:
Is that a correct description of what you are observing? I am assuming that operational discovery fails when doing step 4? Does the new Thread network have an SRP server? Does the Matter device manage to register its operational advertisement with that SRP server?
Peugot206
commented
1 year ago @bzbarsky-apple correct. thanks for your reply. This is why I assume it fails to send Matter commands after. I'm only changing the Thread credentials by creating a new dataset on both devices (although they match). So for the SRP server, I haven't heard of that before (but I just did some reading about it), and I leave that all to the default.
ReneJosefsen
commented
1 year ago If it is possible it would be great to get a full log from the EFR32.
After the credential changes I would assume it will need to reregister the SRP entry, so the log should state something like SRP update succeeded. In case this fails and the DUT is not able to register the SRP service the controller will not be able to resolve the node id and communication will fail.
My initial though was also related to SRP.
Peugot206
commented
1 year ago @ReneJosefsen as I'm trying to gather logs from the EFR32, I suddenly run into this error on the RPI OTBR which runs CHIP-tool. I am not sure what is causing this.. I can remember that I did give it the command INFRA_IF_NAME=wlan0 WEB_GUI=1 ./script/setup in the hope this may solve things, maybe I broke something with this command...? I have never had this critical error before.
Error logs CHIP-tool:
(logs shortened for readability, see edit for full logs. Not relevant to the original issue).
(process:1606): GLib-GObject-CRITICAL **: 10:36:33.433: g_object_unref: assertion 'G_IS_OBJECT (object)' failed
[1693557393.434109][1606:1606] CHIP:DL: System Layer shutdown
[1693557393.434531][1606:1606] CHIP:TOO: Run command failure: src/platform/Linux/BLEManagerImpl.cpp:688: CHIP Error 0x00000003: Incorrect stateHmm, not sure but it does look like bluez is complaining 🤔
Peugot206
commented
1 year ago @ReneJosefsen my bad, I forgot to re-enable sudo systemctl enable hciuart, it works now :). Here are the full EFR32 while I try another commission. The onoff toggle commands are not received at all in the logs.
00> [00:00:00.000][silabs ]==================================================
00> [00:00:00.000][silabs ]SiLabs-Light starting
00> [00:00:00.000][silabs ]==================================================
00> [00:00:00.000][silabs ]Init CHIP Stack
00> [00:00:00.000][info ][DL] Setting device name to : "SiLabs-Light"
00> [00:00:00.000][silabs ]Initializing OpenThread stack
00> [00:00:00.000][info ][DL] OpenThread ifconfig up and thread start
00> [00:00:00.000][info ][DL] OpenThread started: OK
00> [00:00:00.000][info ][DL] Setting OpenThread device type to ROUTER
00> [00:00:00.000][silabs ]Starting OpenThread task
00> [00:00:00.000][info ][SVR] Subscription persistence not supported
00> [00:00:00.000][info ][SVR] Server initializing...
00> [00:00:00.000][detail][FP] Initializing FabricTable [00:00:25.512][info ][DL] _OnPlatformEvent default: event->Type = 32777
00> [00:00:25.512][detail][DL] OpenThread State Changed (Flags: 0x10000040)
00> [00:00:31.536][info ][DL] _OnPlatformEvent default: event->Type = 32777
00> [00:00:31.536][detail][DL] OpenThread State Changed (Flags: 0x200012a4)
00> [00:00:31.536][detail][DL] Device Role: CHILD
00> [00:00:31.536][detail][DL] Partition Id: 0x730C92D3
00> [00:00:31.537][info ][DL] _OnPlatformEvent default: event->Type = 32777
00> [00:00:31.537][detail][DL] Thread Attached updating Multicast address
00> [00:00:31.537][info ][SVR] Joining Multicast groups
00> [00:00:31.538][detail][DL] OpenThread State Changed (Flags: 0x00000001)
00> [00:00:31.538][detail][DL] Thread Unicast Addresses:
00> [00:00:31.538][detail][DL] fda0:a80:e5a4:1:cd18:4537:cfb7:acde/64 valid preferred
00> [00:00:31.539][detail][DL] fd30:2557:1980:b79f:0:ff:fe00:bc01/64 valid rloc
00> [00:00:31.539][detail][DL] fd30:2557:1980:b79f:bd17:2eb9:bb46:a113/64 valid
00> [00:00:31.539][detail][DL] fe80:0:0:0:90a4:b5cc:4f3:66fc/64 va[00:00:34.541][info ][SWU] Stopping the watchdog timer
00> [00:00:34.541][info ][SWU] Starting the periodic query timer, timeout: 86400 seconds
00> [00:00:34.541][detail][DMG] Endpoint 0, Cluster 0x0000_002A update version to df580c9e
00> [00:00:34.542][info ][ZCL] Cluster callback: 0x0000_002A
00> [00:00:34.542][detail][DMG] Endpoint 0, Cluster 0x0000_002A update version to df580c9f
00> [00:00:34.542][info ][ZCL] Cluster callback: 0x0000_002A
00> [00:00:42.227][info ][DL] SRP Client was started, detected server: fd30:2557:1980:b79f:42aa:ebd7:b3d1:11de
00> [00:00:42.227][info ][DL] _OnPlatformEvent default: event->Type = 32777
00> [00:00:42.227][detail][DL] OpenThread State Changed (Flags: 0x00000200)
00> [00:00:42.742][detail][DL] SRP update succeeded
00> [00:00:42.742][info ][DIS] Setting operational delegate post init
00> [00:00:42.742][info ][DL] _OnPlatformEvent default: event->Type = 32784
00> [00:00:42.742][error ][SVR] Server initialization complete
00> [00:00:42.742][info ][DIS] Updating services using commissioning mode 0
00> [00:00:42.743][detail][DL] Using Thread extended MAC for hostname.
00> [00:00:42.743][info ][DIS] Advertise operational node 248092C7195391ED-0000000000000002
00> [00:00:42.743][info ][DL] advertising srp service: 248092C7195391ED-0000000000000002._matter._tcp
00> [00:00:42.743][detail][DL] Using Thread extended MAC for hostname.
00> [00:00:42.744][info ][DIS] Advertise commission parameter vendorID=65521 productID=32773 discriminator=3840/15 cm=[00:00:44.335][detail][DL] SRP update succeeded
00> [00:00:49.021][detail][DL] Start BLE advertissement
00> [00:00:55.453][info ][DL] Connect Event for handle : 1
00> [00:00:55.568][info ][DL] evt_UNKNOWN id = 090600a0
00> [00:00:57.030][info ][DL] Char Write Req, char : 23
00> [00:00:57.030][detail][DL] Write request/command received for CHIPoBLE RX characteristic (con 1, len 9)
00> [00:00:57.031][info ][DL] _OnPlatformEvent kCHIPoBLEWriteReceived
00> [00:00:57.031][info ][BLE] local and remote recv window sizes = 5
00> [00:00:57.031][info ][BLE] selected BTP version 4
00> [00:00:57.031][info ][BLE] using BTP fragment sizes rx 244 / tx 244.
00> [00:00:57.127][info ][DL] HandleTXcharCCCDWrite - Config Flags value : 2
00> [00:00:57.127][info ][DL] CHIPoBLE subscribe received
00> [00:00:57.128][info ][DL] _OnPlatformEvent kCHIPoBLESubscribe
00> [00:00:57.128][detail][IN] BLE EndPoint 0x200099e0 Connection Complete
00> [00:00:57.128][info ][DL] _OnPlatformEvent default: event->Type = 32775
00> [00:00:57.224][info ][DL] Tx Confirmation received
00> [00:00:57.225][info ][DL] stop soft timer
00> [00:00:57.225][info ][DL] _OnPlatformEvent kCHIPoBLEIndicateConfirm
00> [00:00:57.226][info ][DL] Char Write Req, char : 23
00> [00:00:57.226][detail][DL] Write request/command received for CHIPoBLE RX characteristic (con 1, len 73)
00> [00:00:57.227][info ][DL] _OnPlatformEvent kCHIPoBLEWriteReceived
00> [00:00:57.227][info ][EM] >>> [E:26834r S:0 M:263958489] (U) Msg RX from 0:C8F66327FD0418E7 [0000] --- Type 0000:20 (SecureChannel:PBKDFParamRequest)
00> [00:00:59.809][info ][DL] Tx Confirmation received
00> [00:00:59.809][info ][DL] stop soft timer
00> [00:00:59.809][info ][DL] _OnPlatformEvent kCHIPoBLEIndicateConfirm
00> [00:01:02.295][info ][DL] Char Write Req, char : 23
00> [00:01:02.295][detail][DL] Write request/command received for CHIPoBLE RX characteristic (con 1, len 3)
00> [00:01:02.296][info ][DL] _OnPlatformEvent kCHIPoBLEWriteReceived
00> [00:01:04.879][info ][DL] Tx Confirmation received
00> [00:01:04.879][info ][DL] stop soft timer
00> [00:01:04.879][info ][DL] _OnPlatformEvent kCHIPoBLEIndicateConfirm
00> [00:01:05.416][info ][DL] HandleTXcharCCCDWrite - Config Flags value : 0
00> [00:01:05.416][info ][DL] CHIPoBLE unsubscribe received
00> [00:01:05.416][info ][DL] _OnPlatformEvent kCHIPoBLEUnsubscribe
00> [00:01:05.416][detail][IN] Clearing BLE pending packets.
00> [00:01:05.416][info ][BLE] Releasing end point's BLE connection back to application.
00> [00:01:07.512][info ][DL] Disconnect Event for handle : 1
00> [00:01:07.512][info ][DL] BLE GATT connection closed (con 1, reason 4115)
00> [00:01:07.512][info ][DL] _OnPlatformEvent kCHIPoBLEConnectionError
00> [00:01:07.512][detail][DL] Start BLE advertissement
00> [00:01:35.126][info ][DL] _OnPlatformEvent default: event->Type = 32777
00> [00:01:35.126][detail][DL] OpenThread State Changed (Flags: 0x00000064)
00> [00:01:35.126][detail][DL] Device Role: ROUTER
00> [00:01:37.515][detail][DL] bleAdv Timeout : Start slow advertissmentThe EFR32 does join the network and does report a successful SRP entry 🤔
00> [00:00:42.742][detail][DL] SRP update succeeded
Is the PI using a TH image ?
Peugot206
commented
1 year ago Thanks for your help. I'm not sure what you mean with a TH image? 😅
The Raspberry Pi runs on Ubuntu 22.04, I built the Matter SDK on it from scratch and that seems to run fine (apart from sometimes having to restart some Bluetooth services). No pre-built images.
ReneJosefsen
commented
1 year ago Okay, I was wondering if it was based on the Test Harness (TH) images that are created for the specific matter releases.
I'm not super familiar with this setup, but it would be interesting to somehow verify if the routes in the network break when the thread dataset is changes.
Any chance you can generate a log of the whole scenario, so successful commissioning, toggle on/off, change dataset on EFR and OTBR and then the subsequent failure to communicate??
Reproduction steps
Hello everyone,
I have the following setup:
I have the devices succesfully connected in a thread network, I can check this by the HEX datasets matching and the state 'leader' and 'child' (or 'router'). When starting commission, I make sure ble adv is enabled on the EFR32 Matter device using a command (ble adv start).
Here is the following command I run on CHIP-tool where the Timeout error occurs:
./chip-tool pairing ble-thread 1301 hex:[LONGHEX] 20202021 3840I have only once succeeded in this exact setup to commission a device. I really have no clue what I could have done different that time, I do not understand why it keeps failing. Once I send the command I can see in the Matter logs of the EFR32 device that it is receiving stuff. See attached logs below.
I must admit I'm not sure whether I am using 1.1 or 1.3. I am using the latest CHIP-tool version from a few days ago, for the EFR32 I am running the Light Example from the Silicon Labs Matter SDK.
(Furthermore (maybe this should be in a seperate issue) I can't commission the device through my Google Home app. I can see in the EFR32 logs that it is making a connection and the Google Home app can actually find the device, but it fails to commission it. Can't the Google Home app work with OTBR on a Raspberry Pi 4? My phone and the OTBR are connected to the same network).
Bug prevalence
All the time (commission did work only ONCE while using this exact same setup).
GitHub hash of the SDK that was being used
a40963d7d571c18f4da18205b918e0c1b4e788f5
Platform
efr32, nrf, raspi
Platform Version(s)
No response
Type
Platform Issue
Anything else?
Logs OTBR (CHIP-tool, RPI 4)
Logs EFR32 (Matter device)