Does not reply within MQTT keep-alive

[jmgiaever]

Hi,

After my Z-wave network have grown, the daemon has started to fail when I do a reboot.

From the log:

ozwdaemon[1036]: [20201207 17:32:19.205 CET] [ozw.notifications] [debug]: Notification pvt_valueAdded: 281475859349521 Thread:  0xffff889b4450
**mosquitto**[1061]: 1607358739: Client qt-openzwave-1 has exceeded timeout, disconnecting.
ozwdaemon[1036]: [20201207 17:32:19.291 CET] [ozw.mqtt.publisher] [debug]: Publishing Event valueAdded: 281475859349521
ozwdaemon[1036]: [20201207 17:32:19.291 CET] [ozw.notifications] [debug]: Notification pvt_valueAdded: 562950836060177 Thread:  0xffff889b4450
[... ozwdaemon continues like this for a while ... ]
ozwdaemon.ozwdaemon[1036]: [20201207 17:32:21.539 CET] [ozw.mqtt.publisher] [debug]: MQTT State Change "Disconnected"
ozwdaemon[1036]: [20201207 17:32:21.539 CET] [ozw.mqtt.publisher] [warning]: Exiting on Failure
ozwdaemon[1036]: [20201207 17:32:21.539 CET] [ozw.mqtt.publisher] [warning]: MQTT Client Disconnnected
ozwdaemon[1036]: [20201207 17:32:21.539 CET] [ozw.mqtt.publisher] [warning]: MQTT Client Error "Transport Invalid"

I just scrolled through the code and was wondering if the reference to m_client for the ping responses should be this->m_client, as with the line 90-92?

I'm not very familiar with the code and not the language either, but though it would be ok to ask :)

[kpine]

Duplicate of #140. See that issue for workarounds.

[jmgiaever]

Oh, ok. But I tried out changing from m_client to this->m_client on line 93, and it doesn't crash anymore 👍 And I also got a feeling that ozwd booted up way faster. Could the missing reference to the internal field m_client been blocking the main thread?

Dec 08 13:42:24 [20201208 13:42:24.890 CET] [ozw.mqtt.publisher] [debug]: MQTT State Change "Connecting"
Dec 08 13:42:24 [20201208 13:42:24.890 CET] [ozw.mqtt.publisher] [info]: MQTT Client Connecting
Dec 08 13:42:24 [20201208 13:42:24.904 CET] [ozw.library] [debug]: Always - Node: 0 OpenZwave Version 1.6-1545-g1c7b6202 Starting Up

cat text.log | grep "ozw.mqtt.publisher" | grep "PingResponse"

