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.

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

[bug] Application stops responding with CPU stuck at 100% #174

Closed
1 of 3 tasks
kaaelhaa opened this issue Jan 8, 2021 · 16 comments
Closed
1 of 3 tasks

[bug] Application stops responding with CPU stuck at 100% #174

kaaelhaa opened this issue Jan 8, 2021 · 16 comments
Assignees
Labels
bug Something isn't working

Comments

@kaaelhaa
Copy link

kaaelhaa commented Jan 8, 2021

Version

Build/Run method

  • Docker
  • PKG
  • Manually built (git clone - npm install - npm run build )

zwavejs2mqtt version: 1.0.0-alpha.2

Describe the bug
Few minutes after starting the application (ranging from 10-30 minutes) it will stop responding and hog one CPU thread at 100%.

This always happens when zwavejs2mqtt has logged the following:

2021-01-08 00:24:55.129 INFO ZWAVE: Node 48 is asleep
2021-01-08 00:24:55.133 WARN ZWAVE: Node 48 doesn't support groups associations
2021-01-08 00:24:55.457 INFO ZWAVE: Node 48: value added 48-38-0-targetValue => undefined
2021-01-08 00:24:55.458 INFO ZWAVE: Node 48: value added 48-38-0-duration => undefined
2021-01-08 00:24:55.751 INFO ZWAVE: Node 48: value added 48-38-0-currentValue => 12
2021-01-08 00:24:55.752 INFO ZWAVE: Node 48: value added 48-38-0-Open => undefined
2021-01-08 00:24:55.753 INFO ZWAVE: Node 48: value added 48-38-0-Close => undefined
2021-01-08 00:24:55.754 INFO ZWAVE: Node 48: value added 48-49-0-Air temperature => 16
2021-01-08 00:24:55.755 INFO ZWAVE: Node 48: value added 48-64-0-mode => 1
2021-01-08 00:24:55.756 INFO ZWAVE: Node 48: value added 48-64-0-manufacturerData => undefined
2021-01-08 00:24:55.758 INFO ZWAVE: Node 48: value added 48-67-0-setpoint-1 => 15
2021-01-08 00:24:55.759 INFO ZWAVE: Node 48: value added 48-67-0-setpoint-11 => 18
2021-01-08 00:24:55.760 INFO ZWAVE: Node 48: value added 48-114-0-manufacturerId => 328
2021-01-08 00:24:55.761 INFO ZWAVE: Node 48: value added 48-114-0-productType => 2
2021-01-08 00:24:55.762 INFO ZWAVE: Node 48: value added 48-114-0-productId => 1
2021-01-08 00:24:55.763 INFO ZWAVE: Node 48: value added 48-128-0-level => 29
2021-01-08 00:24:55.764 INFO ZWAVE: Node 48: value added 48-128-0-isLow => false
2021-01-08 00:24:55.765 INFO ZWAVE: Node 48: value added 48-132-0-wakeUpInterval => 21600
2021-01-08 00:24:55.766 INFO ZWAVE: Node 48: value added 48-132-0-controllerNodeId => 1
2021-01-08 00:24:55.767 INFO ZWAVE: Node 48: value added 48-134-0-libraryType => 3
2021-01-08 00:24:55.768 INFO ZWAVE: Node 48: value added 48-134-0-protocolVersion => 3.67
2021-01-08 00:24:55.769 INFO ZWAVE: Node 48: value added 48-134-0-firmwareVersions => 0.5

I have uploaded an export of node 48 and log files from zwavejs2mqtt and zwavejs to this Gist: https://gist.github.com/kaaelhaa/6ea4695ed2b5b556b70c0968a59fb49c

To Reproduce
I can reproduce reliably. This always happens after the log lines for Node 48 has been output.

Replicated on latest stable and dev versions.

Expected behavior
Application should be responsive.

Additional context
N/A.

@kaaelhaa kaaelhaa added the bug Something isn't working label Jan 8, 2021
@robertsLando
Copy link
Member

@AlCalzone I see a tons of:

