Zwave2mqtt: [bug] Application crashing on dimmer devices

Created on 28 Jan 2020  ·  38Comments  ·  Source: OpenZWave/Zwave2Mqtt

Version

2.1.1

Build/Run method

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

Zwave2Mqtt version: 2.1.1
Openzwave Version: (imbedded in docker)

Describe the bug
My docker container is crashing a lot. Sometimes there's not much in the docker logs/stdout/stderr. And I can't reproduce it consistently. I should have a very simple setup, with HomeAssistant integration turned on.

To Reproduce
It's crashing randomly, hard to re-produce right now.

Expected behavior
No crashing :)

Additional context
I wasn't able to salvage this from the logs on one crash.

2020-01-28 15:26:54.860 Info, Download Finished: config/aeotec/zw112.xml (Node: 0),
2020-01-28 15:26:55.035 Info, Download Finished: config/aeotec/zw120.xml (Node: 0),
2020-01-28 15:26:55.212 Info, Download Finished: config/aeotec/zw122.xml (Node: 0),
2020-01-28 15:26:55.392 Info, Download Finished: config/aeotec/zw129.xml (Node: 0),
2020-01-28 15:26:55.568 Info, Download Finished: config/aeotec/zw130.xml (Node: 0),
2020-01-28 15:26:55.756 Info, Download Finished: config/aeotec/dsc06106.xml (Node: 0),
2020-01-28 15:26:55.938 Info, Download Finished: config/aeotec/dsc08101.xml (Node: 0),
2020-01-28 15:26:56.126 Info, Download Finished: config/aeotec/dsc10.xml (Node: 0),
2020-01-28 15:26:56.307 Info, Download Finished: config/aeotec/dsc11.xml (Node: 0),
2020-01-28 15:26:56.480 Info, Download Finished: config/aeotec/dsc12104.xml (Node: 0),
2020-01-28 15:26:56.654 Info, Download Finished: config/aeotec/dsc13104.xml (Node: 0),
2020-01-28 15:26:56.828 Info, Download Finished: config/aeotec/dsc14104.xml (Node: 0),
2020-01-28 15:26:57.001 Info, Download Finished: config/aeotec/dsc35103.xml (Node: 0),
2020-01-28 15:26:57.180 Info, Download Finished: config/aeotec/dsc18103.xml (Node: 0),
2020-01-28 15:26:57.377 Info, Download Finished: config/aeotec/dsc19103.xml (Node: 0),
2020-01-28 15:26:57.557 Info, Download Finished: config/aeotec/dsc24.xml (Node: 0),
2020-01-28 15:26:57.730 Info, Download Finished: config/aeotec/dsc26103.xml (Node: 0),
2020-01-28 15:26:57.899 Info, Download Finished: config/aeotec/dsc27103.xml (Node: 0),
2020-01-28 15:26:58.082 Info, Download Finished: config/aeotec/zw062.xml (Node: 0),
2020-01-28 15:26:58.253 Info, Download Finished: config/aeotec/zw075.xml (Node: 0),
2020-01-28 15:26:58.426 Info, Download Finished: config/aeotec/zw078.xml (Node: 0),
2020-01-28 15:26:58.599 Info, Download Finished: config/aeotec/zw096.xml (Node: 0),
2020-01-28 15:26:58.769 Info, Download Finished: config/aeotec/zw098.xml (Node: 0),
2020-01-28 15:26:58.951 Info, Download Finished: config/aeotec/zw099.xml (Node: 0),
2020-01-28 15:26:59.120 Info, Download Finished: config/aeotec/zw111.xml (Node: 0),
2020-01-28 15:26:59.287 Info, Download Finished: config/aeotec/zw116.xml (Node: 0),
2020-01-28 15:26:59.454 Info, Download Finished: config/aeotec/zw121.xml (Node: 0),
2020-01-28 15:26:59.620 Info, Download Finished: config/aeotec/zw132.xml (Node: 0),
2020-01-28 15:26:59.788 Info, Download Finished: config/aeotec/zw139.xml (Node: 0),
2020-01-28 15:27:00.164 Info, Download Finished: config/aeotec/zw140.xml (Node: 0),
2020-01-28 15:27:00.328 Info, Download Finished: config/aeotec/zw141.xml (Node: 0),
2020-01-28 15:27:00.601 Info, Download Finished: config/aeotec/dsd37.xml (Node: 0),
2020-01-28 15:27:00.784 Info, Download Finished: config/aeotec/zw056.xml (Node: 0),
2020-01-28 15:27:00.967 Info, Download Finished: config/aeotec/zw080.xml (Node: 0),
2020-01-28 15:27:01.177 Info, Download Finished: config/aeotec/zw117.xml (Node: 0),
2020-01-28 15:27:01.357 Info, Download Finished: config/BeNext/mygate.xml (Node: 0),
2020-01-28 15:27:01.540 Info, Download Finished: config/BeNext/mydisplay.xml (Node: 0),
2020-01-28 15:27:01.716 Info, Download Finished: config/BeNext/Molite.xml (Node: 0),
2020-01-28 15:27:01.892 Info, Download Finished: config/BeNext/DoorSensor.xml (Node: 0),
2020-01-28 15:27:02.175 Info, Download Finished: config/BeNext/AlarmSound.xml (Node: 0),
2020-01-28 15:27:02.346 Info, Download Finished: config/BeNext/EnergySwitch.xml (Node: 0),
2020-01-28 15:27:02.539 Info, Download Finished: config/BeNext/TagReader.xml (Node: 0),
2020-01-28 15:27:02.716 Info, Download Finished: config/BeNext/TagReader500.xml (Node: 0),
2020-01-28 15:27:02.916 Info, Download Finished: config/BeNext/BuiltinDimmer.xml (Node: 0),
2020-01-28 15:27:03.088 Info, Download Finished: config/BeNext/PanicButton.xml (Node: 0),
2020-01-28 15:27:03.266 Info, Download Finished: config/BeNext/PanicWatch.xml (Node: 0),
2020-01-28 15:27:03.439 Info, Download Finished: config/BeNext/SceneController.xml (Node: 0),
2020-01-28 15:27:03.606 Info, Download Finished: config/BeNext/PluginDimmer.xml (Node: 0),
2020-01-28 15:27:03.778 Info, Download Finished: config/BeNext/1poleswitch.xml (Node: 0),
2020-01-28 15:27:03.952 Info, Download Finished: config/BeNext/2poleswitch.xml (Node: 0),
2020-01-28 15:27:04.126 Info, Download Finished: config/BeNext/HeatingControl.xml (Node: 0),
2020-01-28 15:27:04.301 Info, Download Finished: config/BeNext/P1dongle.xml (Node: 0),
2020-01-28 15:27:04.480 Info, Download Finished: config/trane/TZEMT400AB32MAA.xml (Node: 0),
2020-01-28 15:27:04.654 Info, Download Finished: config/trane/TZEMT400BB32MAA.xml (Node: 0),
2020-01-28 15:27:04.833 Info, Download Finished: config/trane/TZEMT524AA21MA.xml (Node: 0),
2020-01-28 15:27:05.010 Info, Download Finished: config/vera/vera2.xml (Node: 0),
2020-01-28 15:27:05.193 Info, Download Finished: config/kwikset/smartcode.xml (Node: 0),
2020-01-28 15:27:05.362 Info, Download Finished: config/kwikset/914c.xml (Node: 0),
2020-01-28 15:27:05.545 Info, Download Finished: config/qees/reto-dimmer-plus.xml (Node: 0),
2020-01-28 15:27:05.722 Info, Download Finished: config/qees/reto-plugin-switch.xml (Node: 0),
2020-01-28 15:27:05.890 Info, Download Finished: config/northq/nq92021.xml (Node: 0),
2020-01-28 15:27:06.061 Info, Download Finished: config/northq/nq9021.xml (Node: 0),
2020-01-28 15:27:06.237 Info, Download Finished: config/northq/nq9121.xml (Node: 0),
2020-01-28 15:27:06.414 Info, Download Finished: config/schlagelink/itemp.xml (Node: 0),
2020-01-28 15:27:06.595 Info, Download Finished: config/schlagelink/minikeypad.xml (Node: 0),
2020-01-28 15:27:06.765 Info, Download Finished: config/schlagelink/41.xml (Node: 0),
2020-01-28 15:27:06.945 Info, Download Finished: config/2gig/ct30.xml (Node: 0),
2020-01-28 15:27:07.118 Info, Download Finished: config/2gig/ct32.xml (Node: 0),
2020-01-28 15:27:07.292 Info, Download Finished: config/2gig/ct50e.xml (Node: 0),
2020-01-28 15:27:07.462 Info, Download Finished: config/2gig/ct80.xml (Node: 0),
2020-01-28 15:27:07.632 Info, Download Finished: config/2gig/ct100.xml (Node: 0),
2020-01-28 15:27:07.817 Info, Download Finished: config/2gig/ct101.xml (Node: 0),
2020-01-28 15:27:07.990 Info, Download Finished: config/greenwave/gs1110-1-gr-1.xml (Node: 0),
2020-01-28 15:27:08.160 Info, Download Finished: config/greenwave/powernode1.xml (Node: 0),
2020-01-28 15:27:08.329 Info, Download Finished: config/greenwave/powernode6.xml (Node: 0),
2020-01-28 15:27:08.495 Info, Download Finished: config/diehlcontrols/766366.xml (Node: 0),
2020-01-28T14:27:08.625Z z2m:Gateway Closing Gateway...,
POST /api/settings 200 1.164 ms - 63,
2020-01-28 15:27:08.626 Detail, Notification: DriverRemoved,
2020-01-28 15:27:08.626 Always, ***************************************************************************,
2020-01-28 15:27:08.626 Always, *********************  Cumulative Network Statistics  *********************,
2020-01-28 15:27:08.626 Always, *** General,
2020-01-28 15:27:08.626 Always, Driver run time: . .  . 0 days, 0 hours, 0 minutes,
2020-01-28 15:27:08.626 Always, Frames processed: . . . . . . . . . . . . . . . . . . . . 0,
2020-01-28 15:27:08.626 Always, Total messages successfully received: . . . . . . . . . . 0,
2020-01-28 15:27:08.626 Always, Total Messages successfully sent: . . . . . . . . . . . . 0,
2020-01-28 15:27:08.626 Always, ACKs received from controller:  . . . . . . . . . . . . . 0,
2020-01-28 15:27:08.626 Always, *** Errors,
2020-01-28 15:27:08.626 Always, Unsolicited messages received while waiting for ACK:  . . 0,
2020-01-28 15:27:08.626 Always, Reads aborted due to timeouts:  . . . . . . . . . . . . . 0,
2020-01-28 15:27:08.626 Always, Bad checksum errors:  . . . . . . . . . . . . . . . . . . 0,
2020-01-28 15:27:08.626 Always, CANs received from controller:  . . . . . . . . . . . . . 0,
2020-01-28 15:27:08.626 Always, NAKs received from controller:  . . . . . . . . . . . . . 0,
2020-01-28 15:27:08.626 Always, Out of frame data flow errors:  . . . . . . . . . . . . . 0,
2020-01-28 15:27:08.626 Always, Messages retransmitted: . . . . . . . . . . . . . . . . . 0,
2020-01-28 15:27:08.626 Always, Messages dropped and not delivered: . . . . . . . . . . . 0,
2020-01-28 15:27:08.626 Always, ***************************************************************************,
2020-01-28 15:27:08.627 Warning, WARNING: Tried to write driver config with no home ID set,
2020-01-28 15:27:08.627 Info, Stopping DNSThread,,
bug lib problem

