Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Node not available after upgrade #685

Open
olavt opened this issue May 1, 2024 · 7 comments
Open

Node not available after upgrade #685

olavt opened this issue May 1, 2024 · 7 comments

Comments

@olavt
Copy link

olavt commented May 1, 2024 •
edited
Loading

I just upgraded from 5.9.0 to 5.10.0 by doing this:

  1. Pulled down the 5.10.0 Docker image
  2. Stopped the running 5.9.0 Docker container
  3. Started a new 5.10.0 Docker container

Now, the Matter over Threads node that was available when running 5.9.0 is no longer available with 5.10.0.

2024-05-01 20:29:30.634 (MainThread) ERROR [matter_server.server.client_handler] [547834610000] Error while handling: read_attribute (node 1): Node 1 is not (yet) available.

I guess this is a bug somewhere.

To fix the issue I did the following:

  1. Stopped the 5.10.0 Docker container
  2. Deleted the files in the data directory
  3. Started the 5.10.0 Docker container
  4. Called SetThreadDataset
  5. Added the Matter over Thread device
@olavt
Copy link
Author

olavt commented May 10, 2024

I did the same upgrade on another installation today with the same results.

Here's the complete log:

2024-05-10 06:30:51.304 (MainThread) INFO [matter_server.server.stack] Initializing CHIP/Matter Logging...
2024-05-10 06:30:51.305 (MainThread) INFO [matter_server.server.stack] Initializing CHIP/Matter Controller Stack...
[1715322651.379540][1:1] CHIP:CTL: Setting attestation nonce to random value
[1715322651.380135][1:1] CHIP:CTL: Setting CSR nonce to random value
[1715322651.382297][1:1] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs
[1715322651.382859][1:1] CHIP:DL: writing settings to file (/tmp/chip_kvs-mkvBcg)
[1715322651.383003][1:1] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs)
[1715322651.383401][1:1] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /data/chip_factory.ini
[1715322651.383748][1:1] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /data/chip_config.ini
[1715322651.383840][1:1] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /data/chip_counters.ini
[1715322651.384194][1:1] CHIP:DL: writing settings to file (/data/chip_counters.ini-bkgqSi)
[1715322651.384619][1:1] CHIP:DL: renamed tmp file to file (/data/chip_counters.ini)
[1715322651.384662][1:1] CHIP:DL: NVS set: chip-counters/reboot-count = 4 (0x4)
[1715322651.385189][1:1] CHIP:DL: Got Ethernet interface: eth0
[1715322651.385496][1:1] CHIP:DL: Found the primary Ethernet interface:eth0
[1715322651.385817][1:1] CHIP:DL: Got WiFi interface: wlan0
[1715322651.385859][1:1] CHIP:DL: Failed to reset WiFi statistic counts
2024-05-10 06:30:51.386 (MainThread) WARNING [PersistentStorage] Initializing persistent storage from file: /data/chip.json
2024-05-10 06:30:51.387 (MainThread) WARNING [PersistentStorage] Loading configuration from /data/chip.json...
2024-05-10 06:30:51.585 (MainThread) WARNING [CertificateAuthorityManager] Loading certificate authorities from storage...
2024-05-10 06:30:51.585 (MainThread) WARNING [CertificateAuthority] New CertificateAuthority at index 1
2024-05-10 06:30:51.587 (MainThread) WARNING [CertificateAuthority] Loading fabric admins from storage...
2024-05-10 06:30:51.587 (MainThread) WARNING [FabricAdmin] New FabricAdmin: FabricId: 0x0000000000000001, VendorId = 0xFFF1
2024-05-10 06:30:51.588 (MainThread) INFO [matter_server.server.stack] CHIP Controller Stack initialized.
2024-05-10 06:30:51.597 (MainThread) INFO [matter_server.server.server] Starting the Matter Server...
2024-05-10 06:30:51.606 (MainThread) INFO [matter_server.server.helpers.paa_certificates] Fetching the latest PAA root certificates from DCL.
2024-05-10 06:30:58.421 (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 pyca/cryptography#8996 and pyca/cryptography#9253 for more details.
result = self.fn(*self.args, **self.kwargs)

2024-05-10 06:31:10.223 (MainThread) INFO [matter_server.server.helpers.paa_certificates] Fetched 132 PAA root certificates from DCL.
2024-05-10 06:31:10.225 (MainThread) INFO [matter_server.server.helpers.paa_certificates] Fetching the latest PAA root certificates from Git.
2024-05-10 06:31:15.392 (MainThread) INFO [matter_server.server.helpers.paa_certificates] Fetched 90 PAA root certificates from Git.
2024-05-10 06:31:15.394 (MainThread) WARNING [FabricAdmin] Allocating new controller with CaIndex: 1, FabricId: 0x0000000000000001, NodeId: 0x000000000001B669, CatTags: []
2024-05-10 06:31:15.892 (Dummy-2) CHIP_ERROR [chip.native.DL] Long dispatch time: 494 ms, for event type 2
2024-05-10 06:31:15.905 (MainThread) INFO [matter_server.server.device_controller] Loaded 2 nodes from stored configuration
2024-05-10 06:31:15.917 (MainThread) INFO [matter_server.server.vendor_info] Loading vendor info from storage.
2024-05-10 06:31:15.927 (MainThread) INFO [matter_server.server.vendor_info] Loaded 193 vendors from storage.
2024-05-10 06:31:15.927 (MainThread) INFO [matter_server.server.vendor_info] Fetching the latest vendor info from DCL.
2024-05-10 06:31:16.443 (MainThread) INFO [matter_server.server.vendor_info] Fetched 191 vendors from DCL.
2024-05-10 06:31:16.443 (MainThread) INFO [matter_server.server.vendor_info] Saving vendor info to storage.
2024-05-10 06:31:16.610 (MainThread) INFO [matter_server.server.device_controller.mdns] Node 1 discovered on MDNS
2024-05-10 06:31:16.610 (MainThread) INFO [matter_server.server.device_controller.node_1] Setting-up node...
2024-05-10 06:31:16.665 (MainThread) INFO [matter_server.server.device_controller.mdns] Node 2 discovered on MDNS
2024-05-10 06:31:16.666 (MainThread) INFO [matter_server.server.device_controller.node_2] Setting-up node...
2024-05-10 06:31:18.521 (MainThread) INFO [matter_server.server.device_controller.node_2] Setting up attributes and events subscription.
2024-05-10 06:31:19.950 (MainThread) INFO [matter_server.server.device_controller.node_2] Subscription succeeded
2024-05-10 06:31:26.754 (Dummy-2) CHIP_ERROR [chip.native.EM] Failed to Send CHIP MessageCounter:247777465 on exchange 2237i with Node: <0000000000000000, 0> sendCount: 4 max retries: 4
2024-05-10 06:31:30.085 (Dummy-2) CHIP_ERROR [chip.native.SC] CASESession timed out while waiting for a response from the peer. Current state was 1
2024-05-10 06:31:33.087 (MainThread) INFO [matter_server.server.device_controller] Attempting to resolve node 1... (attempt 2 of 2)
2024-05-10 06:31:43.618 (Dummy-2) CHIP_ERROR [chip.native.EM] Failed to Send CHIP MessageCounter:247777469 on exchange 2240i with Node: <0000000000000000, 0> sendCount: 4 max retries: 4
2024-05-10 06:31:46.574 (Dummy-2) CHIP_ERROR [chip.native.SC] CASESession timed out while waiting for a response from the peer. Current state was 1
2024-05-10 06:31:46.575 (MainThread) WARNING [matter_server.server.device_controller.node_1] Setup for node failed: Unable to resolve Node 1
2024-05-10 06:32:22.033 (MainThread) ERROR [matter_server.server.client_handler] [547814478544] Error while handling: read_attribute (node 1): Node 1 is not (yet) available.
2024-05-10 06:32:22.040 (MainThread) ERROR [matter_server.server.client_handler] [547814478544] Error while handling: read_attribute (node 1): Node 1 is not (yet) available.
2024-05-10 06:32:22.045 (MainThread) ERROR [matter_server.server.client_handler] [547814478544] Error while handling: read_attribute (node 1): Node 1 is not (yet) available.
2024-05-10 06:32:22.051 (MainThread) ERROR [matter_server.server.client_handler] [547814478544] Error while handling: read_attribute (node 1): Node 1 is not (yet) available.
2024-05-10 06:32:28.985 (MainThread) ERROR [matter_server.server.client_handler] [547814478544] Error while handling: read_attribute (node 1): Node 1 is not (yet) available.
2024-05-10 06:32:28.991 (MainThread) ERROR [matter_server.server.client_handler] [547814478544] Error while handling: read_attribute (node 1): Node 1 is not (yet) available.
2024-05-10 06:32:28.996 (MainThread) ERROR [matter_server.server.client_handler] [547814478544] Error while handling: read_attribute (node 1): Node 1 is not (yet) available.
2024-05-10 06:32:29.001 (MainThread) ERROR [matter_server.server.client_handler] [547814478544] Error while handling: read_attribute (node 1): Node 1 is not (yet) available.
2024-05-10 06:32:32.337 (MainThread) ERROR [matter_server.server.client_handler] [547814478544] Error while handling: read_attribute (node 1): Node 1 is not (yet) available.
2024-05-10 06:32:32.340 (MainThread) ERROR [matter_server.server.client_handler] [547814478544] Error while handling: read_attribute (node 1): Node 1 is not (yet) available.
2024-05-10 06:32:32.343 (MainThread) ERROR [matter_server.server.client_handler] [547814478544] Error while handling: read_attribute (node 1): Node 1 is not (yet) available.
2024-05-10 06:32:32.366 (MainThread) ERROR [matter_server.server.client_handler] [547814478544] Error while handling: read_attribute (node 1): Node 1 is not (yet) available.
2024-05-10 06:32:35.577 (MainThread) ERROR [matter_server.server.client_handler] [547814478544] Error while handling: read_attribute (node 1): Node 1 is not (yet) available.
2024-05-10 06:32:35.582 (MainThread) ERROR [matter_server.server.client_handler] [547814478544] Error while handling: read_attribute (node 1): Node 1 is not (yet) available.
2024-05-10 06:32:35.617 (MainThread) ERROR [matter_server.server.client_handler] [547814478544] Error while handling: read_attribute (node 1): Node 1 is not (yet) available.
2024-05-10 06:32:35.645 (MainThread) ERROR [matter_server.server.client_handler] [547814478544] Error while handling: read_attribute (node 1): Node 1 is not (yet) available.

@marcelveldt
Copy link
Contributor

This has nothing to do with upgrading the Matter server ?
The Node is not available as setting up the case session failed. Looks like the node couldn't even be discovered on mdns.

So I dont see a bug here but a device issue.

@olavt
Copy link
Author

olavt commented May 15, 2024 •
edited
Loading

The device was working 100% fine just before the upgrade. It was sending attribute updates every 2.5 seconds. Stopped the running Python Matter Server, started the new version and got the messages in the log. And note that the exact same issue happened with two different installations.

@olavt
Copy link
Author

olavt commented May 21, 2024

I re-testet today by upgrading from 5.10 to 6.0.1 and I could not reproduce the issue.

@olavt olavt closed this as completed May 21, 2024
@olavt
Copy link
Author

olavt commented Jun 15, 2024 •
edited
Loading

I upgraded to 6.1.2 and experienced the issue with device becoming unavailable.

@olavt olavt reopened this Jun 15, 2024
@Ktl-XV
Copy link

Ktl-XV commented Jun 30, 2024 •
edited
Loading

It seems that if /root/.matter_server is empty /data is not searched

@olavt
Copy link
Author

olavt commented Jul 22, 2024

It could be related to not specifying these options when starting Python Matter Server:

--storage-path /data --paa-root-cert-dir /data/credentials

I thought it would use /data per default.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@Ktl-XV @olavt @marcelveldt