2021-01-08 00:21:43.784 INFO ZWAVE: Node 54: value updated: 50-1-value-66049 1.2 => 1.4
2021-01-08 00:21:43.788 INFO ZWAVE: Node 54: value updated: 50-1-deltaTime-66049 0 => 0
2021-01-08 00:21:44.945 INFO ZWAVE: Node 54: value updated: 50-1-value-66049 1.4 => 1.4
2021-01-08 00:21:44.948 INFO ZWAVE: Node 54: value updated: 50-1-deltaTime-66049 0 => 0
2021-01-08 00:21:46.104 INFO ZWAVE: Node 54: value updated: 50-1-value-66049 1.4 => 1.4
2021-01-08 00:21:46.106 INFO ZWAVE: Node 54: value updated: 50-1-deltaTime-66049 0 => 0
2021-01-08 00:21:46.561 INFO ZWAVE: Node 54: value updated: 50-1-value-66049 1.4 => 1.4
2021-01-08 00:21:46.564 INFO ZWAVE: Node 54: value updated: 50-1-deltaTime-66049 0 => 0
2021-01-08 00:21:46.915 INFO ZWAVE: Node 54: value updated: 50-1-value-66049 1.4 => 1.4
2021-01-08 00:21:46.917 INFO ZWAVE: Node 54: value updated: 50-1-deltaTime-66049 0 => 0
2021-01-08 00:21:47.259 INFO ZWAVE: Node 54: value updated: 50-1-value-66049 1.4 => 1.4
2021-01-08 00:21:47.262 INFO ZWAVE: Node 54: value updated: 50-1-deltaTime-66049 0 => 0
2021-01-08 00:21:48.100 INFO ZWAVE: Node 54: value updated: 50-1-value-66049 1.4 => 1.4
2021-01-08 00:21:48.103 INFO ZWAVE: Node 54: value updated: 50-1-deltaTime-66049 0 => 0
2021-01-08 00:21:48.424 INFO ZWAVE: Node 54: value updated: 50-1-value-66049 1.4 => 1.4
2021-01-08 00:21:48.426 INFO ZWAVE: Node 54: value updated: 50-1-deltaTime-66049 0 => 0
2021-01-08 00:21:48.747 INFO ZWAVE: Node 54: value updated: 50-1-value-66049 1.4 => 1.4
2021-01-08 00:21:48.750 INFO ZWAVE: Node 54: value updated: 50-1-deltaTime-66049 0 => 0
2021-01-08 00:21:49.238 INFO ZWAVE: Node 54: value updated: 50-1-value-66049 1.4 => 1.4
2021-01-08 00:21:49.242 INFO ZWAVE: Node 54: value updated: 50-1-deltaTime-66049 0 => 0
2021-01-08 00:21:49.281 INFO ZWAVE: Node 54: value updated: 50-1-value-66049 1.4 => 1.4
2021-01-08 00:21:49.284 INFO ZWAVE: Node 54: value updated: 50-1-deltaTime-66049 0 => 0
2021-01-08 00:21:49.306 INFO ZWAVE: Node 54: value updated: 50-1-value-66049 1.4 => 1.4
2021-01-08 00:21:49.308 INFO ZWAVE: Node 54: value updated: 50-1-deltaTime-66049 0 => 0
2021-01-08 00:21:49.463 INFO ZWAVE: Node 54: value updated: 50-1-value-66049 1.4 => 1.4
2021-01-08 00:21:49.466 INFO ZWAVE: Node 54: value updated: 50-1-deltaTime-66049 0 => 0
2021-01-08 00:21:49.546 INFO ZWAVE: Node 54: value updated: 50-1-value-66049 1.4 => 1.4
2021-01-08 00:21:49.548 INFO ZWAVE: Node 54: value updated: 50-1-deltaTime-66049 0 => 0
2021-01-08 00:21:49.628 INFO ZWAVE: Node 54: value updated: 50-1-value-66049 1.4 => 1.4
2021-01-08 00:21:49.630 INFO ZWAVE: Node 54: value updated: 50-1-deltaTime-66049 0 => 0
2021-01-08 00:21:49.774 INFO ZWAVE: Node 54: value updated: 50-1-value-66049 1.4 => 1.4
2021-01-08 00:21:49.778 INFO ZWAVE: Node 54: value updated: 50-1-deltaTime-66049 0 => 0
2021-01-08 00:21:49.796 INFO ZWAVE: Node 54: value updated: 50-1-value-66049 1.4 => 1.4
2021-01-08 00:21:49.798 INFO ZWAVE: Node 54: value updated: 50-1-deltaTime-66049 0 => 0
2021-01-08 00:21:49.873 INFO ZWAVE: Node 54: value updated: 50-1-value-66049 1.4 => 1.4
2021-01-08 00:21:49.875 INFO ZWAVE: Node 54: value updated: 50-1-deltaTime-66049 0 => 0
2021-01-08 00:21:51.122 INFO ZWAVE: Node 54: value updated: 50-1-value-66049 1.4 => 1.4
2021-01-08 00:21:51.125 INFO ZWAVE: Node 54: value updated: 50-1-deltaTime-66049 0 => 0
2021-01-08 00:21:51.198 INFO ZWAVE: Node 54: value updated: 50-1-value-66049 1.4 => 1.4
2021-01-08 00:21:51.200 INFO ZWAVE: Node 54: value updated: 50-1-deltaTime-66049 0 => 0
2021-01-08 00:21:51.259 INFO ZWAVE: Node 54: value updated: 50-1-value-66049 1.4 => 1.4
2021-01-08 00:21:51.262 INFO ZWAVE: Node 54: value updated: 50-1-deltaTime-66049 0 => 0
2021-01-08 00:21:51.662 INFO ZWAVE: Node 54: value updated: 50-2-value-66049 1.2 => 0.9
2021-01-08 00:21:51.670 INFO ZWAVE: Node 54: value updated: 50-2-deltaTime-66049 0 => 0
2021-01-08 00:21:51.931 INFO ZWAVE: Node 54: value updated: 50-2-value-66049 0.9 => 0.9
2021-01-08 00:21:51.934 INFO ZWAVE: Node 54: value updated: 50-2-deltaTime-66049 0 => 0
2021-01-08 00:21:52.044 INFO ZWAVE: Node 54: value updated: 50-2-value-66049 0.9 => 0.9
2021-01-08 00:21:52.047 INFO ZWAVE: Node 54: value updated: 50-2-deltaTime-66049 0 => 0
2021-01-08 00:21:52.852 INFO ZWAVE: Node 54: value updated: 50-2-value-66049 0.9 => 0.2
2021-01-08 00:21:52.855 INFO ZWAVE: Node 54: value updated: 50-2-deltaTime-66049 0 => 0
2021-01-08 00:21:53.031 INFO ZWAVE: Node 54: value updated: 50-2-value-66049 0.2 => 0.2
2021-01-08 00:21:53.034 INFO ZWAVE: Node 54: value updated: 50-2-deltaTime-66049 0 => 0
2021-01-08 00:21:53.359 INFO ZWAVE: Node 54: value updated: 50-2-value-66049 0.2 => 0.2
2021-01-08 00:21:53.361 INFO ZWAVE: Node 54: value updated: 50-2-deltaTime-66049 0 => 0
2021-01-08 00:21:54.182 INFO ZWAVE: Node 54: value updated: 50-2-value-66049 0.2 => 0.2
2021-01-08 00:21:54.184 INFO ZWAVE: Node 54: value updated: 50-2-deltaTime-66049 0 => 0
2021-01-08 00:21:54.365 INFO ZWAVE: Node 54: value updated: 50-2-value-66049 0.2 => 0.2
2021-01-08 00:21:54.368 INFO ZWAVE: Node 54: value updated: 50-2-deltaTime-66049 0 => 0
2021-01-08 00:21:54.622 INFO ZWAVE: Node 54: value updated: 50-2-value-66049 0.2 => 0.2
2021-01-08 00:21:54.625 INFO ZWAVE: Node 54: value updated: 50-2-deltaTime-66049 0 => 0
2021-01-08 00:21:55.021 INFO ZWAVE: Node 54: value updated: 50-2-value-66049 0.2 => 0.2
2021-01-08 00:21:55.024 INFO ZWAVE: Node 54: value updated: 50-2-deltaTime-66049 0 => 0
2021-01-08 00:21:55.345 INFO ZWAVE: Node 54: value updated: 50-2-value-66049 0.2 => 0.2
2021-01-08 00:21:55.348 INFO ZWAVE: Node 54: value updated: 50-2-deltaTime-66049 0 => 0
2021-01-08 00:21:55.529 INFO ZWAVE: Node 54: value updated: 50-2-value-66049 0.2 => 0.2
2021-01-08 00:21:55.532 INFO ZWAVE: Node 54: value updated: 50-2-deltaTime-66049 0 => 0
2021-01-08 00:21:56.021 INFO ZWAVE: Node 54: value updated: 50-2-value-66049 0.2 => 0.2
2021-01-08 00:21:56.024 INFO ZWAVE: Node 54: value updated: 50-2-deltaTime-66049 0 => 0
2021-01-08 00:21:56.063 INFO ZWAVE: Node 54: value updated: 50-2-value-66049 0.2 => 0.2
2021-01-08 00:21:56.066 INFO ZWAVE: Node 54: value updated: 50-2-deltaTime-66049 0 => 0
2021-01-08 00:21:56.140 INFO ZWAVE: Node 54: value updated: 50-2-value-66049 0.2 => 0.2
2021-01-08 00:21:56.143 INFO ZWAVE: Node 54: value updated: 50-2-deltaTime-66049 0 => 0
2021-01-08 00:21:56.298 INFO ZWAVE: Node 54: value updated: 50-2-value-66049 0.2 => 0.2
2021-01-08 00:21:56.301 INFO ZWAVE: Node 54: value updated: 50-2-deltaTime-66049 0 => 0
2021-01-08 00:21:56.362 INFO ZWAVE: Node 54: value updated: 50-2-value-66049 0.2 => 0.2
2021-01-08 00:21:56.365 INFO ZWAVE: Node 54: value updated: 50-2-deltaTime-66049 0 => 0
2021-01-08 00:21:56.443 INFO ZWAVE: Node 54: value updated: 50-2-value-66049 0.2 => 0.2
2021-01-08 00:21:56.445 INFO ZWAVE: Node 54: value updated: 50-2-deltaTime-66049 0 => 0
2021-01-08 00:21:56.570 INFO ZWAVE: Node 54: value updated: 50-2-value-66049 0.2 => 0.2
2021-01-08 00:21:56.572 INFO ZWAVE: Node 54: value updated: 50-2-deltaTime-66049 0 => 0
2021-01-08 00:21:56.595 INFO ZWAVE: Node 54: value updated: 50-2-value-66049 0.2 => 0.2
2021-01-08 00:21:56.600 INFO ZWAVE: Node 54: value updated: 50-2-deltaTime-66049 0 => 0
2021-01-08 00:21:56.638 INFO ZWAVE: Node 54: value updated: 50-2-value-66049 0.2 => 0.2
2021-01-08 00:21:56.640 INFO ZWAVE: Node 54: value updated: 50-2-deltaTime-66049 0 => 0
2021-01-08 00:21:56.732 INFO ZWAVE: Node 54: value updated: 50-2-value-66049 0.2 => 0.2
2021-01-08 00:21:56.734 INFO ZWAVE: Node 54: value updated: 50-2-deltaTime-66049 0 => 0
2021-01-08 00:21:56.761 INFO ZWAVE: Node 54: value updated: 50-2-value-66049 0.2 => 0.2
2021-01-08 00:21:56.763 INFO ZWAVE: Node 54: value updated: 50-2-deltaTime-66049 0 => 0
2021-01-08 00:21:56.827 INFO ZWAVE: Node 54: value updated: 50-2-value-66049 0.2 => 0.2
2021-01-08 00:21:56.829 INFO ZWAVE: Node 54: value updated: 50-2-deltaTime-66049 0 => 0
2021-01-08 00:21:57.137 INFO ZWAVE: Node 54: value updated: 50-2-value-66049 0.2 => 0.9
2021-01-08 00:21:57.140 INFO ZWAVE: Node 54: value updated: 50-2-deltaTime-66049 0 => 0
2021-01-08 00:21:57.461 INFO ZWAVE: Node 54: value updated: 50-2-value-66049 0.9 => 0.9
2021-01-08 00:21:57.464 INFO ZWAVE: Node 54: value updated: 50-2-deltaTime-66049 0 => 0
2021-01-08 00:21:57.643 INFO ZWAVE: Node 54: value updated: 50-2-value-66049 0.9 => 0.9
2021-01-08 00:21:57.646 INFO ZWAVE: Node 54: value updated: 50-2-deltaTime-66049 0 => 0
2021-01-08 00:21:58.466 INFO ZWAVE: Node 54: value updated: 50-2-value-66049 0.9 => 0.9
2021-01-08 00:21:58.468 INFO ZWAVE: Node 54: value updated: 50-2-deltaTime-66049 0 => 0
2021-01-08 00:22:01.948 INFO ZWAVE: Node 54: value updated: 50-2-value-66049 0.9 => 0.9
2021-01-08 00:22:01.951 INFO ZWAVE: Node 54: value updated: 50-2-deltaTime-66049 0 => 0
2021-01-08 00:22:02.041 INFO ZWAVE: Node 54: value updated: 50-2-value-66049 0.9 => 0.9
2021-01-08 00:22:02.043 INFO ZWAVE: Node 54: value updated: 50-2-deltaTime-66049 0 => 0
2021-01-08 00:22:02.082 INFO ZWAVE: Node 54: value updated: 50-2-value-66049 0.9 => 0.9
2021-01-08 00:22:02.088 INFO ZWAVE: Node 54: value updated: 50-2-deltaTime-66049 0 => 0
2021-01-08 00:22:02.119 INFO ZWAVE: Node 54: value updated: 50-2-value-66049 0.9 => 0.9
2021-01-08 00:22:02.121 INFO ZWAVE: Node 54: value updated: 50-2-deltaTime-66049 0 => 0
2021-01-08 00:22:02.289 INFO ZWAVE: Node 54: value updated: 50-2-value-66049 0.9 => 0.9
2021-01-08 00:22:02.292 INFO ZWAVE: Node 54: value updated: 50-2-deltaTime-66049 0 => 0
2021-01-08 00:22:02.556 INFO ZWAVE: Node 54: value updated: 50-2-value-66049 0.9 => 0.9
2021-01-08 00:22:02.559 INFO ZWAVE: Node 54: value updated: 50-2-deltaTime-66049 0 => 0
2021-01-08 00:22:02.608 INFO ZWAVE: Node 54: value updated: 50-2-value-66049 0.9 => 0.9
2021-01-08 00:22:02.611 INFO ZWAVE: Node 54: value updated: 50-2-deltaTime-66049 0 => 0
2021-01-08 00:22:02.650 INFO ZWAVE: Node 54: value updated: 50-2-value-66049 0.9 => 0.9
2021-01-08 00:22:02.652 INFO ZWAVE: Node 54: value updated: 50-2-deltaTime-66049 0 => 0
2021-01-08 00:22:02.900 INFO ZWAVE: Node 54: value updated: 50-2-value-66049 0.9 => 0.9
2021-01-08 00:22:02.907 INFO ZWAVE: Node 54: value updated: 50-2-deltaTime-66049 0 => 0
2021-01-08 00:22:02.988 INFO ZWAVE: Node 54: value updated: 50-2-value-66049 0.9 => 0.9
2021-01-08 00:22:02.991 INFO ZWAVE: Node 54: value updated: 50-2-deltaTime-66049 0 => 0
2021-01-08 00:22:03.070 INFO ZWAVE: Node 54: value updated: 50-2-value-66049 0.9 => 0.9
2021-01-08 00:22:03.072 INFO ZWAVE: Node 54: value updated: 50-2-deltaTime-66049 0 => 0
2021-01-08 00:22:03.307 INFO ZWAVE: Node 54: value updated: 50-2-value-66049 0.9 => 0.9
2021-01-08 00:22:03.311 INFO ZWAVE: Node 54: value updated: 50-2-deltaTime-66049 0 => 0
2021-01-08 00:22:03.335 INFO ZWAVE: Node 54: value updated: 50-2-value-66049 0.9 => 0.9
2021-01-08 00:22:03.338 INFO ZWAVE: Node 54: value updated: 50-2-deltaTime-66049 0 => 0
2021-01-08 00:22:03.365 INFO ZWAVE: Node 54: value updated: 50-2-value-66049 0.9 => 0.9
2021-01-08 00:22:03.367 INFO ZWAVE: Node 54: value updated: 50-2-deltaTime-66049 0 => 0
2021-01-08 00:22:05.521 INFO ZWAVE: Node 54: value updated: 50-2-value-66049 0.9 => 1.3
2021-01-08 00:22:05.524 INFO ZWAVE: Node 54: value updated: 50-2-deltaTime-66049 0 => 0
2021-01-08 00:22:05.637 INFO ZWAVE: Node 54: value updated: 50-2-value-66049 1.3 => 1.3
2021-01-08 00:22:05.640 INFO ZWAVE: Node 54: value updated: 50-2-deltaTime-66049 0 => 0
2021-01-08 00:22:05.887 INFO ZWAVE: Node 54: value updated: 50-2-value-66049 1.3 => 1.3
2021-01-08 00:22:05.890 INFO ZWAVE: Node 54: value updated: 50-2-deltaTime-66049 0 => 0
2021-01-08 00:22:06.242 INFO ZWAVE: Node 54: value updated: 50-2-value-66049 1.3 => 1.3
2021-01-08 00:22:06.245 INFO ZWAVE: Node 54: value updated: 50-2-deltaTime-66049 0 => 0
2021-01-08 00:22:06.837 INFO ZWAVE: Node 54: value updated: 50-2-value-66049 1.3 => 1.3
2021-01-08 00:22:06.840 INFO ZWAVE: Node 54: value updated: 50-2-deltaTime-66049 0 => 0
2021-01-08 00:22:06.893 INFO ZWAVE: Node 54: value updated: 50-2-value-66049 1.3 => 1.3
2021-01-08 00:22:06.895 INFO ZWAVE: Node 54: value updated: 50-2-deltaTime-66049 0 => 0
2021-01-08 00:22:10.970 INFO ZWAVE: Node 54: value updated: 50-2-value-66049 1.3 => 1.3
2021-01-08 00:22:10.973 INFO ZWAVE: Node 54: value updated: 50-2-deltaTime-66049 0 => 0
2021-01-08 00:22:10.995 INFO ZWAVE: Node 54: value updated: 50-2-value-66049 1.3 => 1.3
2021-01-08 00:22:10.998 INFO ZWAVE: Node 54: value updated: 50-2-deltaTime-66049 0 => 0
2021-01-08 00:22:11.072 INFO ZWAVE: Node 54: value updated: 50-2-value-66049 1.3 => 1.3
2021-01-08 00:22:11.074 INFO ZWAVE: Node 54: value updated: 50-2-deltaTime-66049 0 => 0
2021-01-08 00:22:11.229 INFO ZWAVE: Node 54: value updated: 50-2-value-66049 1.3 => 1.3
2021-01-08 00:22:11.230 INFO ZWAVE: Node 54: value updated: 50-2-deltaTime-66049 0 => 0
2021-01-08 00:22:11.291 INFO ZWAVE: Node 54: value updated: 50-2-value-66049 1.3 => 1.3
2021-01-08 00:22:11.292 INFO ZWAVE: Node 54: value updated: 50-2-deltaTime-66049 0 => 0
2021-01-08 00:22:11.319 INFO ZWAVE: Node 54: value updated: 50-2-value-66049 1.3 => 1.3
2021-01-08 00:22:11.321 INFO ZWAVE: Node 54: value updated: 50-2-deltaTime-66049 0 => 0
2021-01-08 00:22:11.694 INFO ZWAVE: Node 54: value updated: 50-2-value-66049 1.3 => 1.3
2021-01-08 00:22:11.695 INFO ZWAVE: Node 54: value updated: 50-2-deltaTime-66049 0 => 0
2021-01-08 00:22:11.794 INFO ZWAVE: Node 54: value updated: 50-2-value-66049 1.3 => 1.3
2021-01-08 00:22:11.796 INFO ZWAVE: Node 54: value updated: 50-2-deltaTime-66049 0 => 0
2021-01-08 00:22:11.875 INFO ZWAVE: Node 54: value updated: 50-2-value-66049 1.3 => 1.3
2021-01-08 00:22:11.877 INFO ZWAVE: Node 54: value updated: 50-2-deltaTime-66049 0 => 0
2021-01-08 00:22:12.089 INFO ZWAVE: Node 54: value updated: 50-2-value-66049 1.3 => 1.3
2021-01-08 00:22:12.091 INFO ZWAVE: Node 54: value updated: 50-2-deltaTime-66049 0 => 0
2021-01-08 00:22:12.135 INFO ZWAVE: Node 54: value updated: 50-2-value-66049 1.3 => 1.3
2021-01-08 00:22:12.138 INFO ZWAVE: Node 54: value updated: 50-2-deltaTime-66049 0 => 0
2021-01-08 00:22:12.183 INFO ZWAVE: Node 54: value updated: 50-2-value-66049 1.3 => 1.3
2021-01-08 00:22:12.185 INFO ZWAVE: Node 54: value updated: 50-2-deltaTime-66049 0 => 0