Most helpful comment

FWIY, I also experienced the described issue with a FIBARO System - FGD212 Dimmer 2 and after testing it with your changes (from zwave2mqtt in docker, with a custom created image), it no longer crashes. I also have two NAS-WR01Z Power plug 12A connected an they still work.

All 38 comments

@kingsleyadam This is happen after a settings update so?

This just happened after switching a light off from HomeAssistant.

I switched the light off, and it went off immediately. I then tried another light and it wouldn't toggle. I check zwave2mqtt and it had crashed.

There's nothing in the logs that look like an exception.

2020-01-28 17:32:51.853 Info, Node035, SwitchMultilevel::Set - Setting to level 0,
2020-01-28T16:32:51.853Z z2m:Mqtt Message received on homeassistant/35/38/1/0/set,
2020-01-28 17:32:51.853 Info, Node035, Value::Set - COMMAND_CLASS_SWITCH_MULTILEVEL - Level - 0 - 1 - 0

@kingsleyadam Could be related to segmentation fault received on multievel updates

It will only crash if you just added a device with Multilevel and have not restarted. (As long as the ozwcache file is updated)

@Fishwaldo, so once the item is added and I've restarted things should be stable?

I had moved to the 2.0.6-dev tag and things were more stable, but the application crashed again later when editing an items gateway properties.

