qt-openzwave crashes when trying to send command/enablepoll/

aav7fl commented 4 years ago

I'm trying to enable polling for a z-wave (non-plus) device with (possibly) buggy firmware. One of the nodes seems to require polling to get updated.

(This is exploring troubleshooting options from https://github.com/OpenZWave/open-zwave/issues/2215#issuecomment-632480262)

One of my attempted solutions is to enable polling (the correct way) via the qz-openzwave mqtt commands.

Previously I was manually editing the poll_intensity value in my ozwcache_0x*.xml file to force polling:

<Value type="decimal" genre="user" instance="3" index="5" label="Humidity" units="%" read_only="true" write_only="false" verify_changes="false" poll_intensity="96" min="0" max="0" value="35">
    <Help>Humidity Sensor Value</Help>
</Value>

I'm pretty sure that's not the the correct way to do this. Based on the documentation, I should be able to enable polling for a specific ValudeIDKey though an MQTT topic.

https://github.com/OpenZWave/qt-openzwave/blob/master/docs/MQTT.md#enablepoll

However, when I send the payload though OpenZWave/1/command/enablepoll/, qt-openzwave crashes.

qt-openzwave Crash Log

Crash Log

```txt [20200522 13:43:49.298 UTC] [qt.mqtt.connection.verbose] [debug]: void QMqttConnection::transportReadReady(), [20200522 13:43:49.298 UTC] [qt.mqtt.connection.verbose] [debug]: Received PUBLISH, [20200522 13:43:49.298 UTC] [qt.mqtt.connection.verbose] [debug]: Finalize PUBLISH: topic: QMqttTopicName("OpenZWave/1/command/enablepoll/") payloadLength: 46, [20200522 13:43:49.299 UTC] [ozw.mqtt.commands] [debug]: Got "OpenZWave/1/command/enablepoll/" Message: "{\"ValueIDKey\":1407374938882098,\"Intensity\":96}", ozwdaemon: /usr/include/rapidjson/document.h:1053: rapidjson::GenericValue& rapidjson::GenericValue::operator[](const rapidjson::GenericValue&) [with SourceAllocator = rapidjson::MemoryPoolAllocator<>; Encoding = rapidjson::UTF8<>; Allocator = rapidjson::MemoryPoolAllocator<>]: Assertion `false' failed., [20200522 13:43:49.336 UTC] [default] [warning]: =============================, [20200522 13:43:49.336 UTC] [default] [warning]: CRASH!!! - Dumping Backtrace:, [20200522 13:43:49.336 UTC] [default] [warning]: =============================, [20200522 13:43:49.336 UTC] [default] [warning]: #1 0x000055dc70a8f5d2 sp=0x000055dc71c4bd40 dumpCallback(google_breakpad::MinidumpDescriptor const&, void*, bool) + 0x32, [20200522 13:43:49.336 UTC] [default] [warning]: #2 0x000055dc70aa6da5 sp=0x000055dc71c4bf90 google_breakpad::ExceptionHandler::GenerateDump(google_breakpad::ExceptionHandler::CrashContext*) + 0x375, [20200522 13:43:49.337 UTC] [default] [warning]: #3 0x000055dc70aa70ef sp=0x000055dc71c4c030 google_breakpad::ExceptionHandler::SignalHandler(int, siginfo_t*, void*) + 0x9f, [20200522 13:43:49.337 UTC] [default] [warning]: #4 0x00007f7ae97a1110 sp=0x000055dc71c4c100 funlockfile + 0x50, [20200522 13:43:49.337 UTC] [default] [warning]: #5 0x00007f7ae9438761 sp=0x00007ffd9106e2f0 gsignal + 0x141, [20200522 13:43:49.337 UTC] [default] [warning]: #6 0x00007f7ae942255b sp=0x00007ffd9106e410 abort + 0x127, [20200522 13:43:49.337 UTC] [default] [warning]: #7 0x00007f7ae942242f sp=0x00007ffd9106e540 __libc_freeres + 0x127, [20200522 13:43:49.337 UTC] [default] [warning]: #8 0x00007f7ae9431092 sp=0x00007ffd9106e590 __assert_fail + 0x42, [20200522 13:43:49.338 UTC] [default] [warning]: #9 0x000055dc70a8e87f sp=0x00007ffd9106e5c0 MqttCommand_EnablePoll::processMessage(rapidjson::GenericDocument, rapidjson::MemoryPoolAllocator, rapidjson::CrtAllocator>&) + 0x3cf, [20200522 13:43:49.338 UTC] [default] [warning]: #10 0x000055dc70a7ce09 sp=0x00007ffd9106e650 MqttCommand::messageReceived(QMqttMessage) + 0x2c59, [20200522 13:43:49.338 UTC] [default] [warning]: #11 0x000055dc70a7d379 sp=0x00007ffd9106e8c0 QtPrivate::QSlotObject, void>::impl(int, QtPrivate::QSlotObjectBase*, QObject*, void**, bool*) + 0x49, [20200522 13:43:49.338 UTC] [default] [warning]: #12 0x00007f7ae9a554e8 sp=0x00007ffd9106e8f0 QMetaObject::activate(QObject*, int, int, void**) + 0x918, [20200522 13:43:49.338 UTC] [default] [warning]: #13 0x00007f7ae9ec81f5 sp=0x00007ffd9106e9e0 QMqttSubscription::messageReceived(QMqttMessage) + 0x35, [20200522 13:43:49.339 UTC] [default] [warning]: #14 0x00007f7ae9ebe1b4 sp=0x00007ffd9106ea10 QMqttConnection::finalize_publish() + 0x1d4, [20200522 13:43:49.339 UTC] [default] [warning]: #15 0x00007f7ae9ebeb1f sp=0x00007ffd9106eae0 QMqttConnection::processDataHelper() + 0x2bf, [20200522 13:43:49.339 UTC] [default] [warning]: #16 0x00007f7ae9ebf2a8 sp=0x00007ffd9106eb40 QMqttConnection::transportReadReady() + 0x78, [20200522 13:43:49.339 UTC] [default] [warning]: #17 0x00007f7ae9a554e8 sp=0x00007ffd9106ebb0 QMetaObject::activate(QObject*, int, int, void**) + 0x918, [20200522 13:43:49.339 UTC] [default] [warning]: #18 0x00007f7ae9dd1874 sp=0x00007ffd9106eca0 QAbstractSocket::setSocketDescriptor(long long, QAbstractSocket::SocketState, QFlags) + 0x664, [20200522 13:43:49.340 UTC] [default] [warning]: #19 0x00007f7ae9dd190b sp=0x00007ffd9106ecc0 QAbstractSocket::setSocketDescriptor(long long, QAbstractSocket::SocketState, QFlags) + 0x6fb, [20200522 13:43:49.340 UTC] [default] [warning]: #20 0x00007f7ae9de3921 sp=0x00007ffd9106ecf0 QTcpServer::incomingConnection(long long) + 0xb561, [20200522 13:43:49.340 UTC] [default] [warning]: #21 0x00007f7ae9a2aa2f sp=0x00007ffd9106ed00 QCoreApplication::notifyInternal2(QObject*, QEvent*) + 0x15f, [20200522 13:43:49.340 UTC] [default] [warning]: #22 0x00007f7ae9a813c5 sp=0x00007ffd9106ed70 QEventDispatcherGlib::registerSocketNotifier(QSocketNotifier*) + 0x145, [20200522 13:43:49.340 UTC] [default] [warning]: #23 0x00007f7ae8ae160d sp=0x00007ffd9106edb0 g_main_context_dispatch + 0x27d, [20200522 13:43:49.340 UTC] [default] [warning]: #24 0x00007f7ae8ae1890 sp=0x00007ffd9106ee30 g_main_context_dispatch + 0x500, [20200522 13:43:49.340 UTC] [default] [warning]: #25 0x00007f7ae8ae191f sp=0x00007ffd9106ee90 g_main_context_iteration + 0x2f, [20200522 13:43:49.341 UTC] [default] [warning]: #26 0x00007f7ae9a807c1 sp=0x00007ffd9106eeb0 QEventDispatcherGlib::processEvents(QFlags) + 0x61, [20200522 13:43:49.341 UTC] [default] [warning]: #27 0x00007f7ae9a296db sp=0x00007ffd9106ef00 QEventLoop::exec(QFlags) + 0x12b, [20200522 13:43:49.341 UTC] [default] [warning]: #28 0x00007f7ae9a31182 sp=0x00007ffd9106ef80 QCoreApplication::exec() + 0x92, [20200522 13:43:49.341 UTC] [default] [warning]: #29 0x000055dc70a49cfc sp=0x00007ffd9106efe0 main + 0x2b0c, [20200522 13:43:49.341 UTC] [default] [warning]: #30 0x00007f7ae9423e0b sp=0x00007ffd9106f4e0 __libc_start_main + 0xeb, [20200522 13:43:49.341 UTC] [default] [warning]: #31 0x000055dc70a4af8a sp=0x00007ffd9106f5a0 _start + 0x2a, [20200522 13:43:49.341 UTC] [default] [warning]: dumpCallback Succeeded: true at /opt/ozw/config/crashes//324eebee-d923-4c90-a3ba5380-78664f7d.dmp, [20200522 13:43:49.341 UTC] [default] [warning]: Uploading MiniDump to https://sentry.io/api/1868130/minidump/?sentry_key=e086ba93030843199aab391947d205da, Failed to open curl lib from binary, use libcurl.so instead, double free or corruption (!prev), ```

qt-openzwave Crash Dump

Here's the crash dump (as a zip since GitHub doesn't like *.dmp files): 324eebee-d923-4c90-a3ba5380-78664f7d.zip