This happens for multiple nodes. What could it be?

@AlCalzone
Copy link
Member

Once we've sorted out the logging issue, I'll need a zwave-js log to see exactly what is going on.
I'm suspecting that the device is spamming, but cannot confirm right now.

@blhoward2
Copy link
Collaborator

What make/model is node 54? Those three values are typical of an energy report being sent.

@kaaelhaa
Copy link
Author

kaaelhaa commented Jan 8, 2021

It's a Qubino ZMNHBD2 Flush 2 Relays with temperature probe. Firmware 1.02.

Is there anything I can do to get more informative logs?

@blhoward2
Copy link
Collaborator

@AlCalzone Separate from this specific issue... Obviously the controller can’t do anything about a device flooding the mesh itself, but is it feasible to throttle misbehaving devices and drop excessive messages in some manner? Or to drop meter-type reports altogether if the system gets under too heavy of a load? The idea being that the mesh may go to hell but at least the broker stays running and accessible to reconfigure the device/debug.

@AlCalzone
Copy link
Member

Is there anything I can do to get more informative logs?

Wait for us to fix logging :)
@robertsLando is working on it right now, I will review and merge it tonight

@AlCalzone
Copy link
Member

@blhoward2 good idea ==> zwave-js/node-zwave-js#1318

@blhoward2
Copy link
Collaborator