If your error is indeed the same as the MultiLevelSwitch bug, yes, it should be stable. If your error is something else then ?????

It's hard to say what the error actually is. There's no exception bubbling up, the application crashes without much in the logs.

I'd be interested in increasing log verbosity to see exactly what's going on.

Could you run the app using nodejs instead of inside a docker container?

Yep, I've spun-up an Ubunntu 18.0.4 VM and will be reinstalling everything from scratch in nodejs.

I'll update again if I see the same issues.

Currently getting this when trying to spin-up zwave2mqtt

Error: libopenzwave.so.1.4: cannot open shared object file: No such file or directory at Object.Module._extensions..node (module.js:680:18) at Module.load (module.js:564:32) at tryModuleLoad (module.js:504:12) at Function.Module._load (module.js:496:3) at Module.require (module.js:595:17) at Module.require (pkg/prelude/bootstrap.js:1166:31) at require (internal/module.js:11:18) at Object.<anonymous> (/snapshot/Zwave2Mqtt/node_modules/openzwave-shared/lib/openzwave-shared.js:27:19) at Module._compile (pkg/prelude/bootstrap.js:1261:22) at Object.Module._extensions..js (module.js:662:10) at Module.load (module.js:564:32) at tryModuleLoad (module.js:504:12) at Function.Module._load (module.js:496:3) at Module.require (module.js:595:17) at Module.require (pkg/prelude/bootstrap.js:1166:31) at require (internal/module.js:11:18)

