[Bug]: Does not reconnect when the TCP connection is broken

[andyboeh]

Checklist

• I am not using Home Assistant. Or: a developer has told me to come here.
• I have checked the troubleshooting section and my problem is not described there.
• I have read the changelog and my problem is not mentioned there.

Deploy method

Docker

Zwavejs2Mqtt version

6.4.1

ZwaveJS version

8.11.1

Describe the bug

I'm using a Z-Wave adapter shared via TCP (ser2net on the server side). Today, I had to reboot the device with the dongle and, as expected, the connection broke. However, it is not restored automatically as I had expected. Instead, the following message is displayed:
Driver: Serial port errored: read ETIMEDOUT (ZW0100)

It would be nice if it tried to reconnect every few seconds until the server can be reached again. We already worked on a similar bug in zwave-js/zwave-js-ui#1246 and I saw similar reports in #3509.

To Reproduce

1. Connect the Z-Wave dongle via ser2net
2. Stop ser2net
3. Wait for the lost connection in zwavejs2mqtt
4. Start ser2net

This gives Driver: Serial port errored: The socket closed unexpectedly! (ZW0100), but it doesn't reconnect either!

Expected behavior

After 4., the connection should be auto-restored.

Additional context

No response

[robertsLando]

@AlCalzone Does that throws a driver error?

[AlCalzone]

https://github.com/zwave-js/node-zwave-js/pull/3520/files

It should emit a ZWaveError with code Driver_Failed.

[robertsLando]

@andyboeh Could you attach zwavejs logs please? I always try a restart when there is a driver error

[andyboeh]

Here you go - nothing more happens, it just sits there displaying the error although the server is already restarted.

zwavejs_2022-02-01.log

[AlCalzone]

2022-02-01T15:54:52.754Z DRIVER   Serial port errored: The socket closed unexpectedly! (ZW0100)
2022-02-01T15:54:52.757Z DRIVER   destroying driver instance...
2022-02-01T15:54:52.776Z DRIVER   driver instance destroyed
2022-02-01T15:54:52.786Z DRIVER   ███████╗ ██╗    ██╗  █████╗  ██╗   ██╗ ███████╗             ██╗ ███████╗
                                  ╚══███╔╝ ██║    ██║ ██╔══██╗ ██║   ██║ ██╔════╝             ██║ ██╔════╝
                                    ███╔╝  ██║ █╗ ██║ ███████║ ██║   ██║ █████╗   █████╗      ██║ ███████╗
                                   ███╔╝   ██║███╗██║ ██╔══██║ ╚██╗ ██╔╝ ██╔══╝   ╚════╝ ██   ██║ ╚════██║
                                  ███████╗ ╚███╔███╔╝ ██║  ██║  ╚████╔╝  ███████╗        ╚█████╔╝ ███████║
                                  ╚══════╝  ╚══╝╚══╝  ╚═╝  ╚═╝   ╚═══╝   ╚══════╝         ╚════╝  ╚══════╝
2022-02-01T15:54:52.786Z DRIVER   version 8.11.1
2022-02-01T15:54:52.786Z DRIVER   
2022-02-01T15:54:52.786Z DRIVER   starting driver...
2022-02-01T15:54:52.788Z DRIVER   opening serial port tcp://SercommPrivate.lan:5000

The driver is also being restarted, but then it doesn't connect... I'll have to check why.

[andyboeh]

We had a partial power outage today where both of my Z-Wave controllers lost power but the server running zwave-js stayed online (thanks to its UPS). Once again, I had to manually reconnect to the controllers.

[vlycop]