@kaaelhaa Is this a new device? Was it working previously with another platform (without any config changes)?

@kaaelhaa
Copy link
Author

kaaelhaa commented Jan 8, 2021

@blhoward2 The device have been in the network for at least a few years. It has always been very chatty though. Same goes for node 36 which is also another type of Qubino device (ZMNHAD1 Flush 1 Relay).

Have been in use on Z-way, HASS and qt-openzwave previously without issues.

@AlCalzone
Copy link
Member

@kaaelhaa Are you able to run the application without Docker and capture a profile like its described here (the parts with the --prof and the --prof-process params).

Would be intersting to know what's hogging the most performance here.

@kaaelhaa
Copy link
Author

kaaelhaa commented Jan 8, 2021

So, I executed node --prof bin/www and waited for the process to lock up (took approx. 15 minutes or "normal" operation) and then let it stay consuming 100% CPU for 10 minutes after that.

Processed the profiler output and put it in this Gist: https://gist.github.com/kaaelhaa/4ce04c21554d69082cbb1a48aaa248d3

Do note I got several errors logged by the processor like

Move: unknown source 1464775896
dropping: overflow

Haven't investigated those yet, so I don't know how much they impact the result.

But, from the output of the processor it seems to be stuck somewhere in https://github.com/zwave-js/zwavejs2mqtt/blob/master/lib/Gateway.js#L1242. This makes somewhat sense, as Node 48 is a climate device (Eurotronic Comet Z ). Node 51 and 83 are similar devices.