MQTT Topic and Payload that crashed qt-openzwave

Topic: OpenZWave/1/command/enablepoll/ Payload: {"ValueIDKey":1407374938882098,"Intensity":96}

Other Helpful Information

MQTT ValueIDKey Info

Output from OpenZWave/1/node/3/instance/3/commandclass/49/value/1407374938882098/

{
    "Label": "Instance 3: Humidity",
    "Value": 59,
    "Units": "%",
    "ValueSet": false,
    "ValuePolled": false,
    "ChangeVerified": false,
    "Min": 0,
    "Max": 0,
    "Type": "Decimal",
    "Instance": 3,
    "CommandClass": "COMMAND_CLASS_SENSOR_MULTILEVEL",
    "Index": 5,
    "Node": 3,
    "Genre": "User",
    "Help": "Humidity Sensor Value",
    "ValueIDKey": 1407374938882098,
    "ReadOnly": false,
    "WriteOnly": false,
    "Event": "valueAdded",
    "TimeStamp": 1590154347
}

Questions

Is there a good way to find the ValueIDKey? Right now I'm getting it from my HA core.entity_registry... which I know there has to be a better way inside the MQTT commands. I just haven't found it.
Is this enablepoll command something I will need to enable every boot, on every config update, or something else?
Is the enablepoll adding a PollInterval behind the scenes to the options.xml file that ozw (non-wrapper) reads, or is that more for a global polling setting? https://github.com/OpenZWave/open-zwave/wiki/Config-Options#optionsxml
What additional information can I provide to help debug this?