@kingsleyadam COuld you tell me the steps you have run?

Yep, here's what I've done

  1. Install operating system dependencies:
curl -sL https://deb.nodesource.com/setup_12.x | sudo -E bash -
sudo apt-get update && sudo apt-get -y install libudev-dev make build-essential unzip nodejs git
  1. Install openzwave
sudo mkdir /opt/open-zwave && \
  sudo chown -R $USER:$USER /opt/open-zwave
git clone https://github.com/OpenZWave/open-zwave.git /opt/open-zwave && cd /opt/open-zwave
make
sudo make install
sudo ldconfig
export LD_LIBRARY_PATH=/usr/local/lib64
sudo sed -i '$a LD_LIBRARY_PATH=/usr/local/lib64' /etc/environment
sudo MinOZW /dev/ttyACM0 # Run to test, needs to be run as sudo
  1. Install zwave2mqtt
sudo mkdir /opt/zwave2mqtt && \
  sudo chown -R $USER:$USER /opt/zwave2mqtt && \
  cd /opt/zwave2mqtt
curl -s https://api.github.com/repos/OpenZWave/Zwave2Mqtt/releases/latest  | grep "browser_download_url.*zip" | cut -d : -f 2,3 | tr -d \" | wget -i -
unzip zwave2mqtt-v*.zip
  1. Run zwave2mqtt
cd /opt/zwave2mqtt && ./zwave2mqtt

I was able to get it working by instead of running 3 and 4 above, I built and ran based upon the latest git code.

sudo mkdir /opt/zwave2mqtt && \
  sudo chown -R $USER:$USER /opt/zwave2mqtt
git clone https://github.com/OpenZWave/Zwave2Mqtt /opt/zwave2mqtt && \
  cd /opt/zwave2mqtt
npm install
npm run build
npm start
> [email protected] start /opt/zwave2mqtt
> node bin/www

  z2m:Store settings.json not found +0ms
  z2m:Store scenes.json not found +2ms
  z2m:Store nodes.json not found +0ms
  z2m:Gateway No custom hass devices file found +0ms
  z2m:App Application path:/opt/zwave2mqtt +0ms
  z2m:Gateway Zwave settings are not valid +3ms
  z2m:App Listening on port 8091 +0ms