@AlCalzone
Copy link
Member

But, from the output of the processor it seems to be stuck somewhere in

My guess is on this loop:
https://github.com/zwave-js/zwavejs2mqtt/blob/04952ea13414e6a2d075dc2e07ec610ff4f066fc/lib/Gateway.js#L1262-L1280

There's probably a more performant way than looping through all values (which can be many) every few ms.

@kaaelhaa
Copy link
Author

kaaelhaa commented Jan 9, 2021

@AlCalzone I tried adding some extra logging to that loop and the 20 node values for node 48 is looped through in an instant.
Adding some more logging to the function to see if I can triage this, especially this loop is of concern now:

https://github.com/zwave-js/zwavejs2mqtt/blob/04952ea13414e6a2d075dc2e07ec610ff4f066fc/lib/Gateway.js#L1338-L1364

@kaaelhaa
Copy link
Author

kaaelhaa commented Jan 9, 2021

My testing confirms this loop is infinite:

https://github.com/zwave-js/zwavejs2mqtt/blob/04952ea13414e6a2d075dc2e07ec610ff4f066fc/lib/Gateway.js#L1346-L1351

That's what causes everything to freeze.

Is it necessary to have this stanza as it seems #68 improved the logic quite a bit?

@robertsLando
Copy link
Member

My testing confirms this loop is infinite:

Let me check this.

robertsLando added a commit that referenced this issue Jan 11, 2021
@robertsLando
Copy link
Member

@kaaelhaa Really bad, thanks for the issue report! Fixed on master now!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working
Projects
None yet
Development

No branches or pull requests

4 participants