So i found something, debugging with F11 is very inconsistent, i hate it.
When starting the debuger with a fake/down tcp ip, the serial.on("close", () immediately trigger, but since it have a [if (this.isOpen) {](

node-zwave-js/packages/serial/src/ZWaveSocket.ts

Line 21 in 966e51f

if (this.isOpen) {

) i doesn't do anything more and silently failed.
I believe this cause a lack of 'error' that the UI should catch to try a restart.
Removing the if sadly still don't emit the error in the log but at least to go downsteam. i'll keep digging when i have some time

[vlycop]

it is re-filtered by

node-zwave-js/packages/zwave-js/src/lib/driver/Driver.ts

Line 788 in 966e51f

.on("error", (err) => {

				if (this.isSoftResetting && !this.serial?.isOpen) {
					// A disconnection while soft resetting is to be expected
					return;
				} else if (!this._isOpen) {
					// tryOpenSerialport takes care of error handling
					return;
				}

Removing it to does allow the error to come through.

Debugger attached.
Debugger attached.
Debugger attached.
13:42:50.368 DRIVER   ███████╗ ██╗    ██╗  █████╗  ██╗   ██╗ ███████╗             ██╗ ███████╗
                      ╚══███╔╝ ██║    ██║ ██╔══██╗ ██║   ██║ ██╔════╝             ██║ ██╔════╝
                        ███╔╝  ██║ █╗ ██║ ███████║ ██║   ██║ █████╗   █████╗      ██║ ███████╗
                       ███╔╝   ██║███╗██║ ██╔══██║ ╚██╗ ██╔╝ ██╔══╝   ╚════╝ ██   ██║ ╚════██║
                      ███████╗ ╚███╔███╔╝ ██║  ██║  ╚████╔╝  ███████╗        ╚█████╔╝ ███████║
                      ╚══════╝  ╚══╝╚══╝  ╚═╝  ╚═╝   ╚═══╝   ╚══════╝         ╚════╝  ╚══════╝
13:42:50.371 DRIVER   version 9.0.1
13:42:50.372 DRIVER   
13:42:50.372 DRIVER   starting driver...
13:42:50.381 DRIVER   opening serial port tcp://192.168.20.63:5896
13:42:55.740 DRIVER   Serial port errored: connect ECONNREFUSED 192.168.20.63:5896
ZWaveError: Serial port errored: connect ECONNREFUSED 192.168.20.63:5896 (ZW0100)
    at ZWaveSocket.<anonymous> (/home/vlycop/Documents/Dev/node-zwave-js/packages/zwave-js/src/lib/driver/Driver.ts:792:19)
    at ZWaveSocket.emit (node:events:520:28)
    at ZWaveSocket.emit (node:domain:475:12)
    at Socket.<anonymous> (/home/vlycop/Documents/Dev/node-zwave-js/packages/serial/src/ZWaveSerialPortBase.ts:112:9)
    at Socket.emit (node:events:520:28)
    at Socket.emit (node:domain:475:12)
    at emitErrorNT (node:internal/streams/destroy:157:8)
    at emitErrorCloseNT (node:internal/streams/destroy:122:3)
    at processTicksAndRejections (node:internal/process/task_queues:83:21) {
  code: 100,
  context: undefined,
  transactionSource: undefined
}
13:42:55.746 DRIVER   destroying driver instance...
13:42:55.748 DRIVER   driver instance destroyed
ZWaveError: Serial port errored: The socket closed unexpectedly! (ZW0100)
    at ZWaveSocket.<anonymous> (/home/vlycop/Documents/Dev/node-zwave-js/packages/zwave-js/src/lib/driver/Driver.ts:792:19)
    at ZWaveSocket.emit (node:events:520:28)
    at ZWaveSocket.emit (node:domain:475:12)
    at Socket.<anonymous> (/home/vlycop/Documents/Dev/node-zwave-js/packages/serial/src/ZWaveSocket.ts:21:13)
    at Socket.emit (node:events:520:28)
    at Socket.emit (node:domain:475:12)
    at TCP.<anonymous> (node:net:687:12)
    at TCP.callbackTrampoline (node:internal/async_hooks:130:17) {
  code: 100,
  context: undefined,
  transactionSource: undefined
}
Waiting for the debugger to disconnect...
Waiting for the debugger to disconnect...
Waiting for the debugger to disconnect...

I feel like

node-zwave-js/packages/zwave-js/src/lib/driver/Driver.ts

Line 915 in 966e51f

try {

doesn't do it's job and don't catch the expected error to wait and retry a couple of time

[vlycop]

i have tried a lot of thing but this is overall to much for me.
I don't understand what happenes that cause everything to stop rather than continue after the socket.open is called.
I hope what i found could be of any use as i really need auto restart to work in order to move from openzwave to this project.

[vlycop]

Thank-you very much !