I turned the above into a system.d service so I can better test this.

[Unit]
Description=zwave2mqtt service
After=network.target
StartLimitIntervalSec=0

[Service]
Type=simple
Restart=no
RestartSec=1
User=root
ExecStart=/usr/bin/npm start
WorkingDirectory=/opt/zwave2mqtt
Environment="LD_LIBRARY_PATH=/usr/local/lib64"

[Install]
WantedBy=multi-user.target

Yes the problem was that you where using the pkg version, that was packaged using ozw 1.4. You did it right in the last comment by running npm build and npm install.

Let me know if your problem persists

Daniel

On 29 Jan 2020, at 12:08, Adam Kingsley notifications@github.com wrote:


I was able to get it working by instead of running 3 and 4 above, I built and ran based upon the latest git code.

sudo mkdir /opt/zwave2mqtt && \
sudo chown -R $USER:$USER /opt/zwave2mqtt
git clone https://github.com/OpenZWave/Zwave2Mqtt /opt/zwave2mqtt && \
cd /opt/zwave2mqtt
npm install
npm run build
npm start

You are receiving this because you were assigned.
Reply to this email directly, view it on GitHub, or unsubscribe.

I was able to reproduce this almost immediately upon adding the first node to the network, it is a dimmer.

I only have 1 dimmer node on the network. This happens every time I try to update it's dimmer level, even after restarting the npm process.

Log output is

0 info it worked if it ends with ok
1 verbose cli [ '/usr/bin/node', '/usr/bin/npm', 'start' ]
2 info using [email protected]
3 info using [email protected]
4 verbose run-script [ 'prestart', 'start', 'poststart' ]
5 info lifecycle [email protected]~prestart: [email protected]
6 info lifecycle [email protected]~start: [email protected]
7 verbose lifecycle [email protected]~start: unsafe-perm in lifecycle true
8 verbose lifecycle [email protected]~start: PATH: /usr/lib/node_modules/npm/node_modules/npm-lifecycle/node-gyp-bin:/opt/zwave2mqtt/node_modules/.bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin
9 verbose lifecycle [email protected]~start: CWD: /opt/zwave2mqtt
10 silly lifecycle [email protected]~start: Args: [ '-c', 'node bin/www' ]
11 silly lifecycle [email protected]~start: Returned: code: 139  signal: null
12 info lifecycle [email protected]~start: Failed to exec start script
13 verbose stack Error: [email protected] start: `node bin/www`
13 verbose stack Exit status 139
13 verbose stack     at EventEmitter.<anonymous> (/usr/lib/node_modules/npm/node_modules/npm-lifecycle/index.js:332:16)
13 verbose stack     at EventEmitter.emit (events.js:223:5)
13 verbose stack     at ChildProcess.<anonymous> (/usr/lib/node_modules/npm/node_modules/npm-lifecycle/lib/spawn.js:55:14)
13 verbose stack     at ChildProcess.emit (events.js:223:5)
13 verbose stack     at maybeClose (internal/child_process.js:1021:16)
13 verbose stack     at Process.ChildProcess._handle.onexit (internal/child_process.js:283:5)
14 verbose pkgid [email protected]
15 verbose cwd /opt/zwave2mqtt
16 verbose Linux 4.15.0-76-generic
17 verbose argv "/usr/bin/node" "/usr/bin/npm" "start"
18 verbose node v12.14.1
19 verbose npm  v6.13.4
20 error code ELIFECYCLE
21 error errno 139
22 error [email protected] start: `node bin/www`
22 error Exit status 139
23 error Failed at the [email protected] start script.
23 error This is probably not a problem with npm. There is likely additional logging output above.
24 verbose exit [ 139, true ]

Edit, additional logging output from the service

