Battery level not reported correctly (both in Android app and Matter) : still reported as 100% always
Following log comes predictably every 25 minutes. Only the node which is my Nuki lock. It has never lost connectivity permanently, but commands occasionally are not executed. The log seems to indicate some connection instability.
Mar 16 16:46:08 LivingPI python[448805]: 2024-03-16 16:46:08 LivingPI chip.DMG[448805] ERROR Subscription Liveness timeout with SubscriptionID = 0x5d130ee1, Peer = 01:0000000000000010
Mar 16 16:46:08 LivingPI python[448805]: 2024-03-16 16:46:08 LivingPI matter_server.server.device_controller.[node 16][448805] INFO Previous subscription failed with Error: 50, re-subscribing in 0 ms...
Mar 16 16:46:09 LivingPI python[448805]: 2024-03-16 16:46:09 LivingPI PersistentStorage[448805] INFO DeleteSdkKey: [redacted]
Mar 16 16:46:09 LivingPI python[448805]: 2024-03-16 16:46:09 LivingPI PersistentStorage[448805] INFO Committing...
Mar 16 16:46:09 LivingPI python[448805]: 2024-03-16 16:46:09 LivingPI PersistentStorage[448805] INFO SetSdkKey: f/1/s/0000000000000010 = [redacted]
Mar 16 16:46:09 LivingPI python[448805]: 2024-03-16 16:46:09 LivingPI PersistentStorage[448805] INFO Committing...
Mar 16 16:46:09 LivingPI python[448805]: 2024-03-16 16:46:09 LivingPI PersistentStorage[448805] INFO SetSdkKey: [redacted]
Mar 16 16:46:09 LivingPI python[448805]: 2024-03-16 16:46:09 LivingPI PersistentStorage[448805] INFO Committing...
Mar 16 16:46:10 LivingPI python[448805]: 2024-03-16 16:46:10 LivingPI root[448805] INFO Re-subscription succeeded!
Mar 16 16:46:10 LivingPI python[448805]: 2024-03-16 16:46:10 LivingPI matter_server.server.device_controller.[node 16][448805] INFO Re-Subscription succeeded
The new unlatch feature with Matter 1.2 is quite nice and working as intended, just needed to reload the Matter integration in HA.
I am also having the re-subscription issue in HA every 25 minutes:
2024-03-19 12:40:33 (Dummy-2) CHIP_ERROR [chip.native.DMG] Subscription Liveness timeout with SubscriptionID = 0xcd3adf88, Peer = 01:0000000000000006
2024-03-19 12:40:33 (MainThread) INFO [matter_server.server.device_controller.node_6] Previous subscription failed with Error: 50, re-subscribing in 0 ms...
2024-03-19 12:40:35 (MainThread) INFO [root] Re-subscription succeeded!
2024-03-19 12:40:35 (MainThread) INFO [matter_server.server.device_controller.node_6] Re-Subscription succeeded
2024-03-19 13:05:43 (Dummy-2) CHIP_ERROR [chip.native.DMG] Subscription Liveness timeout with SubscriptionID = 0x6a013655, Peer = 01:0000000000000006
2024-03-19 13:05:43 (MainThread) INFO [matter_server.server.device_controller.node_6] Previous subscription failed with Error: 50, re-subscribing in 0 ms...
2024-03-19 13:05:46 (MainThread) INFO [root] Re-subscription succeeded!
2024-03-19 13:05:46 (MainThread) INFO [matter_server.server.device_controller.node_6] Re-Subscription succeeded
2024-03-19 13:30:54 (Dummy-2) CHIP_ERROR [chip.native.DMG] Subscription Liveness timeout with SubscriptionID = 0xe24d2549, Peer = 01:0000000000000006
2024-03-19 13:30:54 (MainThread) INFO [matter_server.server.device_controller.node_6] Previous subscription failed with Error: 50, re-subscribing in 0 ms...
2024-03-19 13:30:57 (MainThread) INFO [root] Re-subscription succeeded!
2024-03-19 13:30:57 (MainThread) INFO [matter_server.server.device_controller.node_6] Re-Subscription succeeded
@Stefan_Reiterer is there any hope of seeing an added layer of security with the optional setting to require a PIN to unlock the Nuki over Matter?
Original post has been updated with release notes for the Smart Lock Beta 4.2.4
This Beta includes further improvements for the WiFi reconnect handling as well as the general WiFi connection. Furthermore the power consumption gets decreased with this build due to adaptations of the dynamic BLE advertising as well as improvements on the WiFi connection handling.
Please install this build and provide feedback via this channel - thank you
I’ve been having connectivity problems for a while with the beta including current 4.2.4.
See my log which was taken from a recently power cycled Smart Lock 4.0 and newly started Matter server (over Thread). Node 23 is the Smart Lock. Other nodes are different products, other brands, working fine. Node 23 shows succesfully discovered on mdns , but fails the rest of the connection process.
I never had this sort of problems before I was on the beta firmware.
-- Journal begins at Sat 2024-03-23 16:19:09 CET, ends at Sat 2024-03-23 16:30:04 CET. --
Mar 23 16:19:38 LivingPI systemd[1]: Started Mijn Matter Server.
Mar 23 16:19:43 LivingPI python[1309]: 2024-03-23 16:19:43 (MainThread) INFO [matter_server.server.stack] Initializing CHIP/Matter Logging...
Mar 23 16:19:43 LivingPI python[1309]: 2024-03-23 16:19:43 (MainThread) INFO [matter_server.server.stack] Initializing CHIP/Matter Controller Stack...
Mar 23 16:19:43 LivingPI python[1309]: [1711207183.591846][1309:1309] CHIP:CTL: Setting attestation nonce to random value
Mar 23 16:19:43 LivingPI python[1309]: [1711207183.612406][1309:1309] CHIP:CTL: Setting CSR nonce to random value
Mar 23 16:19:43 LivingPI python[1309]: [1711207183.688300][1309:1309] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs
Mar 23 16:19:43 LivingPI python[1309]: [1711207183.688563][1309:1309] CHIP:DL: writing settings to file (/tmp/chip_kvs-MZvsv9)
Mar 23 16:19:43 LivingPI python[1309]: [1711207183.688740][1309:1309] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs)
Mar 23 16:19:43 LivingPI python[1309]: [1711207183.690649][1309:1309] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /data/chip_factory.ini
Mar 23 16:19:43 LivingPI python[1309]: [1711207183.706435][1309:1309] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /data/chip_config.ini
Mar 23 16:19:43 LivingPI python[1309]: [1711207183.707018][1309:1309] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /data/chip_counters.ini
Mar 23 16:19:43 LivingPI python[1309]: [1711207183.711670][1309:1309] CHIP:DL: writing settings to file (/data/chip_counters.ini-aTY1Ba)
Mar 23 16:19:43 LivingPI python[1309]: [1711207183.712158][1309:1309] CHIP:DL: renamed tmp file to file (/data/chip_counters.ini)
Mar 23 16:19:43 LivingPI python[1309]: [1711207183.712204][1309:1309] CHIP:DL: NVS set: chip-counters/reboot-count = 94 (0x5E)
Mar 23 16:19:43 LivingPI python[1309]: [1711207183.712743][1309:1309] CHIP:DL: Got Ethernet interface: eth0
Mar 23 16:19:43 LivingPI python[1309]: [1711207183.713020][1309:1309] CHIP:DL: Found the primary Ethernet interface:eth0
Mar 23 16:19:43 LivingPI python[1309]: [1711207183.713300][1309:1309] CHIP:DL: Got WiFi interface: wlan0
Mar 23 16:19:43 LivingPI python[1309]: [1711207183.713354][1309:1309] CHIP:DL: Failed to reset WiFi statistic counts
Mar 23 16:19:43 LivingPI python[1309]: 2024-03-23 16:19:43 (MainThread) WARNING [PersistentStorage] Initializing persistent storage from file: /home/pi/.matter_server/chip.json
Mar 23 16:19:59 LivingPI python[1309]: 2024-03-23 16:19:59 (MainThread) WARNING [PersistentStorage] Loading configuration from /home/pi/.matter_server/chip.json...
Mar 23 16:19:59 LivingPI python[1309]: 2024-03-23 16:19:59 (MainThread) WARNING [CertificateAuthorityManager] Loading certificate authorities from storage...
Mar 23 16:19:59 LivingPI python[1309]: 2024-03-23 16:19:59 (MainThread) WARNING [CertificateAuthority] New CertificateAuthority at index 1
Mar 23 16:19:59 LivingPI python[1309]: 2024-03-23 16:19:59 (MainThread) WARNING [CertificateAuthority] Loading fabric admins from storage...
Mar 23 16:19:59 LivingPI python[1309]: 2024-03-23 16:19:59 (MainThread) WARNING [FabricAdmin] New FabricAdmin: FabricId: 0x0000000000000001, VendorId = 0xFFF1
Mar 23 16:19:59 LivingPI python[1309]: 2024-03-23 16:19:59 (MainThread) INFO [matter_server.server.stack] CHIP Controller Stack initialized.
Mar 23 16:19:59 LivingPI python[1309]: 2024-03-23 16:19:59 (MainThread) INFO [matter_server.server.server] Starting the Matter Server...
Mar 23 16:19:59 LivingPI python[1309]: 2024-03-23 16:19:59 (MainThread) INFO [matter_server.server.helpers.paa_certificates] Skip fetching certificates (already fetched within the last 24h).
Mar 23 16:19:59 LivingPI python[1309]: 2024-03-23 16:19:59 (MainThread) WARNING [FabricAdmin] Allocating new controller with CaIndex: 1, FabricId: 0x0000000000000001, NodeId: 0x000000000001B669, CatTags: []
Mar 23 16:20:00 LivingPI python[1309]: 2024-03-23 16:20:00 (Dummy-2) CHIP_ERROR [chip.native.DL] Long dispatch time: 626 ms, for event type 2
Mar 23 16:20:00 LivingPI python[1309]: 2024-03-23 16:20:00 (MainThread) INFO [matter_server.server.device_controller] Loaded 6 nodes from stored configuration
Mar 23 16:20:00 LivingPI python[1309]: 2024-03-23 16:20:00 (MainThread) INFO [matter_server.server.vendor_info] Loading vendor info from storage.
Mar 23 16:20:00 LivingPI python[1309]: 2024-03-23 16:20:00 (MainThread) INFO [matter_server.server.vendor_info] Loaded 181 vendors from storage.
Mar 23 16:20:00 LivingPI python[1309]: 2024-03-23 16:20:00 (MainThread) INFO [matter_server.server.vendor_info] Fetching the latest vendor info from DCL.
Mar 23 16:20:00 LivingPI python[1309]: 2024-03-23 16:20:00 (MainThread) INFO [matter_server.server.vendor_info] Fetched 179 vendors from DCL.
Mar 23 16:20:00 LivingPI python[1309]: 2024-03-23 16:20:00 (MainThread) INFO [matter_server.server.vendor_info] Saving vendor info to storage.
Mar 23 16:20:01 LivingPI python[1309]: 2024-03-23 16:20:01 (MainThread) INFO [matter_server.server.device_controller.mdns] Node 1 discovered on MDNS
Mar 23 16:20:01 LivingPI python[1309]: 2024-03-23 16:20:01 (MainThread) INFO [matter_server.server.device_controller.mdns] Node 4 discovered on MDNS
Mar 23 16:20:01 LivingPI python[1309]: 2024-03-23 16:20:01 (MainThread) INFO [matter_server.server.device_controller.mdns] Node 22 discovered on MDNS
Mar 23 16:20:01 LivingPI python[1309]: 2024-03-23 16:20:01 (MainThread) INFO [matter_server.server.device_controller.mdns] Node 23 discovered on MDNS
Mar 23 16:20:01 LivingPI python[1309]: 2024-03-23 16:20:01 (MainThread) INFO [matter_server.server.device_controller.mdns] Node 10 discovered on MDNS
Mar 23 16:20:01 LivingPI python[1309]: 2024-03-23 16:20:01 (MainThread) INFO [matter_server.server.device_controller.node_1] Setting-up node...
Mar 23 16:20:01 LivingPI python[1309]: 2024-03-23 16:20:01 (MainThread) INFO [matter_server.server.device_controller.node_4] Setting-up node...
Mar 23 16:20:01 LivingPI python[1309]: 2024-03-23 16:20:01 (MainThread) INFO [matter_server.server.device_controller.node_22] Setting-up node...
Mar 23 16:20:01 LivingPI python[1309]: 2024-03-23 16:20:01 (MainThread) INFO [matter_server.server.device_controller.node_23] Setting-up node...
Mar 23 16:20:01 LivingPI python[1309]: 2024-03-23 16:20:01 (MainThread) INFO [matter_server.server.device_controller.node_10] Setting-up node...
Mar 23 16:20:01 LivingPI python[1309]: 2024-03-23 16:20:01 (MainThread) INFO [matter_server.server.device_controller.mdns] Node 17 discovered on MDNS
Mar 23 16:20:01 LivingPI python[1309]: 2024-03-23 16:20:01 (MainThread) INFO [matter_server.server.device_controller.node_17] Setting-up node...
Mar 23 16:20:02 LivingPI python[1309]: 2024-03-23 16:20:02 (MainThread) INFO [matter_server.server.device_controller.node_1] Setting up attributes and events subscription.
Mar 23 16:20:04 LivingPI python[1309]: 2024-03-23 16:20:04 (MainThread) INFO [matter_server.server.device_controller.node_4] Setting up attributes and events subscription.
Mar 23 16:20:05 LivingPI python[1309]: 2024-03-23 16:20:05 (MainThread) INFO [matter_server.server.device_controller.node_22] Setting up attributes and events subscription.
Mar 23 16:20:13 LivingPI python[1309]: 2024-03-23 16:20:13 (MainThread) INFO [matter_server.server.device_controller.node_1] Subscription succeeded
Mar 23 16:20:18 LivingPI python[1309]: 2024-03-23 16:20:18 (MainThread) INFO [matter_server.server.device_controller.node_22] Subscription succeeded
Mar 23 16:20:25 LivingPI python[1309]: 2024-03-23 16:20:25 (MainThread) INFO [matter_server.server.device_controller.node_4] Subscription succeeded
Mar 23 16:20:34 LivingPI python[1309]: 2024-03-23 16:20:34 (Dummy-2) CHIP_ERROR [chip.native.EM] Failed to Send CHIP MessageCounter:220298590 on exchange 35192i sendCount: 4 max retries: 4
Mar 23 16:20:40 LivingPI python[1309]: 2024-03-23 16:20:40 (Dummy-2) CHIP_ERROR [chip.native.SC] CASESession timed out while waiting for a response from the peer. Current state was 1
Mar 23 16:20:42 LivingPI python[1309]: 2024-03-23 16:20:42 (MainThread) INFO [matter_server.server.device_controller.node_10] Setting up attributes and events subscription.
Mar 23 16:20:42 LivingPI python[1309]: 2024-03-23 16:20:42 (MainThread) INFO [matter_server.server.device_controller.node_17] Setting up attributes and events subscription.
Mar 23 16:20:43 LivingPI python[1309]: 2024-03-23 16:20:43 (MainThread) INFO [matter_server.server.device_controller] Attempting to resolve node 23... (attempt 2 of 2)
Mar 23 16:20:44 LivingPI python[1309]: 2024-03-23 16:20:44 (MainThread) INFO [matter_server.server.device_controller.node_17] Subscription succeeded
Mar 23 16:20:57 LivingPI python[1309]: 2024-03-23 16:20:57 (MainThread) INFO [matter_server.server.device_controller.node_10] Subscription succeeded
Mar 23 16:21:14 LivingPI python[1309]: 2024-03-23 16:21:14 (Dummy-2) CHIP_ERROR [chip.native.EM] Failed to Send CHIP MessageCounter:220298597 on exchange 35197i sendCount: 4 max retries: 4
Mar 23 16:21:18 LivingPI python[1309]: 2024-03-23 16:21:18 (Dummy-2) CHIP_ERROR [chip.native.SC] CASESession timed out while waiting for a response from the peer. Current state was 1
Mar 23 16:21:18 LivingPI python[1309]: 2024-03-23 16:21:18 (MainThread) WARNING [matter_server.server.device_controller.node_23] Setup for node failed: Unable to resolve Node 23
With 4.2.3 and Nuki Hub (BLE API) the activity log worked. Now with 4.2.4 I receive again not the last 5 entries, it looks like the wrong order. Also the authorization data is not correct.
Is it possible to downgrade to 4.2.3? I am going on vacation some days and last fw broke so many things:
not able to open/close using matter with HA
very slow response from mqtt
battery draining very fast
sometimes door is open later when 2 persons are in the entrance, much late, when you are already inside home. I had to deactivate Auto Unlock for security reasons.
Original post has been updated with release notes for the Smart Lock Beta 4.2.5
This Beta includes improvements on the MQTT connection (adjusted internal settings and optimized timeout handling) as well as further optimizations on the power consumption due to an adapted handling of unlatch actions.
Please install this build and provide feedback via this channel - thank you
1-Button on Smart Lock 4 Pro ( when Button used to Unlock/Lock its work but notification not work ( notification are not sent to Nuki App or apple home ) To update the lock status.
2- lock status break only when used Button on smart Lock 4 pro ( lock / unlock ) .
My issues with the slow response of MQTT and non working matter were resolved after removing a thread repeater I had between the Nuki and the router. With a direct connection now, it works correctly.
My Nuki is the only device in the Thread network and I only have a Thread Border Router, Home Assistant.
After the 4.2.5 update it seems that commands are more reliable to the Nuki but it won’t update it’s status.
If I send a command it will execute it but it won’t update its status to the Matter server, the older release would loose its connection completely and stop responding to commands and updating the Matter server on status changes.
With this new release I’ve seen a reduction in the re-subrscription logs in the Matter servers but I’ve also seen a surge in errors:
2024-03-31 07:15:13 (Dummy-2) CHIP_ERROR [chip.native.DMG] Subscription Liveness timeout with SubscriptionID = 0x05277932, Peer = 01:0000000000000006
2024-03-31 07:15:13 (MainThread) INFO [matter_server.server.device_controller.node_6] Previous subscription failed with Error: 50, re-subscribing in 0 ms...
2024-03-31 07:15:16 (MainThread) INFO [root] Re-subscription succeeded!
2024-03-31 07:15:16 (MainThread) INFO [matter_server.server.device_controller.node_6] Re-Subscription succeeded
2024-03-31 07:40:23 (Dummy-2) CHIP_ERROR [chip.native.DMG] Subscription Liveness timeout with SubscriptionID = 0x9ad297b3, Peer = 01:0000000000000006
2024-03-31 07:40:23 (MainThread) INFO [matter_server.server.device_controller.node_6] Previous subscription failed with Error: 50, re-subscribing in 0 ms...
2024-03-31 07:40:27 (MainThread) INFO [root] Re-subscription succeeded!
2024-03-31 07:40:27 (MainThread) INFO [matter_server.server.device_controller.node_6] Re-Subscription succeeded
2024-03-31 07:58:39 (MainThread) INFO [matter_server.server.device_controller.mdns] Node 6 re-discovered on MDNS
2024-03-31 07:58:39 (MainThread) INFO [matter_server.server.device_controller.node_6] Setting-up node...
2024-03-31 07:58:39 (MainThread) INFO [matter_server.server.device_controller.node_6] Unsubscribing from existing subscription.
2024-03-31 07:58:39 (MainThread) INFO [matter_server.server.device_controller.node_6] Setting up attributes and events subscription.
2024-03-31 07:58:39 (MainThread) WARNING [matter_server.server.device_controller.node_6] Unable to subscribe to Node: src/inet/UDPEndPointImplSockets.cpp:417: OS Error 0x02000013: No such device
2024-04-01 22:09:01 (MainThread) INFO [matter_server.server.device_controller.mdns] Node 6 discovered on MDNS
2024-04-01 22:09:01 (MainThread) INFO [matter_server.server.device_controller.node_6] Setting-up node...
2024-04-01 22:09:01 (MainThread) INFO [matter_server.server.device_controller.node_6] Setting up attributes and events subscription.
2024-04-01 22:09:01 (MainThread) WARNING [matter_server.server.device_controller.node_6] Unable to subscribe to Node: src/inet/UDPEndPointImplSockets.cpp:417: OS Error 0x02000013: No such device
2024-04-02 08:21:28 (MainThread) INFO [matter_server.server.device_controller.mdns] Node 6 discovered on MDNS
2024-04-02 08:21:28 (MainThread) INFO [matter_server.server.device_controller.node_6] Setting-up node...
2024-04-02 08:21:28 (MainThread) INFO [matter_server.server.device_controller.node_6] Setting up attributes and events subscription.
2024-04-02 08:21:28 (MainThread) WARNING [matter_server.server.device_controller.node_6] Unable to subscribe to Node: src/inet/UDPEndPointImplSockets.cpp:417: OS Error 0x02000013: No such device
I confirmed the same problem in an update 4.2.5 and
4.2.4
The Smart Lock Beta 4.2.5 update broke :
1-Button on Smart Lock 4 Pro ( when Button used to Unlock/Lock its work but notification not work ( notification are not sent to Nuki App or apple home ) To update the lock status.
2- lock status break only when used Button on smart Lock 4 pro ( lock / unlock ) .