Thanks for taking a look!

kpine commented 4 years ago

Looks like there's a problem with the casing of ValueIDKey. JSON lookup uses ValueIdKey, but expects the former.

    return this->sendSimpleStatus(mgr->enablePoll(msg["ValueIdKey"].GetUint64(), msg["Intensity"].GetUint()));

Fishwaldo commented 4 years ago

Thanks for looking into this. I Just pushed a fix.

Fishwaldo commented 4 years ago

Is there a good way to find the ValueIDKey? Right now I'm getting it from my HA core.entity_registry... which I know there has to be a better way inside the MQTT commands. I just haven't found it.

Its right there in both the Topic and Payload.

Is this enablepoll command something I will need to enable every boot, on every config update, or something else?

As long as you keep your ozwcache file, it should only need to be set once.

Is the enablepoll adding a PollInterval behind the scenes to the options.xml file that ozw (non-wrapper) reads, or is that more for a global polling setting? https://github.com/OpenZWave/open-zwave/wiki/Config-Options#optionsxml

You can update via the MQTT interface (sorry, its missing from the documentation) - https://github.com/OpenZWave/qt-openzwave/blob/master/qt-ozwdaemon/mqttcommands/setPollInterval.cpp

What additional information can I provide to help debug this?

Test when the new docker images appear (in a few hours at most)

kpine commented 4 years ago

Built locally, looks good.

[20200522 23:43:26.624 PDT] [ozw.mqtt.commands] [debug]: Got  "OpenZWave/1/command/enablepoll/"  Message:  "{\n  \"ValueIDKey\": 281475317252130,\n  \"Intensity\": 2\n}"
[20200522 23:43:26.625 PDT] [ozw.library] [info]: Info - Node: 20 EnablePoll for HomeID 0xf83a19d3, value(cc=0x31,in=0x01,id=0x02)--poll list has 1 items

aav7fl commented 4 years ago

Is there a good way to find the ValueIDKey? Right now I'm getting it from my HA core.entity_registry... which I know there has to be a better way inside the MQTT commands. I just haven't found it.

Its right there in both the Topic and Payload.

Yep. I see it there. But I had to find it from HA before I was able to use it in the topic.

What topic would I call to get a list of the ValueIDKey for a given node?

Test when the new docker images appear (in a few hours at most)

Looks like the new image is working great! Thanks for fixing this so quickly @kpine + @Fishwaldo!

OpenZWave / qt-openzwave