search

home-assistant / core

:house_with_garden: Open source home automation that puts local control and privacy first.
https://www.home-assistant.io
Apache License 2.0
72.67k stars 30.42k forks source link

Most recent Matter updated stopped my previous connection with Aqara Smart Lock U100 (Matter enabled lock) to stop working #112088

Closed lambros414 closed 7 months ago

lambros414 commented 7 months ago

The problem

Forgive me if this is the wrong location to post, but not certain where to put this.

I installed a Matter enabled lock (Aqara Smart Lock U100) a few weeks ago within home assistant. Admittedly to took some time for it to be recognized using the companion app to add the device, however it was eventually added after sever attempts.

I recently upgraded to the latest version of Matter (trying to find the version number but can't find it).

Since then, trying to control the device from home assistant does not work. Also, when manually locking/unlocking the lock, the state isn't updated within Home assistant.

I looked in log files and did not notice any errors when loading the Matter Integration, nor trying to control the lock.

What version of Home Assistant Core has the issue?

2024.2.5

What was the last working version of Home Assistant Core?

2024.2.4 (???)

What type of installation are you running?

Home Assistant OS

Integration causing the issue

Matter (Beta)

Link to integration documentation on our website

No response

Diagnostics information

No response

Example YAML snippet

No response

Anything in the logs that might be useful for us?

No response

Additional information

No response

home-assistant[bot] commented 7 months ago

Hey there @home-assistant/matter, mind taking a look at this issue as it has been labeled with an integration (matter) you are listed as a code owner for? Thanks!

Code owner commands Code owners of `matter` can trigger bot actions by commenting: - `@home-assistant close` Closes the issue. - `@home-assistant rename Awesome new title` Renames the issue. - `@home-assistant reopen` Reopen the issue. - `@home-assistant unassign matter` Removes the current integration label and assignees on the issue, add the integration domain after the command. - `@home-assistant add-label needs-more-information` Add a label (needs-more-information, problem in dependency, problem in custom component) to the issue. - `@home-assistant remove-label needs-more-information` Remove a label (needs-more-information, problem in dependency, problem in custom component) on the issue.

(message by CodeOwnersMention)

matter documentation matter source (message by IssueLinks)

Panzer1119 commented 7 months ago

I have the same problem.

I have two Tapo/TP-Link plugs, a "dumb" one and an energy monitoring one.

The dump one works, but the energy monitoring one is unavailable.

Here are my matter server logs:

s6-rc: info: service s6rc-oneshot-runner: starting
s6-rc: info: service s6rc-oneshot-runner successfully started
s6-rc: info: service fix-attrs: starting
s6-rc: info: service banner: starting
s6-rc: info: service fix-attrs successfully started
s6-rc: info: service legacy-cont-init: starting
s6-rc: info: service legacy-cont-init successfully started

-----------------------------------------------------------
 Add-on: Matter Server
 Matter WebSocket Server for Home Assistant Matter support.
-----------------------------------------------------------
 Add-on version: 5.4.0
 You are running the latest version of this add-on.
 System: Home Assistant OS 12.0  (amd64 / qemux86-64)
 Home Assistant Core: 2024.2.5
 Home Assistant Supervisor: 2024.02.1
-----------------------------------------------------------
 Please, share the above information when looking for help
 or support in, e.g., GitHub, forums or the Discord chat.
-----------------------------------------------------------
s6-rc: info: service banner successfully started
s6-rc: info: service matter-server: starting
s6-rc: info: service matter-server successfully started
s6-rc: info: service legacy-services: starting
[12:01:20] INFO: Starting Matter Server...
s6-rc: info: service legacy-services successfully started
[12:01:21] INFO: Using 'enp0s18' as primary network interface.
[12:01:21] INFO: Successfully send discovery information to Home Assistant.
2024-03-03 12:01:22 (MainThread) INFO [matter_server.server.stack] Initializing CHIP/Matter Logging...
[1709463682.379589][125:125] CHIP:CTL: Setting attestation nonce to random value
[1709463682.379820][125:125] CHIP:CTL: Setting CSR nonce to random value
2024-03-03 12:01:22 (MainThread) INFO [matter_server.server.stack] Initializing CHIP/Matter Controller Stack...
2024-03-03 12:01:22 (MainThread) CHIP_ERROR [chip.native.DL] Failed to get WiFi interface
2024-03-03 12:01:22 (MainThread) CHIP_ERROR [chip.native.DL] Failed to reset WiFi statistic counts
2024-03-03 12:01:22 (MainThread) WARNING [PersistentStorage] Initializing persistent storage from file: /data/chip.json
2024-03-03 12:01:22 (MainThread) WARNING [PersistentStorage] Loading configuration from /data/chip.json...
2024-03-03 12:01:22 (MainThread) WARNING [CertificateAuthorityManager] Loading certificate authorities from storage...
2024-03-03 12:01:22 (MainThread) WARNING [CertificateAuthority] New CertificateAuthority at index 1
2024-03-03 12:01:22 (MainThread) WARNING [CertificateAuthority] Loading fabric admins from storage...
2024-03-03 12:01:22 (MainThread) WARNING [FabricAdmin] New FabricAdmin: FabricId: 0x0000000000000002, VendorId = 0x134B
2024-03-03 12:01:22 (MainThread) INFO [matter_server.server.stack] CHIP Controller Stack initialized.
2024-03-03 12:01:22 (MainThread) INFO [matter_server.server.server] Starting the Matter Server...
2024-03-03 12:01:22 (MainThread) INFO [matter_server.server.helpers.paa_certificates] Fetching the latest PAA root certificates from DCL.
2024-03-03 12:01:23 (ThreadPoolExecutor-0_0) WARNING [py.warnings] /usr/local/lib/python3.11/concurrent/futures/thread.py:58: CryptographyDeprecationWarning: The parsed certificate contains a NULL parameter value in its signature algorithm parameters. This is invalid and will be rejected in a future version of cryptography. If this certificate was created via Java, please upgrade to JDK21+ or the latest JDK11/17 once a fix is issued. If this certificate was created in some other fashion please report the issue to the cryptography issue tracker. See https://github.com/pyca/cryptography/issues/8996 and https://github.com/pyca/cryptography/issues/9253 for more details.
  result = self.fn(*self.args, **self.kwargs)

2024-03-03 12:01:32 (MainThread) INFO [matter_server.server.helpers.paa_certificates] Fetched 129 PAA root certificates from DCL.
2024-03-03 12:01:32 (MainThread) INFO [matter_server.server.helpers.paa_certificates] Fetching the latest PAA root certificates from Git.
2024-03-03 12:01:34 (MainThread) INFO [matter_server.server.helpers.paa_certificates] Fetched 90 PAA root certificates from Git.
2024-03-03 12:01:34 (MainThread) WARNING [FabricAdmin] Allocating new controller with CaIndex: 1, FabricId: 0x0000000000000002, NodeId: 0x000000000001B669, CatTags: []
2024-03-03 12:01:34 (MainThread) INFO [matter_server.server.device_controller] Loaded 2 nodes from stored configuration
2024-03-03 12:01:34 (MainThread) INFO [matter_server.server.vendor_info] Loading vendor info from storage.
2024-03-03 12:01:34 (MainThread) INFO [matter_server.server.vendor_info] Loaded 172 vendors from storage.
2024-03-03 12:01:34 (MainThread) INFO [matter_server.server.vendor_info] Fetching the latest vendor info from DCL.
2024-03-03 12:01:34 (MainThread) INFO [matter_server.server.device_controller] Node 2 (re)discovered on MDNS
2024-03-03 12:01:34 (MainThread) INFO [matter_server.server.device_controller] Setting-up node 2...
2024-03-03 12:01:34 (MainThread) INFO [matter_server.server.device_controller.node_2] Setting up attributes and events subscription.
2024-03-03 12:01:36 (MainThread) INFO [matter_server.server.vendor_info] Fetched 170 vendors from DCL.
2024-03-03 12:01:36 (MainThread) INFO [matter_server.server.vendor_info] Saving vendor info to storage.
2024-03-03 12:01:36 (MainThread) INFO [matter_server.server.device_controller.node_2] Subscription succeeded
2024-03-03 12:20:46 (MainThread) INFO [matter_server.server.device_controller.node_1] Node could not be discovered on the network, returning cached IP's
lambros414 commented 7 months ago

A new version of matter came out this morning - 5.4.0. I upgraded to that and it appears to have fixed the problem

Panzer1119 commented 7 months ago

A new version of matter came out this morning - 5.4.0. I upgraded to that and it appears to have fixed the problem

I'm also on this version, but it's broken.

lambros414 commented 7 months ago

I spoke too soon. after installing to 5.4.0 it did work for a while, but it is again, not working. So I concur with Panzer1119

marcelveldt commented 7 months ago

Please test of the latest beta matter server fixes this. In Matter server add-on settings, enable the toggle to enable beta versions. This will install the latest beta of matter server at startup of the add-on. You can watch the log and it should install matter server 5.6.1b3

lambros414 commented 7 months ago

Marceldt, I did what you suggested and toggled enable beta version. I did notice in the log that it said it was loading a pre-release version (didn't specify the version number). then went to the integration section and looked under the matter integration. It said it failed to load the integration. I restarted HA. it did start and was running then.

It did not solve the problem. when I look at my lock in the integration, it shows a green status and doesn't show a lock on the toggle (which it did before this problem happened (as an FYI).

I again toggled the enable beta version in add on section, and again, was not able to restart the integration, however after some time it did restart, but the control for the lock still did not work.

In short, it does not appear to be working in my case

lambros414 commented 7 months ago

I just updated home assistant core to 2024.3, and the matter seems to have gone away. my lock it is now responding to opening and closing commands as well as updating status when controlling manually. so I guess it is safe to close this issue then

lambros414 commented 7 months ago

Wow. Sorry to do this, but shortly after updating home assistant and the matter server. It did work briefly, but then stopped again, the same way. Trying to control the lock through home assistant is not working again, only after one hour post update. then after some time it started working. It isn't consistent. I believe there must be an issue still present because I can't depend on the integration controlling the lock or updating status.

marcelveldt commented 7 months ago

Please update to the latest Matter server add-on that has just been released, version 5.4.1

lambros414 commented 7 months ago

Hi. I did upgrade to 5.4.1 prior to the last comment where I mentioned it wasn't consistently working. I have been trying it more, and it seems to be more consistent. I'll see if it fails to respond throughout the day and if not, will close this issue. - but to summarize, after upgrading to 5.4.1 it did work for a while, stopped a for a while, and started working again.

lambros414 commented 7 months ago

It seems to be working better after upgrading to 5.4.1. Despite after the original upgrade, it stopped working for a while, it seems to be working as expected now. Will re-open if the issue resurfaces.

Thanks for your help and the fix@

Panzer1119 commented 7 months ago

It still doesn't work for me at all, since the plug became unavailable, it never came back according to the logbook.

I don't know if I should open another issue or reopen this one?

I am up-to-date afaik:

Core 2024.3.0 Supervisor 2024.02.1 Operating System 12.0 Matter Server 5.4.1

marcelveldt commented 7 months ago

Please create your own issue with all relevant details, including the log from the matter server.

lambros414 commented 7 months ago

So sorry, Re-opening it again as it isn't working for me again. don't know if it is different than others, but right now, it appears to be more of an intermittent problem - worked for an hour or so this morning, but when attempting to control the lock through HA just now, it isn't responsive. Again, looking at the switch on the matter dashboard, the lock usually shows an open/closed lock when it is working, and changes from green when locked to red when unlocked. Right now, not seeing any lock icons, and despite me flipping the switch, it stays green. I know you mentioned for Panzer1119 to open his own issues, but since I am reopening this one, don't know if another one is needed.

Also, would be happy to collect and send logs to you, but so far I haven't seen anything pertaining to the lock and the matter add-on/integration in the logs

marcelveldt commented 7 months ago

@lambros414 since you ar ethe original author of the issue its fine to re-open the closed issue if the issue came back. In the end it's not resolved. I think I have a clue what is going on for you. Can you give the latest beta version a try ? Enable the beta toggle in the add-on settings and at startup it should install 5.9.0b0 - let me know if that fixes the issue of sending commands.

amaisano commented 7 months ago

FWIW, I started having problems with my Aqara U100 lock this week after updating to core 2024.3.0 and Matter 5.4.1.

If I use a code in the the lock.lock service call i get the following error. If i do NOT use any code data, it works. The codes have not changed on my lock.

 File "/usr/src/homeassistant/homeassistant/components/lock/__init__.py", line 215, in async_handle_lock_service
    await self.async_lock(**self.add_default_code(kwargs))
  File "/usr/src/homeassistant/homeassistant/components/matter/lock.py", line 94, in async_lock
    await self.send_device_command(
  File "/usr/src/homeassistant/homeassistant/components/matter/lock.py", line 83, in send_device_command
    await self.matter_client.send_device_command(
  File "/usr/local/lib/python3.12/site-packages/matter_server/client/client.py", line 432, in send_device_command
    return await self.send_command(
           ^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/matter_server/client/client.py", line 540, in send_command
    return await future
           ^^^^^^^^^^^^
matter_server.common.errors.UnknownError: InteractionModelError: Failure (0x1)
lambros414 commented 7 months ago

I've installed install 5.9.0b0 and so far so good. seems to be working. I'll keep trying it after various amounts of time to see if I can consistently get it to work properly. if so, I'll close this one out.

Thanks for your efforts here!

lambros414 commented 7 months ago

5.9.0b0 beta version appears to have fixed the issue. Been playing with the lock for a few hours and it the matter add-on/integration and it hasn't failed once.

lambros414 commented 7 months ago

I think closing this issue is jinx. Right after closing it, I went in and tried the lock again. problem is back. Something slightly different this time. Although it isn't controlling the lock - I am seeing a lock icon now on the switch - which wasn't there before.

Net: Still having an intermittent problem with the integration not controlling my lock

lambros414 commented 7 months ago

So most recently.... was working for most of yesterday. got up this morning, and tried to lock/unlock from HA. no response. restarted add-on, integration, and home assistant as a whole. Still no response. then after about an hour or so, went back to it, and it is working again now. I don't know what has changed during that time. if there is something I could capture in a log, would be happy to share, but I haven't been seeing anything relevant (that I am aware of)

lambros414 commented 7 months ago

An update.... the intermittent working appears to have stopped and it is now just not working at all. Hasn't been for more than a day. I didn't update (but do have the option for beta matter add-on turned on, don't know if there has been a new beta version pushed out that could have been installed.

marcelveldt commented 7 months ago

I'm starting to think that there's an issue with your device or its connectivity ? When you cant control it from HA, can you still control it from the Aqara Hub itself ? Can you share the log of the Matter Server ?

lambros414 commented 7 months ago

I would be surprised if it is the device since it was working for a few weeks prior to the upgrade done that caused me to report the bug initially.

Woke up this morning and as of 7:15 am, it is working, at least for now.

I set the log collection to detail. I don't think things will help yet as the lock is currently working, but I'll share it now. I'll also share it again if/when it stops working.

Here is a current log - with it working:

Requirement already satisfied: rich in /usr/local/lib/python3.11/site-packages (from home-assistant-chip-core==2024.2.2->python-matter-server[server]) (13.7.1) Requirement already satisfied: pyyaml in /usr/local/lib/python3.11/site-packages (from home-assistant-chip-core==2024.2.2->python-matter-server[server]) (6.0.1) Requirement already satisfied: ipdb in /usr/local/lib/python3.11/site-packages (from home-assistant-chip-core==2024.2.2->python-matter-server[server]) (0.13.13) Requirement already satisfied: deprecation in /usr/local/lib/python3.11/site-packages (from home-assistant-chip-core==2024.2.2->python-matter-server[server]) (2.1.0) Requirement already satisfied: ecdsa in /usr/local/lib/python3.11/site-packages (from home-assistant-chip-core==2024.2.2->python-matter-server[server]) (0.18.0) Requirement already satisfied: ifaddr>=0.1.7 in /usr/local/lib/python3.11/site-packages (from zeroconf==0.131.0->python-matter-server[server]) (0.2.0) Requirement already satisfied: aiosignal>=1.1.2 in /usr/local/lib/python3.11/site-packages (from aiohttp->python-matter-server[server]) (1.3.1) Requirement already satisfied: attrs>=17.3.0 in /usr/local/lib/python3.11/site-packages (from aiohttp->python-matter-server[server]) (23.2.0) Requirement already satisfied: frozenlist>=1.1.1 in /usr/local/lib/python3.11/site-packages (from aiohttp->python-matter-server[server]) (1.4.1) Requirement already satisfied: multidict<7.0,>=4.5 in /usr/local/lib/python3.11/site-packages (from aiohttp->python-matter-server[server]) (6.0.5) Requirement already satisfied: yarl<2.0,>=1.0 in /usr/local/lib/python3.11/site-packages (from aiohttp->python-matter-server[server]) (1.9.4) Requirement already satisfied: humanfriendly>=9.1 in /usr/local/lib/python3.11/site-packages (from coloredlogs->python-matter-server[server]) (10.0) Requirement already satisfied: pycparser in /usr/local/lib/python3.11/site-packages (from cffi>=1.12->cryptography==42.0.5->python-matter-server[server]) (2.21) Requirement already satisfied: idna>=2.0 in /usr/local/lib/python3.11/site-packages (from yarl<2.0,>=1.0->aiohttp->python-matter-server[server]) (3.6) Requirement already satisfied: packaging in /usr/local/lib/python3.11/site-packages (from deprecation->home-assistant-chip-core==2024.2.2->python-matter-server[server]) (23.2) Requirement already satisfied: six>=1.9.0 in /usr/local/lib/python3.11/site-packages (from ecdsa->home-assistant-chip-core==2024.2.2->python-matter-server[server]) (1.16.0) Requirement already satisfied: ipython>=7.31.1 in /usr/local/lib/python3.11/site-packages (from ipdb->home-assistant-chip-core==2024.2.2->python-matter-server[server]) (8.22.2) Requirement already satisfied: decorator in /usr/local/lib/python3.11/site-packages (from ipdb->home-assistant-chip-core==2024.2.2->python-matter-server[server]) (5.1.1) Requirement already satisfied: markdown-it-py>=2.2.0 in /usr/local/lib/python3.11/site-packages (from rich->home-assistant-chip-core==2024.2.2->python-matter-server[server]) (3.0.0) Requirement already satisfied: pygments<3.0.0,>=2.13.0 in /usr/local/lib/python3.11/site-packages (from rich->home-assistant-chip-core==2024.2.2->python-matter-server[server]) (2.17.2) Requirement already satisfied: jedi>=0.16 in /usr/local/lib/python3.11/site-packages (from ipython>=7.31.1->ipdb->home-assistant-chip-core==2024.2.2->python-matter-server[server]) (0.19.1) Requirement already satisfied: matplotlib-inline in /usr/local/lib/python3.11/site-packages (from ipython>=7.31.1->ipdb->home-assistant-chip-core==2024.2.2->python-matter-server[server]) (0.1.6) Requirement already satisfied: prompt-toolkit<3.1.0,>=3.0.41 in /usr/local/lib/python3.11/site-packages (from ipython>=7.31.1->ipdb->home-assistant-chip-core==2024.2.2->python-matter-server[server]) (3.0.43) Requirement already satisfied: stack-data in /usr/local/lib/python3.11/site-packages (from ipython>=7.31.1->ipdb->home-assistant-chip-core==2024.2.2->python-matter-server[server]) (0.6.3) Requirement already satisfied: traitlets>=5.13.0 in /usr/local/lib/python3.11/site-packages (from ipython>=7.31.1->ipdb->home-assistant-chip-core==2024.2.2->python-matter-server[server]) (5.14.1) Requirement already satisfied: pexpect>4.3 in /usr/local/lib/python3.11/site-packages (from ipython>=7.31.1->ipdb->home-assistant-chip-core==2024.2.2->python-matter-server[server]) (4.9.0) Requirement already satisfied: mdurl~=0.1 in /usr/local/lib/python3.11/site-packages (from markdown-it-py>=2.2.0->rich->home-assistant-chip-core==2024.2.2->python-matter-server[server]) (0.1.2) Requirement already satisfied: parso<0.9.0,>=0.8.3 in /usr/local/lib/python3.11/site-packages (from jedi>=0.16->ipython>=7.31.1->ipdb->home-assistant-chip-core==2024.2.2->python-matter-server[server]) (0.8.3) Requirement already satisfied: ptyprocess>=0.5 in /usr/local/lib/python3.11/site-packages (from pexpect>4.3->ipython>=7.31.1->ipdb->home-assistant-chip-core==2024.2.2->python-matter-server[server]) (0.7.0) Requirement already satisfied: wcwidth in /usr/local/lib/python3.11/site-packages (from prompt-toolkit<3.1.0,>=3.0.41->ipython>=7.31.1->ipdb->home-assistant-chip-core==2024.2.2->python-matter-server[server]) (0.2.13) Requirement already satisfied: executing>=1.2.0 in /usr/local/lib/python3.11/site-packages (from stack-data->ipython>=7.31.1->ipdb->home-assistant-chip-core==2024.2.2->python-matter-server[server]) (2.0.1) Requirement already satisfied: asttokens>=2.1.0 in /usr/local/lib/python3.11/site-packages (from stack-data->ipython>=7.31.1->ipdb->home-assistant-chip-core==2024.2.2->python-matter-server[server]) (2.4.1) Requirement already satisfied: pure-eval in /usr/local/lib/python3.11/site-packages (from stack-data->ipython>=7.31.1->ipdb->home-assistant-chip-core==2024.2.2->python-matter-server[server]) (0.2.2) Downloading python_matter_server-5.9.0b0-py3-none-any.whl (99 kB) ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 99.6/99.6 kB 2.3 MB/s eta 0:00:00 Installing collected packages: python-matter-server Attempting uninstall: python-matter-server Found existing installation: python-matter-server 5.8.1 Uninstalling python-matter-server-5.8.1: Successfully uninstalled python-matter-server-5.8.1 Successfully installed python-matter-server-5.9.0b0 WARNING: Running pip as the 'root' user can result in broken permissions and conflicting behaviour with the system package manager. It is recommended to use a virtual environment instead: https://pip.pypa.io/warnings/venv [07:17:06] INFO: Using 'end0' as primary network interface. [07:17:07] INFO: Successfully send discovery information to Home Assistant. Reading symbols from /usr/local/bin/python... (No debugging symbols found in /usr/local/bin/python) Starting program: /usr/local/bin/python /usr/local/bin/matter-server --storage-path /data --port 5580 --log-level info --primary-interface end0 --fabricid 2 --vendorid 4939 --listen-address 172.30.32.1 [Thread debugging using libthread_db enabled] Using host libthread_db library "/lib/aarch64-linux-gnu/libthread_db.so.1". [New Thread 0x7ff44f01e0 (LWP 243)] [Detaching after vfork from child process 244] 2024-03-12 07:17:15 (MainThread) INFO [matter_server.server.stack] Initializing CHIP/Matter Logging... 2024-03-12 07:17:15 (MainThread) INFO [matter_server.server.stack] Initializing CHIP/Matter Controller Stack... [1710242247.892063][240:240] CHIP:CTL: Setting attestation nonce to random value [1710242247.912950][240:240] CHIP:CTL: Setting CSR nonce to random value [New Thread 0x7ff10191e0 (LWP 245)] [1710242248.043616][240:240] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs [1710242248.049087][240:240] CHIP:DL: writing settings to file (/tmp/chip_kvs-5SP0Oj) [1710242248.049432][240:240] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1710242248.050121][240:240] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /data/chip_factory.ini [1710242248.068430][240:240] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /data/chip_config.ini [1710242248.069614][240:240] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /data/chip_counters.ini [1710242248.075693][240:240] CHIP:DL: writing settings to file (/data/chip_counters.ini-aGpV0m) [1710242248.082951][240:240] CHIP:DL: renamed tmp file to file (/data/chip_counters.ini) [1710242248.083137][240:240] CHIP:DL: NVS set: chip-counters/reboot-count = 100 (0x64) [1710242248.084220][240:240] CHIP:DL: Got Ethernet interface: end0 [1710242248.085130][240:240] CHIP:DL: Found the primary Ethernet interface:end0 [1710242248.086125][240:240] CHIP:DL: Got WiFi interface: wlan0 [1710242248.092550][240:240] CHIP:DL: Found the primary WiFi interface:wlan0 2024-03-12 07:17:28 (MainThread) WARNING [PersistentStorage] Initializing persistent storage from file: /data/chip.json 2024-03-12 07:17:28 (MainThread) WARNING [PersistentStorage] Loading configuration from /data/chip.json... [New Thread 0x7ff08181e0 (LWP 246)] 2024-03-12 07:17:28 (MainThread) WARNING [CertificateAuthorityManager] Loading certificate authorities from storage... 2024-03-12 07:17:28 (MainThread) WARNING [CertificateAuthority] New CertificateAuthority at index 1 2024-03-12 07:17:28 (MainThread) WARNING [CertificateAuthority] Loading fabric admins from storage... 2024-03-12 07:17:28 (MainThread) WARNING [FabricAdmin] New FabricAdmin: FabricId: 0x0000000000000002, VendorId = 0x134B 2024-03-12 07:17:28 (MainThread) INFO [matter_server.server.stack] CHIP Controller Stack initialized. 2024-03-12 07:17:28 (MainThread) INFO [matter_server.server.server] Starting the Matter Server... [New Thread 0x7fe3fff1e0 (LWP 247)] 2024-03-12 07:17:28 (MainThread) INFO [matter_server.server.helpers.paa_certificates] Fetching the latest PAA root certificates from DCL. 2024-03-12 07:17:29 (ThreadPoolExecutor-0_0) WARNING [py.warnings] /usr/local/lib/python3.11/concurrent/futures/thread.py:58: CryptographyDeprecationWarning: The parsed certificate contains a NULL parameter value in its signature algorithm parameters. This is invalid and will be rejected in a future version of cryptography. If this certificate was created via Java, please upgrade to JDK21+ or the latest JDK11/17 once a fix is issued. If this certificate was created in some other fashion please report the issue to the cryptography issue tracker. See https://github.com/pyca/cryptography/issues/8996 and https://github.com/pyca/cryptography/issues/9253 for more details. result = self.fn(*self.args, **self.kwargs)

2024-03-12 07:17:35 (MainThread) INFO [matter_server.server.helpers.paa_certificates] Fetched 129 PAA root certificates from DCL. 2024-03-12 07:17:35 (MainThread) INFO [matter_server.server.helpers.paa_certificates] Fetching the latest PAA root certificates from Git. 2024-03-12 07:17:40 (MainThread) INFO [matter_server.server.helpers.paa_certificates] Fetched 90 PAA root certificates from Git. 2024-03-12 07:17:40 (MainThread) WARNING [FabricAdmin] Allocating new controller with CaIndex: 1, FabricId: 0x0000000000000002, NodeId: 0x000000000001B669, CatTags: [] 2024-03-12 07:17:41 (Dummy-2) CHIP_ERROR [chip.native.DL] Long dispatch time: 742 ms, for event type 2 2024-03-12 07:17:41 (MainThread) INFO [matter_server.server.device_controller] Loaded 1 nodes from stored configuration 2024-03-12 07:17:41 (MainThread) INFO [matter_server.server.vendor_info] Loading vendor info from storage. 2024-03-12 07:17:41 (MainThread) INFO [matter_server.server.vendor_info] Loaded 178 vendors from storage. 2024-03-12 07:17:41 (MainThread) INFO [matter_server.server.vendor_info] Fetching the latest vendor info from DCL. 2024-03-12 07:17:41 (MainThread) INFO [matter_server.server.vendor_info] Fetched 176 vendors from DCL. 2024-03-12 07:17:41 (MainThread) INFO [matter_server.server.vendor_info] Saving vendor info to storage. 2024-03-12 07:17:42 (MainThread) INFO [matter_server.server.device_controller.mdns] Node 19 discovered on MDNS 2024-03-12 07:17:42 (MainThread) INFO [matter_server.server.device_controller.node_19] Setting-up node... 2024-03-12 07:17:42 (MainThread) INFO [matter_server.server.device_controller.node_19] Setting up attributes and events subscription. 2024-03-12 07:17:47 (Dummy-2) CHIP_ERROR [chip.native.EM] Failed to Send CHIP MessageCounter:102168796 on exchange 7850i sendCount: 4 max retries: 4 2024-03-12 07:17:49 (Dummy-2) CHIP_ERROR [chip.native.DMG] Time out! failed to receive report data from Exchange: 7850i 2024-03-12 07:17:50 (MainThread) INFO [matter_server.server.device_controller.node_19] Subscription succeeded

lambros414 commented 7 months ago

As of 7:40, it has stopped working. below is the log. I am noticing a few lines showing chip error near the bottom of the log. is that at all telling something about my lock? If so, please give me your thoughts. I purchased this from Amazon last month, and still have till the 17th of this month to return/exchange.

Requirement already satisfied: rich in /usr/local/lib/python3.11/site-packages (from home-assistant-chip-core==2024.2.2->python-matter-server[server]) (13.7.1) Requirement already satisfied: pyyaml in /usr/local/lib/python3.11/site-packages (from home-assistant-chip-core==2024.2.2->python-matter-server[server]) (6.0.1) Requirement already satisfied: ipdb in /usr/local/lib/python3.11/site-packages (from home-assistant-chip-core==2024.2.2->python-matter-server[server]) (0.13.13) Requirement already satisfied: deprecation in /usr/local/lib/python3.11/site-packages (from home-assistant-chip-core==2024.2.2->python-matter-server[server]) (2.1.0) Requirement already satisfied: ecdsa in /usr/local/lib/python3.11/site-packages (from home-assistant-chip-core==2024.2.2->python-matter-server[server]) (0.18.0) Requirement already satisfied: ifaddr>=0.1.7 in /usr/local/lib/python3.11/site-packages (from zeroconf==0.131.0->python-matter-server[server]) (0.2.0) Requirement already satisfied: aiosignal>=1.1.2 in /usr/local/lib/python3.11/site-packages (from aiohttp->python-matter-server[server]) (1.3.1) Requirement already satisfied: attrs>=17.3.0 in /usr/local/lib/python3.11/site-packages (from aiohttp->python-matter-server[server]) (23.2.0) Requirement already satisfied: frozenlist>=1.1.1 in /usr/local/lib/python3.11/site-packages (from aiohttp->python-matter-server[server]) (1.4.1) Requirement already satisfied: multidict<7.0,>=4.5 in /usr/local/lib/python3.11/site-packages (from aiohttp->python-matter-server[server]) (6.0.5) Requirement already satisfied: yarl<2.0,>=1.0 in /usr/local/lib/python3.11/site-packages (from aiohttp->python-matter-server[server]) (1.9.4) Requirement already satisfied: humanfriendly>=9.1 in /usr/local/lib/python3.11/site-packages (from coloredlogs->python-matter-server[server]) (10.0) Requirement already satisfied: pycparser in /usr/local/lib/python3.11/site-packages (from cffi>=1.12->cryptography==42.0.5->python-matter-server[server]) (2.21) Requirement already satisfied: idna>=2.0 in /usr/local/lib/python3.11/site-packages (from yarl<2.0,>=1.0->aiohttp->python-matter-server[server]) (3.6) Requirement already satisfied: packaging in /usr/local/lib/python3.11/site-packages (from deprecation->home-assistant-chip-core==2024.2.2->python-matter-server[server]) (23.2) Requirement already satisfied: six>=1.9.0 in /usr/local/lib/python3.11/site-packages (from ecdsa->home-assistant-chip-core==2024.2.2->python-matter-server[server]) (1.16.0) Requirement already satisfied: ipython>=7.31.1 in /usr/local/lib/python3.11/site-packages (from ipdb->home-assistant-chip-core==2024.2.2->python-matter-server[server]) (8.22.2) Requirement already satisfied: decorator in /usr/local/lib/python3.11/site-packages (from ipdb->home-assistant-chip-core==2024.2.2->python-matter-server[server]) (5.1.1) Requirement already satisfied: markdown-it-py>=2.2.0 in /usr/local/lib/python3.11/site-packages (from rich->home-assistant-chip-core==2024.2.2->python-matter-server[server]) (3.0.0) Requirement already satisfied: pygments<3.0.0,>=2.13.0 in /usr/local/lib/python3.11/site-packages (from rich->home-assistant-chip-core==2024.2.2->python-matter-server[server]) (2.17.2) Requirement already satisfied: jedi>=0.16 in /usr/local/lib/python3.11/site-packages (from ipython>=7.31.1->ipdb->home-assistant-chip-core==2024.2.2->python-matter-server[server]) (0.19.1) Requirement already satisfied: matplotlib-inline in /usr/local/lib/python3.11/site-packages (from ipython>=7.31.1->ipdb->home-assistant-chip-core==2024.2.2->python-matter-server[server]) (0.1.6) Requirement already satisfied: prompt-toolkit<3.1.0,>=3.0.41 in /usr/local/lib/python3.11/site-packages (from ipython>=7.31.1->ipdb->home-assistant-chip-core==2024.2.2->python-matter-server[server]) (3.0.43) Requirement already satisfied: stack-data in /usr/local/lib/python3.11/site-packages (from ipython>=7.31.1->ipdb->home-assistant-chip-core==2024.2.2->python-matter-server[server]) (0.6.3) Requirement already satisfied: traitlets>=5.13.0 in /usr/local/lib/python3.11/site-packages (from ipython>=7.31.1->ipdb->home-assistant-chip-core==2024.2.2->python-matter-server[server]) (5.14.1) Requirement already satisfied: pexpect>4.3 in /usr/local/lib/python3.11/site-packages (from ipython>=7.31.1->ipdb->home-assistant-chip-core==2024.2.2->python-matter-server[server]) (4.9.0) Requirement already satisfied: mdurl~=0.1 in /usr/local/lib/python3.11/site-packages (from markdown-it-py>=2.2.0->rich->home-assistant-chip-core==2024.2.2->python-matter-server[server]) (0.1.2) Requirement already satisfied: parso<0.9.0,>=0.8.3 in /usr/local/lib/python3.11/site-packages (from jedi>=0.16->ipython>=7.31.1->ipdb->home-assistant-chip-core==2024.2.2->python-matter-server[server]) (0.8.3) Requirement already satisfied: ptyprocess>=0.5 in /usr/local/lib/python3.11/site-packages (from pexpect>4.3->ipython>=7.31.1->ipdb->home-assistant-chip-core==2024.2.2->python-matter-server[server]) (0.7.0) Requirement already satisfied: wcwidth in /usr/local/lib/python3.11/site-packages (from prompt-toolkit<3.1.0,>=3.0.41->ipython>=7.31.1->ipdb->home-assistant-chip-core==2024.2.2->python-matter-server[server]) (0.2.13) Requirement already satisfied: executing>=1.2.0 in /usr/local/lib/python3.11/site-packages (from stack-data->ipython>=7.31.1->ipdb->home-assistant-chip-core==2024.2.2->python-matter-server[server]) (2.0.1) Requirement already satisfied: asttokens>=2.1.0 in /usr/local/lib/python3.11/site-packages (from stack-data->ipython>=7.31.1->ipdb->home-assistant-chip-core==2024.2.2->python-matter-server[server]) (2.4.1) Requirement already satisfied: pure-eval in /usr/local/lib/python3.11/site-packages (from stack-data->ipython>=7.31.1->ipdb->home-assistant-chip-core==2024.2.2->python-matter-server[server]) (0.2.2) Downloading python_matter_server-5.9.0b0-py3-none-any.whl (99 kB) ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 99.6/99.6 kB 2.3 MB/s eta 0:00:00 Installing collected packages: python-matter-server Attempting uninstall: python-matter-server Found existing installation: python-matter-server 5.8.1 Uninstalling python-matter-server-5.8.1: Successfully uninstalled python-matter-server-5.8.1 Successfully installed python-matter-server-5.9.0b0 WARNING: Running pip as the 'root' user can result in broken permissions and conflicting behaviour with the system package manager. It is recommended to use a virtual environment instead: https://pip.pypa.io/warnings/venv [07:17:06] INFO: Using 'end0' as primary network interface. [07:17:07] INFO: Successfully send discovery information to Home Assistant. Reading symbols from /usr/local/bin/python... (No debugging symbols found in /usr/local/bin/python) Starting program: /usr/local/bin/python /usr/local/bin/matter-server --storage-path /data --port 5580 --log-level info --primary-interface end0 --fabricid 2 --vendorid 4939 --listen-address 172.30.32.1 [Thread debugging using libthread_db enabled] Using host libthread_db library "/lib/aarch64-linux-gnu/libthread_db.so.1". [New Thread 0x7ff44f01e0 (LWP 243)] [Detaching after vfork from child process 244] 2024-03-12 07:17:15 (MainThread) INFO [matter_server.server.stack] Initializing CHIP/Matter Logging... 2024-03-12 07:17:15 (MainThread) INFO [matter_server.server.stack] Initializing CHIP/Matter Controller Stack... [1710242247.892063][240:240] CHIP:CTL: Setting attestation nonce to random value [1710242247.912950][240:240] CHIP:CTL: Setting CSR nonce to random value [New Thread 0x7ff10191e0 (LWP 245)] [1710242248.043616][240:240] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs [1710242248.049087][240:240] CHIP:DL: writing settings to file (/tmp/chip_kvs-5SP0Oj) [1710242248.049432][240:240] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1710242248.050121][240:240] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /data/chip_factory.ini [1710242248.068430][240:240] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /data/chip_config.ini [1710242248.069614][240:240] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /data/chip_counters.ini [1710242248.075693][240:240] CHIP:DL: writing settings to file (/data/chip_counters.ini-aGpV0m) [1710242248.082951][240:240] CHIP:DL: renamed tmp file to file (/data/chip_counters.ini) [1710242248.083137][240:240] CHIP:DL: NVS set: chip-counters/reboot-count = 100 (0x64) [1710242248.084220][240:240] CHIP:DL: Got Ethernet interface: end0 [1710242248.085130][240:240] CHIP:DL: Found the primary Ethernet interface:end0 [1710242248.086125][240:240] CHIP:DL: Got WiFi interface: wlan0 [1710242248.092550][240:240] CHIP:DL: Found the primary WiFi interface:wlan0 2024-03-12 07:17:28 (MainThread) WARNING [PersistentStorage] Initializing persistent storage from file: /data/chip.json 2024-03-12 07:17:28 (MainThread) WARNING [PersistentStorage] Loading configuration from /data/chip.json... [New Thread 0x7ff08181e0 (LWP 246)] 2024-03-12 07:17:28 (MainThread) WARNING [CertificateAuthorityManager] Loading certificate authorities from storage... 2024-03-12 07:17:28 (MainThread) WARNING [CertificateAuthority] New CertificateAuthority at index 1 2024-03-12 07:17:28 (MainThread) WARNING [CertificateAuthority] Loading fabric admins from storage... 2024-03-12 07:17:28 (MainThread) WARNING [FabricAdmin] New FabricAdmin: FabricId: 0x0000000000000002, VendorId = 0x134B 2024-03-12 07:17:28 (MainThread) INFO [matter_server.server.stack] CHIP Controller Stack initialized. 2024-03-12 07:17:28 (MainThread) INFO [matter_server.server.server] Starting the Matter Server... [New Thread 0x7fe3fff1e0 (LWP 247)] 2024-03-12 07:17:28 (MainThread) INFO [matter_server.server.helpers.paa_certificates] Fetching the latest PAA root certificates from DCL. 2024-03-12 07:17:29 (ThreadPoolExecutor-0_0) WARNING [py.warnings] /usr/local/lib/python3.11/concurrent/futures/thread.py:58: CryptographyDeprecationWarning: The parsed certificate contains a NULL parameter value in its signature algorithm parameters. This is invalid and will be rejected in a future version of cryptography. If this certificate was created via Java, please upgrade to JDK21+ or the latest JDK11/17 once a fix is issued. If this certificate was created in some other fashion please report the issue to the cryptography issue tracker. See https://github.com/pyca/cryptography/issues/8996 and https://github.com/pyca/cryptography/issues/9253 for more details. result = self.fn(*self.args, **self.kwargs)

2024-03-12 07:17:35 (MainThread) INFO [matter_server.server.helpers.paa_certificates] Fetched 129 PAA root certificates from DCL. 2024-03-12 07:17:35 (MainThread) INFO [matter_server.server.helpers.paa_certificates] Fetching the latest PAA root certificates from Git. 2024-03-12 07:17:40 (MainThread) INFO [matter_server.server.helpers.paa_certificates] Fetched 90 PAA root certificates from Git. 2024-03-12 07:17:40 (MainThread) WARNING [FabricAdmin] Allocating new controller with CaIndex: 1, FabricId: 0x0000000000000002, NodeId: 0x000000000001B669, CatTags: [] 2024-03-12 07:17:41 (Dummy-2) CHIP_ERROR [chip.native.DL] Long dispatch time: 742 ms, for event type 2 2024-03-12 07:17:41 (MainThread) INFO [matter_server.server.device_controller] Loaded 1 nodes from stored configuration 2024-03-12 07:17:41 (MainThread) INFO [matter_server.server.vendor_info] Loading vendor info from storage. 2024-03-12 07:17:41 (MainThread) INFO [matter_server.server.vendor_info] Loaded 178 vendors from storage. 2024-03-12 07:17:41 (MainThread) INFO [matter_server.server.vendor_info] Fetching the latest vendor info from DCL. 2024-03-12 07:17:41 (MainThread) INFO [matter_server.server.vendor_info] Fetched 176 vendors from DCL. 2024-03-12 07:17:41 (MainThread) INFO [matter_server.server.vendor_info] Saving vendor info to storage. 2024-03-12 07:17:42 (MainThread) INFO [matter_server.server.device_controller.mdns] Node 19 discovered on MDNS 2024-03-12 07:17:42 (MainThread) INFO [matter_server.server.device_controller.node_19] Setting-up node... 2024-03-12 07:17:42 (MainThread) INFO [matter_server.server.device_controller.node_19] Setting up attributes and events subscription. 2024-03-12 07:17:47 (Dummy-2) CHIP_ERROR [chip.native.EM] Failed to Send CHIP MessageCounter:102168796 on exchange 7850i sendCount: 4 max retries: 4 2024-03-12 07:17:49 (Dummy-2) CHIP_ERROR [chip.native.DMG] Time out! failed to receive report data from Exchange: 7850i 2024-03-12 07:17:50 (MainThread) INFO [matter_server.server.device_controller.node_19] Subscription succeeded

marcelveldt commented 7 months ago

Can you share the relevant log (near 7:40) as this part is not useful

lambros414 commented 7 months ago

at 16:21, the above is the last entry in matter log. there are no more entries.

I changed the log collection to debug (it was set to info before). I then tried a few times to control the lock from the matter device page, and the below log was created.... real time. Hope this is more helpful...

} 2024-03-12 16:21:46 (MainThread) DEBUG [matter_server.server.client_handler] [549277151760] Received CommandMessage(message_id='5471487f9c05483ea48334d34859b056', command='subscribe_attribute', args={'node_id': 19, 'attribute_path': ['4/47/12']}) 2024-03-12 16:21:46 (MainThread) DEBUG [matter_server.server.client_handler] [549277151760] Handling command subscribe_attribute 2024-03-12 16:21:46 (MainThread) DEBUG [matter_server.server.device_controller] The subscribe_attribute command has been deprecated and will be removed from a future version. You no longer need to call this to subscribe to attribute changes. 2024-03-12 16:22:09 (MainThread) DEBUG [matter_server.server.client_handler] [549277151760] Received: { "message_id": "ff5218c342b74ddb982d33ccacde11b3", "command": "device_command", "args": { "node_id": 19, "endpoint_id": 4, "cluster_id": 257, "command_name": "UnlockDoor", "payload": { "PINCode": null }, "response_type": null, "timed_request_timeout_ms": 1000, "interaction_timeout_ms": null } } 2024-03-12 16:22:09 (MainThread) DEBUG [matter_server.server.client_handler] [549277151760] Received CommandMessage(message_id='ff5218c342b74ddb982d33ccacde11b3', command='device_command', args={'node_id': 19, 'endpoint_id': 4, 'cluster_id': 257, 'command_name': 'UnlockDoor', 'payload': {'PINCode': None}, 'response_type': None, 'timed_request_timeout_ms': 1000, 'interaction_timeout_ms': None}) 2024-03-12 16:22:09 (MainThread) DEBUG [matter_server.server.client_handler] [549277151760] Handling command device_command 2024-03-12 16:22:09 (Dummy-2) DEBUG [matter_server.server.device_controller.node_19] Received node event: EventReadResult(Header=EventHeader(EndpointId=4, ClusterId=257, EventId=2, EventNumber=787148, Priority=<EventPriority.CRITICAL: 2>, Timestamp=1981667267, TimestampType=<EventTimestampType.SYSTEM: 0>), Status=<Status.Success: 0>, Data=DoorLock.Events.LockOperation(lockOperationType=<LockOperationTypeEnum.kUnlock: 1>, operationSource=<OperationSourceEnum.kRemote: 7>, userIndex=Null, fabricIndex=3, sourceNode=112233, credentials=[])) - transaction: <Subscription (Id=4279775250)> 2024-03-12 16:22:11 (MainThread) DEBUG [matter_server.server.client_handler] [549277151760] Received: { "message_id": "98689c039b6e430fbc3c2931868d9c71", "command": "device_command", "args": { "node_id": 19, "endpoint_id": 4, "cluster_id": 257, "command_name": "LockDoor", "payload": { "PINCode": null }, "response_type": null, "timed_request_timeout_ms": 1000, "interaction_timeout_ms": null } } 2024-03-12 16:22:11 (MainThread) DEBUG [matter_server.server.client_handler] [549277151760] Received CommandMessage(message_id='98689c039b6e430fbc3c2931868d9c71', command='device_command', args={'node_id': 19, 'endpoint_id': 4, 'cluster_id': 257, 'command_name': 'LockDoor', 'payload': {'PINCode': None}, 'response_type': None, 'timed_request_timeout_ms': 1000, 'interaction_timeout_ms': None}) 2024-03-12 16:22:11 (MainThread) DEBUG [matter_server.server.client_handler] [549277151760] Handling command device_command 2024-03-12 16:22:11 (Dummy-2) DEBUG [matter_server.server.device_controller.node_19] Received node event: EventReadResult(Header=EventHeader(EndpointId=4, ClusterId=257, EventId=2, EventNumber=787149, Priority=<EventPriority.CRITICAL: 2>, Timestamp=1981669941, TimestampType=<EventTimestampType.SYSTEM: 0>), Status=<Status.Success: 0>, Data=DoorLock.Events.LockOperation(lockOperationType=<LockOperationTypeEnum.kLock: 0>, operationSource=<OperationSourceEnum.kRemote: 7>, userIndex=Null, fabricIndex=3, sourceNode=112233, credentials=[])) - transaction: <Subscription (Id=4279775250)> 2024-03-12 16:22:13 (MainThread) DEBUG [matter_server.server.client_handler] [549277151760] Received: { "message_id": "4ca69472e15d4edbb32e9c5fc5968e4e", "command": "device_command", "args": { "node_id": 19, "endpoint_id": 4, "cluster_id": 257, "command_name": "UnlockDoor", "payload": { "PINCode": null }, "response_type": null, "timed_request_timeout_ms": 1000, "interaction_timeout_ms": null } } 2024-03-12 16:22:13 (MainThread) DEBUG [matter_server.server.client_handler] [549277151760] Received CommandMessage(message_id='4ca69472e15d4edbb32e9c5fc5968e4e', command='device_command', args={'node_id': 19, 'endpoint_id': 4, 'cluster_id': 257, 'command_name': 'UnlockDoor', 'payload': {'PINCode': None}, 'response_type': None, 'timed_request_timeout_ms': 1000, 'interaction_timeout_ms': None}) 2024-03-12 16:22:13 (MainThread) DEBUG [matter_server.server.client_handler] [549277151760] Handling command device_command 2024-03-12 16:22:13 (Dummy-2) DEBUG [matter_server.server.device_controller.node_19] Received node event: EventReadResult(Header=EventHeader(EndpointId=4, ClusterId=257, EventId=2, EventNumber=787150, Priority=<EventPriority.CRITICAL: 2>, Timestamp=1981671257, TimestampType=<EventTimestampType.SYSTEM: 0>), Status=<Status.Success: 0>, Data=DoorLock.Events.LockOperation(lockOperationType=<LockOperationTypeEnum.kUnlock: 1>, operationSource=<OperationSourceEnum.kRemote: 7>, userIndex=Null, fabricIndex=3, sourceNode=112233, credentials=[])) - transaction: <Subscription (Id=4279775250)> 2024-03-12 16:23:20 (MainThread) DEBUG [matter_server.server.client_handler] [549277151760] Received: { "message_id": "939e50a1cc11492e989b32e667661ee7", "command": "device_command", "args": { "node_id": 19, "endpoint_id": 4, "cluster_id": 257, "command_name": "UnlockDoor", "payload": { "PINCode": null }, "response_type": null, "timed_request_timeout_ms": 1000, "interaction_timeout_ms": null } } 2024-03-12 16:23:20 (MainThread) DEBUG [matter_server.server.client_handler] [549277151760] Received CommandMessage(message_id='939e50a1cc11492e989b32e667661ee7', command='device_command', args={'node_id': 19, 'endpoint_id': 4, 'cluster_id': 257, 'command_name': 'UnlockDoor', 'payload': {'PINCode': None}, 'response_type': None, 'timed_request_timeout_ms': 1000, 'interaction_timeout_ms': None}) 2024-03-12 16:23:20 (MainThread) DEBUG [matter_server.server.client_handler] [549277151760] Handling command device_command 2024-03-12 16:23:20 (Dummy-2) DEBUG [matter_server.server.device_controller.node_19] Received node event: EventReadResult(Header=EventHeader(EndpointId=4, ClusterId=257, EventId=2, EventNumber=787151, Priority=<EventPriority.CRITICAL: 2>, Timestamp=1981738971, TimestampType=<EventTimestampType.SYSTEM: 0>), Status=<Status.Success: 0>, Data=DoorLock.Events.LockOperation(lockOperationType=<LockOperationTypeEnum.kUnlock: 1>, operationSource=<OperationSourceEnum.kRemote: 7>, userIndex=Null, fabricIndex=3, sourceNode=112233, credentials=[])) - transaction: <Subscription (Id=4279775250)> 2024-03-12 16:23:20 (ThreadPoolExecutor-0_0) DEBUG [matter_server.server.storage] Saved data to persistent storage 2024-03-12 16:23:22 (MainThread) DEBUG [matter_server.server.client_handler] [549277151760] Received: { "message_id": "09e8adee4f1c43b4b3bd06de969c6cf5", "command": "device_command", "args": { "node_id": 19, "endpoint_id": 4, "cluster_id": 257, "command_name": "LockDoor", "payload": { "PINCode": null }, "response_type": null, "timed_request_timeout_ms": 1000, "interaction_timeout_ms": null } } 2024-03-12 16:23:22 (MainThread) DEBUG [matter_server.server.client_handler] [549277151760] Received CommandMessage(message_id='09e8adee4f1c43b4b3bd06de969c6cf5', command='device_command', args={'node_id': 19, 'endpoint_id': 4, 'cluster_id': 257, 'command_name': 'LockDoor', 'payload': {'PINCode': None}, 'response_type': None, 'timed_request_timeout_ms': 1000, 'interaction_timeout_ms': None}) 2024-03-12 16:23:22 (MainThread) DEBUG [matter_server.server.client_handler] [549277151760] Handling command device_command 2024-03-12 16:23:22 (Dummy-2) DEBUG [matter_server.server.device_controller.node_19] Received node event: EventReadResult(Header=EventHeader(EndpointId=4, ClusterId=257, EventId=2, EventNumber=787152, Priority=<EventPriority.CRITICAL: 2>, Timestamp=1981740840, TimestampType=<EventTimestampType.SYSTEM: 0>), Status=<Status.Success: 0>, Data=DoorLock.Events.LockOperation(lockOperationType=<LockOperationTypeEnum.kLock: 0>, operationSource=<OperationSourceEnum.kRemote: 7>, userIndex=Null, fabricIndex=3, sourceNode=112233, credentials=[])) - transaction: <Subscription (Id=4279775250)>

lambros414 commented 7 months ago

marcelveldt,

Any thoughts since I shared the last log file. I am thinking of exchanging the lock for another one of the same kind in case there is something wrong with my lock. I have been reluctant to do this because [amaisano] has also been experiencing problems with this same brand lock.

If you do indeed think there could be a communication issue with regards to the lock, I would need to exchange it very soon as the exchange period within Amazon is about to expire.

Any input would be greatly appreciated.

marcelveldt commented 7 months ago

Your logs are still not very helpful tbh, sorry. There really is no need for debug logs unless explicitly asked, they are very verbose. The partial logs you shared above look fine, like nothing is wrong and everything is working. What EXACTLY is the issue with the lock ?

Can you grab the full log perhaps from start to finish ?

To show more log lines of the Python Matter Server add-on you can use this CLI command (e.g. in the Terminal & SSH add-on): ha host logs --identifier addon_core_matter_server -n 10000

To store it in a file in the config directory (to download via VS Code add-on/Samba add-on) you can redirect the logs into a log file using: ha host logs --identifier addon_core_matter_server -n 10000 > /config/matter.log

(you can increase/decrease the number of lines depending on need)

lambros414 commented 7 months ago

Your logs are still not very helpful tbh, sorry. There really is no need for debug logs unless explicitly asked, they are very verbose. The partial logs you shared above look fine, like nothing is wrong and everything is working. What EXACTLY is the issue with the lock ?

Can you grab the full log perhaps from start to finish ?

To show more log lines of the Python Matter Server add-on you can use this CLI command (e.g. in the Terminal & SSH add-on): ha host logs --identifier addon_core_matter_server -n 10000

To store it in a file in the config directory (to download via VS Code add-on/Samba add-on) you can redirect the logs into a log file using: ha host logs --identifier addon_core_matter_server -n 10000 > /config/matter.log

(you can increase/decrease the number of lines depending on need)

To answer to your question on what EXACTLY the issue with the lock..... When I issue a command from HA to open or close the lock, from the matter integration page - showing the device, it does not respond in any way. The page shows the lock opening/closing, but the lock doesn't respond. When I open/close the lock manually, or through the app that comes with the lock - it works, but the status doesn't update. Can't be controlled from HA or have correct status shown by HA.

I executed the command line command you recommended and got a lot of lines in it. I would assume it may be too big to upload, but will try... Please let me know if it give you what you may need or what I should look for to assist.

matter.log

lambros414 commented 7 months ago

I thought I would add a little more information. It appears again to be intermittently working. Right now, as of 7:33 on Thursday, the lock is able to be controlled from HA and the status is being updated. In case it helps in any way, I am attaching a log file with the last 100 lines of the log to show it working, to see if there is any difference between this log and the previous one I included where it was not working matter-working.log

lambros414 commented 7 months ago

I don't know if anything has been changed. I haven't received any updates on my previous posts, but since my last post 2 days ago the my lock has been consistently working. since then. I'll close the issue for now as I don't want to leave things open. if it reappears, I'll reopen the bug.

If any modifications have been made, thanks for the assistance!