Jan 29 12:37:15 zwave2mqtt zwave2mqtt[1803]: #033[39m#033[392020-01-29T12:37:15.780Z z2m:Gateway Error while discovering value 2-49-1-4 of node 2: Cannot set property 'unit_of_measurement' of undefined
Jan 29 12:37:15 zwave2mqtt zwave2mqtt[1803]: 2020-01-29T12:37:15.780Z z2m:Gateway Error while discovering value 2-50-1-0 of node 2: Cannot set property 'unit_of_measurement' of undefined
Jan 29 12:37:15 zwave2mqtt zwave2mqtt[1803]: 2020-01-29T12:37:15.781Z z2m:Gateway Error while discovering value 2-50-1-2 of node 2: Cannot set property 'unit_of_measurement' of undefined
Jan 29 12:37:15 zwave2mqtt zwave2mqtt[1803]: 2020-01-29T12:37:15.782Z z2m:Zwave node 2 ready: FIBARO System - FGD212 Dimmer 2 (Light Dimmer Switch)
Jan 29 12:37:24 zwave2mqtt zwave2mqtt[1803]: 2020-01-29T12:37:24.944Z z2m:App Zwave api call: setValue [ 2, 38, 1, 0, '40' ]
Jan 29 12:37:24 zwave2mqtt zwave2mqtt[1803]: m#033[39m2020-01-29 12:37:24.945 Info, Node002, Value::Set - COMMAND_CLASS_SWITCH_MULTILEVEL - Level - 0 - 1 - 40
Jan 29 12:37:24 zwave2mqtt zwave2mqtt[1803]: #033[39m#033[39m#033[39m2020-01-29 12:37:24.945 Info, Node002, SwitchMultilevel::Set - Setting to level 40
Jan 29 12:37:25 zwave2mqtt zwave2mqtt[1803]: #033[39m#033[39Segmentation fault (core dumped)

An additional note, I added just a binary switch and that does not cause an application crash. That one seems to work just fine.

@kingsleyadam It is related to the issue #141. @Fishwaldo told me that he is tring to fix this on OZW

@robertsLando, interesting that I don't see any stream buffer issues in my errors. Is that the correct issue?

Check my last comment on that issue

Got it, I see it now although it seems it should be a separate non related issue.

Thanks again for you help @robertsLando , I really appreciate it.

@kingsleyadam You welcome hope this will be fixed soon :smiley:

I've got a _lab_ environment setup where I'm able to replicate this issue. Running openzwave 1.6, the latest zwave2mqtt code, a spare zwave controller, and a spare dimmer. Running on a raspberry pi.

I can test this whenever a fix is posted.

@Fishwaldo Please let me know when you create a fix for this crashes

I may ask help for testing the fix (in dev branch) when I’m ready. It makes some fairly substantial changes to some core OZW functions and I’m only about 80% sure it won’t break something else. Stay tuned. 😜

@Fishwaldo Thanks! I would like to relase a new version but I prefer to wait for ozw2 to fix this :)

@Fishwaldo, I have a minimal testing _lab_ setup that I can replicate my issues on. Let me know which commit to build off of and I can give it a try whenever you're ready.

@kingsleyadam I think this branch https://github.com/OpenZWave/open-zwave/tree/Dev

Testing now would be ok. But I’ve yet to actually test with secure devices so... I’m not a fan of wasting people’s time. Secure devices might require some further changes.... once I hit thats stage and we feel it’s “alpha” I’ll post here.

I moved my openzwave git branch and Dev and built/brought everything online.

I ran through my scenario that crashed the service and this time around it didn't crash and my MQTT entries got updated accordingly.

For me, this looks to be fixed. But I don't have any security devices.

I can test this again once it's in its final state.

Thanks. This is pretty big change to the core. Did you only test with a dimmer?

@Fishwaldo , I also tested this with a standard switch without issues.

I don't have a wide range of devices I can test with, unfortunately. But it seems to have addressed the issues I was having.

Thanks for the feedback.

FWIY, I also experienced the described issue with a FIBARO System - FGD212 Dimmer 2 and after testing it with your changes (from zwave2mqtt in docker, with a custom created image), it no longer crashes. I also have two NAS-WR01Z Power plug 12A connected an they still work.

Cheers!

I think I will create a release so :)

Yeah. I’m pretty confident there isn’t any major bugs now. Went a lot smoother than I thought

Was this page helpful?
0 / 5 - 0 ratings

Related issues

larstobi picture larstobi  ·  8Comments

christoph-luebbe picture christoph-luebbe  ·  8Comments

raspberrypython picture raspberrypython  ·  5Comments

lsilva171 picture lsilva171  ·  6Comments

dooz127 picture dooz127  ·  3Comments