Dec 08 13:44:30 [ozw.mqtt.publisher] [debug]: "Tue Dec 8 13:44:30 2020 PingResponse\n"
Dec 08 13:44:53 [ozw.mqtt.publisher] [debug]: "Tue Dec 8 13:44:53 2020 PingResponse\n"
Dec 08 13:45:53 [ozw.mqtt.publisher] [debug]: "Tue Dec 8 13:45:53 2020 PingResponse\n"
Dec 08 13:46:53 [ozw.mqtt.publisher] [debug]: "Tue Dec 8 13:46:53 2020 PingResponse\n"
Dec 08 13:47:53 [ozw.mqtt.publisher] [debug]: "Tue Dec 8 13:47:53 2020 PingResponse\n"
Dec 08 13:48:53 [ozw.mqtt.publisher] [debug]: "Tue Dec 8 13:48:53 2020 PingResponse\n"
Dec 08 13:49:53 [ozw.mqtt.publisher] [debug]: "Tue Dec 8 13:49:53 2020 PingResponse\n"
Dec 08 13:50:53 [ozw.mqtt.publisher] [debug]: "Tue Dec 8 13:50:53 2020 PingResponse\n"
Dec 08 13:51:53 [ozw.mqtt.publisher] [debug]: "Tue Dec 8 13:51:53 2020 PingResponse\n"
Dec 08 13:52:53 [ozw.mqtt.publisher] [debug]: "Tue Dec 8 13:52:53 2020 PingResponse\n"
Dec 08 13:53:53 [ozw.mqtt.publisher] [debug]: "Tue Dec 8 13:53:53 2020 PingResponse\n"
Dec 08 13:56:53 [ozw.mqtt.publisher] [debug]: "Tue Dec 8 13:56:53 2020 PingResponse\n"
Dec 08 13:57:53 [ozw.mqtt.publisher] [debug]: "Tue Dec 8 13:57:53 2020 PingResponse\n"
Dec 08 13:58:53 [ozw.mqtt.publisher] [debug]: "Tue Dec 8 13:58:53 2020 PingResponse\n"
Dec 08 13:59:53 [ozw.mqtt.publisher] [debug]: "Tue Dec 8 13:59:53 2020 PingResponse\n"
Dec 08 14:00:53 [ozw.mqtt.publisher] [debug]: "Tue Dec 8 14:00:53 2020 PingResponse\n"
Dec 08 14:01:53 [ozw.mqtt.publisher] [debug]: "Tue Dec 8 14:01:53 2020 PingResponse\n"
Dec 08 14:02:53 [ozw.mqtt.publisher] [debug]: "Tue Dec 8 14:02:53 2020 PingResponse\n"
Dec 08 14:03:53 [ozw.mqtt.publisher] [debug]: "Tue Dec 8 14:03:53 2020 PingResponse\n"
Dec 08 14:04:53 [ozw.mqtt.publisher] [debug]: "Tue Dec 8 14:04:53 2020 PingResponse\n"
Dec 08 14:05:53 [ozw.mqtt.publisher] [debug]: "Tue Dec 8 14:05:53 2020 PingResponse\n"
Dec 08 14:06:53 [ozw.mqtt.publisher] [debug]: "Tue Dec 8 14:06:53 2020 PingResponse\n"
Dec 08 14:07:53 [ozw.mqtt.publisher] [debug]: "Tue Dec 8 14:07:53 2020 PingResponse\n"
Dec 08 14:08:53 [ozw.mqtt.publisher] [debug]: "Tue Dec 8 14:08:53 2020 PingResponse\n"
Dec 08 14:09:53 [ozw.mqtt.publisher] [debug]: "Tue Dec 8 14:09:53 2020 PingResponse\n"
Dec 08 14:10:53 [ozw.mqtt.publisher] [debug]: "Tue Dec 8 14:10:53 2020 PingResponse\n"
Dec 08 14:11:53 [ozw.mqtt.publisher] [debug]: "Tue Dec 8 14:11:53 2020 PingResponse\n"
Dec 08 14:12:53 [ozw.mqtt.publisher] [debug]: "Tue Dec 8 14:12:53 2020 PingResponse\n"

Looks like the ping response is sent every minute after boot.

Edit: I actually see there's a gap between 13:53:53 and 13:56:53, but could that be because ozwdaemon is sending other data through mqtt and the ping response is not needed?

[m3ki]

@jmgiaever Hey, yeah i think you're right. I am a bit rusty with cpp, but it does look like it maybe missing a reference to a field. It's an odd way of making a typo though.

[jmgiaever]

True :) For anyone who wants to test it, it's available as a snap - in ithe edge channel snap install ozwdaemon --edge.

See ozwdaemon.exec --help for description on usage.

[kpine]

There shouldn't be any difference between this->m_client and m_client. I would guess it's just a style preference, so fixing it would at least make it consistent, but I wouldn't expect any functional change.

The ping responses are working with the existing code, except for the problem in #140. If you are not seeing the ozw.notifications logs after your change, it means you didn't reproduce your original problem. Did you see those?

[jmgiaever]

Ok, maybe it's possible to reference an internal field within it's own scope by skipping this. I know it isn't possible to reference fields of a struct in C, go etc or object orientated languages (that I know of at least).

[m3ki]

So trying to remember cpp, you only need to use "this" in this case if there is another variable hiding the instance variable right? why did your code work better? you say your code worked faster. Did you delete the ozw cache and try your code then?

keeping in mind that omitting it is inconsistent with the rest of the code ;)

[m3ki]

A friend compiled "this" fix and added my fix to add MQTT_KEEP_ALIVE environment variable to change timeout as needed
docker here https://hub.docker.com/r/firstof9/qt-ozwdaemon

[Olen]

Just added a PR for the "this"-fix.

[Olen]

The @firstof9 container also includes updates of lots of underlying dependecies, including the QT-version etc. so it might behave better also because of fixes in other libraries.

[m3ki]

@Olen yes but, there was a reason for using older QT libraries. Newer libraries break all in one container for ozw admin.

[firstof9]

Correct it totally breaks the bundled ozw-admin.