ZWave Controller stopped working after reboot (no Updates (really!) - using ser2net, socat and docker)

Add-ons Bindings
1

Hi all,

Problem:
My zWave Stick (Aoetec Gen 5) connected via ser2net/socat from an other RPi3 suddenly stopped working after a restart of the docker container running my openhab. It was working before for quite some time.

Setup:

Details:
For some unknown reason, my docker container running openhab restarted in the middle of the night a couple of weeks ago. Since then I am not able to get my zwave Controller running again.

The Controller remains offline like this:
grafik

The USB Port is configured like this:
grafik

The socat log looks good, I think its working.

2023/01/03 23:41:46 socat[19302] I socat by Gerhard Rieger - see www.dest-unreach.org
2023/01/03 23:41:46 socat[19302] I This product includes software developed by the OpenSSL Project for use in the OpenSSL Toolkit. (http://www.openssl.org/)
2023/01/03 23:41:46 socat[19302] I This product includes software written by Tim Hudson (tjh@cryptsoft.com)
2023/01/03 23:41:46 socat[19302] I setting option "symbolic-link" to "/dev/ttyUSB0"
2023/01/03 23:41:46 socat[19302] I setting option "raw"
2023/01/03 23:41:46 socat[19302] I setting option "user" to 107
2023/01/03 23:41:46 socat[19302] I setting option "group" to 20
2023/01/03 23:41:46 socat[19302] I setting option "perm" to 511
2023/01/03 23:41:46 socat[19302] I openpty({4}, {5}, {"/dev/pts/2"},,) -> 0
2023/01/03 23:41:46 socat[19302] N PTY is /dev/pts/2
2023/01/03 23:41:46 socat[19302] N opening connection to AF=2 192.168.178.32:3333
2023/01/03 23:41:46 socat[19302] I starting connect loop
2023/01/03 23:41:46 socat[19302] I socket(2, 1, 6) -> 6
2023/01/03 23:42:01 socat[19302] N successfully connected from local address AF=2 192.168.178.39:57706
2023/01/03 23:42:01 socat[19302] I resolved and opened all sock addresses
2023/01/03 23:42:01 socat[19302] N starting data transfer loop with FDs [4,4] and [6,6]
2023/01/03 23:42:15 socat[19302] I transferred 18 bytes from 6 to 4
2023/01/03 23:42:15 socat[19302] I transferred 31 bytes from 4 to 6
2023/01/03 23:42:17 socat[19302] I transferred 18 bytes from 6 to 4
2023/01/03 23:42:17 socat[19302] I transferred 31 bytes from 4 to 6
2023/01/03 23:42:18 socat[19302] I transferred 18 bytes from 6 to 4

This is the virtual USB Device on the host machine:

grafik
grafik814×77 6.88 KB

And this is the same device inside my docker container:
grafik

This is the volume linking for the USB Port in my docker-compose file:

    volumes:
      - "/etc/localtime:/etc/localtime:ro"
      - "/etc/timezone:/etc/timezone:ro"
      - "/opt/openhab/openhab_3.2/openhab_addons:/openhab/addons"
      - "/opt/openhab/openhab_3.2/openhab_conf:/openhab/conf"
      - "/opt/openhab/openhab_3.2/openhab_userdata:/openhab/userdata"
      - "/dev/ttyUSB0:/dev/ttyUSB0"

I restarted everything a couple of time already, the Controller remains offline. This is what I see in my openhab.log after a restart of the openhab container:

2023-01-04 01:04:47.027 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - Creating ZWave discovery service for zwave:serial_zstick:6fca5138fc with scan time of 60
2023-01-04 01:04:47.034 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - ZWave discovery: Active zwave:serial_zstick:6fca5138fc
2023-01-04 01:04:47.037 [INFO ] [zwave.handler.ZWaveControllerHandler] - Attempting to add listener when controller is null
2023-01-04 01:04:47.298 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Initializing ZWave serial controller.
2023-01-04 01:04:47.301 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Initializing ZWave Controller zwave:serial_zstick:6fca5138fc.
2023-01-04 01:04:47.414 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:6fca5138fc:node5.
2023-01-04 01:04:47.427 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: MANUFACTURER not set
2023-01-04 01:04:47.469 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:6fca5138fc:node9.
2023-01-04 01:04:47.472 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:6fca5138fc:node8.
2023-01-04 01:04:47.477 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: MANUFACTURER not set
2023-01-04 01:04:47.494 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 9: MANUFACTURER not set
2023-01-04 01:04:47.547 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:6fca5138fc:node19.
2023-01-04 01:04:47.658 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:6fca5138fc:node6.
2023-01-04 01:04:47.696 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:6fca5138fc:node21.
2023-01-04 01:04:47.707 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:6fca5138fc:node20.
2023-01-04 01:04:47.719 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:6fca5138fc:node17.
2023-01-04 01:04:47.759 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:6fca5138fc:node15.
2023-01-04 01:04:47.810 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:6fca5138fc:node7.
2023-01-04 01:04:47.832 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:6fca5138fc:node18.
2023-01-04 01:04:47.849 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:6fca5138fc:node16.
2023-01-04 01:04:47.849 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:6fca5138fc:node14.
2023-01-04 01:04:47.854 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 14: MANUFACTURER not set
2023-01-04 01:04:47.941 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:6fca5138fc:node12.
2023-01-04 01:04:47.966 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: MANUFACTURER not set
2023-01-04 01:04:47.983 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:6fca5138fc:node13.
2023-01-04 01:06:17.165 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - No bridgeUID found in getConfigDescription thing:zwave:serial_zstick:6fca5138fc

I am a little lost here, it should work… but it does not.

Any help is greatly appreciated!

cheers
Reinhard

2

There’s a thread on this here (since I kept having the same problems).

Quick fix (though not sustainable) here. Long-term fix here.

3

Thanks for your reply, but unfortunately that seems not to be my issue.
I just can’t figure out, what the problem is. But I have none of the lock files

4

I do not use this type of setup, but is it normal that the logs say

and your picture has a “p” inserted /dev/ttypUSB0 ?

5

Since you are connecting to the zwave device from ser2net is there a reason you are using socat on the openhab instance instead of specifying the remote ser2net in the Thing as:
port="rfc2217://nameofremoteser2net:ser2netport" ?

6

and your picture has a “p” inserted /dev/ttypUSB0 ?

That is a typo indeed, good find :slight_smile: I already changed it, and it did not change anything

7

Since you are connecting to the zwave device from ser2net is there a reason you are using socat on the openhab instance instead of specifying the remote ser2net in the Thing as:
port="rfc2217://nameofremoteser2net:ser2netport" ?

I did not know that this was possible. I just followed the guide mentioned above. I will try that later today. But I am running openhab in a container, so that might be a problem. (not sure, will see)

8

I was finally able to check the direct ser2net connection. And it is working! Yeah! :smiley:

I had to change my ser2net config like this. The commented line is how it was, and the other is how it is now.

#3333:raw:0:/dev/ttyACM0:115200 8DATABITS NONE 1STOPBIT
3333:telnet:0:/dev/ttyACM0:115200 8DATABITS NONE 1STOPBIT remctl