search

OpenZWave / qt-openzwave

QT5 Wrapper for OpenZWave
GNU Lesser General Public License v3.0
105 stars 30 forks source link

OZW (qt-openzwave docker) stops updating MQTT - yet keep alive continues #198

Closed mkmer closed 1 year ago

mkmer commented 3 years ago

Over the last month, I've found the qt-openzwave docker container (multiple times) in a state where the log files show the MQTT client answering PING to the MQTT server, but the ozw daemon is not longer updating items from the zwave usb controller. Turning lights on/off does not produce log data (thus indicating the daemon is either dead or no longer talking to the USB stick). Attempting to trigger a switch fails (as expected in this state).

Sifting through the logs isn't revealing any warning/error data indicating a crash, and restarting the container always results in a functioning zwave network (again).

I'll be happy to share log files and anything else or dig through files if needed - as clearly this is not enough information to debug anything.

mkmer commented 3 years ago

Maybe related to scene action? Attached is the last activity seen from ozw.library - then just MQTT pings for hours.

2021-01-18 20:03:44.218813227 [20210118 15:03:44.218 EST] [ozw.library] [info]: Info - Node: 20 Automatically Clearing Scene 1 in 1000ms 2021-01-18 20:03:44.218828197 [20210118 15:03:44.218 EST] [ozw.logging] [debug]: popping Log Mesages 2021-01-18 20:03:44.220910945 [20210118 15:03:44.220 EST] [ozw.library] [info]: Info - Node: 0 Timer: adding event in 1000 ms 2021-01-18 20:03:44.220985308 [20210118 15:03:44.220 EST] [ozw.logging] [debug]: popping Log Mesages 2021-01-18 20:03:44.222821686 [20210118 15:03:44.222 EST] [ozw.library] [debug]: Detail - Node: 0 Timer: waiting with timeout 1000 ms 2021-01-18 20:03:44.222888217 [20210118 15:03:44.222 EST] [ozw.logging] [debug]: popping Log Mesages 2021-01-18 20:03:44.224827797 [20210118 15:03:44.224 EST] [ozw.library] [debug]: Detail - Node: 20 Notification: ValueChanged CC: COMMAND_CLASS_CENTRAL_SCENE I nstance: 1 Index: 1 2021-01-18 20:03:44.224877196 [20210118 15:03:44.224 EST] [ozw.logging] [debug]: popping Log Mesages 2021-01-18 20:03:44.226746658 [20210118 15:03:44.226 EST] [ozw.notifications] [debug]: Notification pvt_valueChanged: 281475317940244 Thread: 0x7fb02642f9c0 2021-01-18 20:03:44.228613823 [20210118 15:03:44.228 EST] [ozw.mqtt.publisher] [debug]: Publishing Event valueChanged: 281475317940244 2021-01-18 20:03:45.224918694 [20210118 15:03:45.224 EST] [ozw.library] [info]: Info - Node: 0 Timer: delayed event 2021-01-18 20:03:45.225001026 [20210118 15:03:45.224 EST] [ozw.logging] [debug]: popping Log Mesages 2021-01-18 20:03:45.226864296 [20210118 15:03:45.226 EST] [ozw.library] [debug]: Detail - Node: 20 Value Updated: old value=1, new value=0, type=list 2021-01-18 20:03:45.226937929 [20210118 15:03:45.226 EST] [ozw.logging] [debug]: popping Log Mesages 2021-01-18 20:03:45.228780717 [20210118 15:03:45.228 EST] [ozw.library] [debug]: Detail - Node: 20 Changes to this value are not verified 2021-01-18 20:03:45.228849113 [20210118 15:03:45.228 EST] [ozw.logging] [debug]: popping Log Mesages 2021-01-18 20:03:45.230686037 [20210118 15:03:45.230 EST] [ozw.library] [debug]: Detail - Node: 0 Timer: waiting with timeout -1 ms 2021-01-18 20:03:45.230788129 [20210118 15:03:45.230 EST] [ozw.logging] [debug]: popping Log Mesages 2021-01-18 20:03:45.233131607 [20210118 15:03:45.232 EST] [ozw.library] [debug]: Detail - Node: 20 Notification: ValueChanged CC: COMMAND_CLASS_CENTRAL_SCENE I nstance: 1 Index: 1 2021-01-18 20:03:45.233228542 [20210118 15:03:45.233 EST] [ozw.logging] [debug]: popping Log Mesages 2021-01-18 20:03:45.235647048 [20210118 15:03:45.235 EST] [ozw.notifications] [debug]: Notification pvt_valueChanged: 281475317940244 Thread: 0x7fb02642f9c0 2021-01-18 20:03:45.239016020 [20210118 15:03:45.238 EST] [ozw.mqtt.publisher] [debug]: Publishing Event valueChanged: 281475317940244 2021-01-18 20:04:43.748061545 [20210118 15:04:43.747 EST] [ozw.mqtt.publisher] [debug]: "Mon Jan 18 15:04:43 2021 PingResponse\n" 2021-01-18 20:05:43.748356579 [20210118 15:05:43.748 EST] [ozw.mqtt.publisher] [debug]: "Mon Jan 18 15:05:43 2021 PingResponse\n" 2021-01-18 20:06:43.748122523 [20210118 15:06:43.748 EST] [ozw.mqtt.publisher] [debug]: "Mon Jan 18 15:06:43 2021 PingResponse\n" 2021-01-18 20:07:43.748799825 [20210118 15:07:43.748 EST] [ozw.mqtt.publisher] [debug]: "Mon Jan 18 15:07:43 2021 PingResponse\n" 2021-01-18 20:08:43.771170063 [20210118 15:08:43.767 EST] [ozw.mqtt.publisher] [debug]: "Mon Jan 18 15:08:43 2021 PingResponse\n" 2021-01-18 20:09:43.748217971 [20210118 15:09:43.748 EST] [ozw.mqtt.publisher] [debug]: "Mon Jan 18 15:09:43 2021 PingResponse\n" 2021-01-18 20:10:43.748602206 [20210118 15:10:43.748 EST] [ozw.mqtt.publisher] [debug]: "Mon Jan 18 15:10:43 2021 PingResponse\n" 2021-01-18 20:11:43.748086481 [20210118 15:11:43.747 EST] [ozw.mqtt.publisher] [debug]: "Mon Jan 18 15:11:43 2021 PingResponse\n" 2021-01-18 20:12:43.751803489 [20210118 15:12:43.751 EST] [ozw.mqtt.publisher] [debug]: "Mon Jan 18 15:12:43 2021 PingResponse\n"

mkmer commented 3 years ago

Further research indicates this may be a USB connectivity issue with the Zwave controller. In an attempt to recreate the issue, disconnecting then reconnecting the USB device results in what appears to be the same behavior. It appears the Daemon doesn't identify a reset of the hardware / disconnection of the hardware and reset the connection.

While I can't be sure this is my current issue, a reset of the zwave controller results in the same condition (and probably shouldn't).

jamesgol commented 3 years ago

Came here to see if anyone else was having the same problem. Looks like I'll be checking my USB connectivity