[bug] Failed with error: ZWAVE: Controller status: Driver: Failed to initialize the driver: dest already exists

[robertpeteuil]

Version = 1.0.0-alpha.2 (most recent dev container, created at 2021-01-07T17:24:48)

Build/Run method

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

zwavejs2mqtt version: 5.7.0? (the version in the dev container specified above)

Describe the bug

• zwavejs2mqtt stopped processing ZWave and container log had error ZWAVE: Controller status: Driver: Failed to initialize the driver: dest already exists
  • web UI and mqtt were still running, but it couldn't process any zwave signals
• failed attempts to fix
  • stop/start new container
  • reboot host
  • delete mqtt sub-directory in store before starting new container
    • I have a local store folder mapped to /usr/src/app/store like your docker compose example
• how I eventually fixed it
  • deleted entire local store directory & contents
  • started new container
  • imported settings.json & nodes.json via web UI
• If this happens again
  • Is there was way to automate configuration at startup? (important for high-availability & recover-ability)
  • can I create the store dir and place settings & nodes file into it before starting container?

To Reproduce

• Unsure how to reproduce as I have no idea what triggered it
• Any ideas on what might cause the error: ZWAVE: Controller status: Driver: Failed to initialize the driver: dest already exists

Expected behavior

• If the ZWave controller cannot be initialized, container should exit with an error code.
  • This will allow it to get picked up by logging & monitoring tools which can (hopefully) kick off a process to fix/restart.

Additional context

• Here's the container log after one of the reboots (when triaging)
  • unfortunately, debug log inside the container went away as soon as I started to triage

2021-01-09 17:43:38.462 WARN STORE: scenes.json not found
/bin/sh: git: not found
2021-01-09 17:43:40.170 INFO APP: Version: 1.0.0-alpha.2
2021-01-09 17:43:40.172 INFO APP: Application path:/usr/src/app
2021-01-09 17:43:40.390 INFO MQTT: Connecting to mqtt://192.168.1.10:1883
2021-01-09 17:43:40.512 INFO ZWAVE: Connecting to /dev/ttyUSB0
Logging to file:
/usr/src/app/bin/zwave-1.log
2021-01-09 17:43:40.588 INFO APP: Listening on port 8091
2021-01-09 17:43:40.786 INFO MQTT: MQTT client connected
2021-01-09 17:43:42.981 INFO ZWAVE: Controller status: Driver: Failed to initialize the driver: dest already exists.
2021-01-09 17:43:43.088 INFO SOCKET: New connection abcdef-123456789
2021-01-09 17:43:50.094 INFO APP: GET /api/settings 200 165.257 ms - 787
2021-01-09 17:43:50.717 INFO SOCKET: Event INITED emitted to abcdef-123456789
2021-01-09 17:43:54.384 INFO APP: GET /api/settings 304 106.951 ms - -
2021-01-09 17:43:54.827 INFO SOCKET: Event INITED emitted to abcdef-123456789

• Container Log where I got it working after deleting local storage

2021-01-09 17:47:50.205 WARN STORE: settings.json not found
2021-01-09 17:47:50.275 WARN STORE: scenes.json not found
2021-01-09 17:47:50.276 WARN STORE: nodes.json not found
/bin/sh: git: not found
2021-01-09 17:47:51.850 INFO APP: Version: 1.0.0-alpha.2
2021-01-09 17:47:51.852 INFO APP: Application path:/usr/src/app
2021-01-09 17:47:52.000 ERROR GATEWAY: Zwave settings are not valid
2021-01-09 17:47:52.006 INFO APP: Listening on port 8091
2021-01-09 17:47:52.434 INFO SOCKET: New connection abcdef-123456789
2021-01-09 17:48:06.418 INFO APP: GET /api/settings 200 173.769 ms - 105
2021-01-09 17:48:06.970 INFO SOCKET: Event INITED emitted to abcdef-123456789
2021-01-09 17:48:10.169 INFO APP: GET /api/settings 304 127.139 ms - -
2021-01-09 17:48:18.583 INFO GATEWAY: Closing Gateway...
2021-01-09 17:48:18.665 INFO MQTT: Connecting to mqtt://192.168.1.10:1883
2021-01-09 17:48:18.804 INFO ZWAVE: Connecting to /dev/ttyUSB0
Logging to file:
/usr/src/app/bin/zwave-1.log
2021-01-09 17:48:18.874 INFO APP: POST /api/settings 200 372.986 ms - 63
2021-01-09 17:48:18.923 INFO MQTT: MQTT client connected
2021-01-09 17:48:21.511 INFO ZWAVE: Zwave driver is ready
2021-01-09 17:48:21.513 INFO ZWAVE: Controller status: Driver ready
2021-01-09 17:48:21.517 INFO ZWAVE: Node added 1

[robertsLando]

@AlCalzone Any clue about this error?

[robertpeteuil]

Thanks. I realize this might be tough without all the logs. I don’t care so much about the error per se, just want to be able to make an automated way to recover for high-availability.

• I’ll continue to monitor my setup, as I think I saw this once when I was first starting.
• Next time I’ll capture the internal debug logs before terminating the container.

[AlCalzone]

Thats fixed in 6.0.0-alpha.3, which contains this:
AlCalzone/jsonl-db#108

[AlCalzone]

@robertpeteuil you'll find a .bak file in your store and probably a .jsonl with a similar name.
If .bak has 0 bytes size, delete it.
If .jsonl has 0 bytes size, delete it and rename the .bak.

[robertpeteuil]

Thanks @AlCalzone.

• Yes, in my old store directory did have several files with the suffix .bak (I made a backup of it before deleting.)
• I had created these before changing the config and/or restarting (Ironically, to help track changes)
  • Fortunately, I've been copying them to another dir since this issue

I'll download the latest dev image (created a couple hours ago) and restarted.

• Working great, and I noticed the Honeywell switch added here is now identified!
• The version number is still 1.0.0-alpha.2 in Web UI and mqtt _CLIENTS/ZWAVE_GATEWAY-server\version key - but i suspect this is just an oversight, as it may not be the official A3 yet.

[robertsLando]

@robertpeteuil If you are using docker, use dev tag