Custom driver - not seeing unsolicited reports from device?

[lcstyle]

Hi,

I've got a custom driver for a custom zuno device and it is working, but I don't get unsolicited reports from the device even though it is sending reports every 30 seconds.

If I perform a sensor multilevel get command from the device page, then I see the report come in (the event triggered).

The zuno is using :

// send report to controller (Life Line group)
  zunoSendReport(1);

https://z-uno.z-wave.me/Reference/zunoSendReport/

I don't think it's a device side issue with the firmware, I think it's just my not understanding how to subscribe to or enable the unsolicited reports it is sending.

Technically, if the device is sending reports, shouldn't that trigger my zwaveEvent from the parse method? I even have a catch all to see any data that comes in, but i don't see anything coming into the device from the logs?

def parse(String description)
{
    log.debug "Non-parsed event: ${description}"
    hubitat.zwave.Command cmd = zwave.parse(description,[0x85:2,0x31:7,0x5E:2,0x70:1,0x8E:3,0x7A:3,0x5A:1,0x59:1,0x73:1,0x98:0,0x86:2,0x72:2])
    if (cmd) {
                result = zwaveEvent(cmd)
                log.debug "Parsed ${cmd} to ${result.inspect()}"
        } else {
                log.debug "Non-parsed event: ${description}"
        }
        return result
}

[bertabcd1234]

Yes, everything the Z-Wave device sends to the hub will go to your parse() method, so if you're not seeing anything in your log.debug line there, my first thought would be that the device isn't sending anything. I'm not familiar with the Z-Uno but see that you think it's supposed to be sending something; however, given this, my first assumption would be that something is wrong with that end of things. You might be able to make absolutely certain lifeline association is set via something like zwave.associationV2.associationSet(groupingIdentifier: 1, nodeId: [zwaveHubNodeId]) (run that through zwaveSecureEncap() if needed and either return it from a method like configure() or send it "manually" -- same as any Z-Wave command), but I'm not sure that would make any difference.

If you have a Zniffer or some way to see what the device is actually sending, that would be better evidence; then you'd know there's a problem if the hub isn't getting something it is sending. My suspicion, however, is again that you'd simply see it isn't.

[lcstyle]

Dear bertabcd1234, thank you kindly for your response, I think I know where to go now. It's my first driver, so I've been feeling my way around in the dark all day. Right now I solved the problem by scheduling a multi level sensor get call every fifteen minutes or so, and that seems to work around the issue for now, but I'm still curious what's happening to the data being sent by the devices send call, which runs every 30 seconds or so.

[lcstyle]

@bertabcd1234

zwave.associationV2.associationSet(groupingIdentifier: 1, nodeId: [zwaveHubNodeId])

I did an association report using the basic zwave tools:

dev:8982022-11-27 08:58:16.173 AMinfoAssociationReport- groupingIdentifier:2, maxNodesSupported:8, nodes:[]
dev:8982022-11-27 08:58:15.675 AMinfoAssociationReport- groupingIdentifier:1, maxNodesSupported:8, nodes:[]

i noticed for grouping identifier 1, there's no nodes in the array.

So I sent

    cmds = [secureCmd(zwave.associationV2.associationSet(groupingIdentifier: 1, nodeId: [1]))]

and that fixed it! I am now seeing the reports, however, the reports are showing as ("skip")!!!:

dev:8982022-11-27 09:17:34.276 AM debug skip: SensorMultilevelReport(precision:2, scale:0, sensorType:20, sensorValue:[0, 7], size:2, scaledSensorValue:0.07)

I unscheduled my sensor multilevel report job, and that fixed the Skip!! wow is there a lot of undocumented behavior going on here!! Is there any explanation as to why a scheduled job would cause unsolicited reports for that 0x20 group to be "skipped"? (is this documented somewhere)!

I can't thank you enough as it's working now!

[bertabcd1234]

@lcstyle

the reports are showing as ("skip")

The platform doesn't do that on its own. It sounds like you're using a pattern often seen in example drivers, where you delegate handling different command classes to different methods, and then you have a "catch all" method that logs "skip" that will run if nothing else matches. The solution is to add something that matches. In your case, this would be a SensorMultiLevelReport of some version (the sensor has a maximum version that it will support, and you can tell zwave.parse() to return that version or anything lower, often specified in a static field variable somewhere in your code or sometimes passed directly to it--can't really say without seeing it or knowing more).

[lcstyle]

@bertabcd1234

and then you have a "catch all" method that logs "skip" that will run if nothing else matches.

you know that's exactly what I thought too initially, but then i searched my code for the string skip and I couldn't find it:

def parse(String description)
{
    log.debug "Non-parsed event: ${description}"
    hubitat.zwave.Command cmd = zwave.parse(description,[0x85:2,0x31:7,0x5E:2,0x70:1,0x8E:3,0x7A:3,0x5A:1,0x59:1,0x73:1,0x98:0,0x86:2,0x72:2])
    if (cmd) {
                result = zwaveEvent(cmd)
                log.debug "Parsed ${cmd} to ${result.inspect()}"
        } else {
                log.debug "Non-parsed event: ${description}"
        }
        return result
}

and a catch all

def zwaveEvent(hubitat.zwave.Command cmd) {
    logging("Unhandled Z-Wave Event: $cmd")
}

my sensor multilevel report method:

void zwaveEvent(hubitat.zwave.commands.sensormultilevelv7.SensorMultilevelReport cmd) {
    log.debug "Sensor Multilevel Report - Sensor Type: ${cmd.sensorType}, Sensor Value: ${cmd.scaledSensorValue}"
    Map evt = [:]
    switch (cmd.sensorType) {
        case 20:  // 0x14 Multilevel Sensor Distance
            evt.unit = "in" // distance in the example code is sent in Meters
            evt.name = "distance"
            def value = (String) (((cmd.scaledSensorValue * 100) * 0.3937007874).toFloat().round(1))
            evt.value = value
            evt.descriptionText = "${device.displayName}: Distance is ${value}${evt.unit}"
            sendEvent(evt)
            break
    }
}

Here are the log entries again:

dev:8982022-11-27 09:20:05.937 AM debug skip: SensorMultilevelReport(precision:2, scale:0, sensorType:20, sensorValue:[0, 7], size:2, scaledSensorValue:0.07)
dev:8982022-11-27 09:19:35.631 AM debug skip: SensorMultilevelReport(precision:2, scale:0, sensorType:20, sensorValue:[0, 7], size:2, scaledSensorValue:0.07)
dev:8982022-11-27 09:19:05.261 AM debug skip: SensorMultilevelReport(precision:2, scale:0, sensorType:20, sensorValue:[0, 7], size:2, scaledSensorValue:0.07)
dev:8982022-11-27 09:18:34.924 AM debug skip: SensorMultilevelReport(precision:2, scale:0, sensorType:20, sensorValue:[0, 7], size:2, scaledSensorValue:0.07)
dev:8982022-11-27 09:18:04.588 AM debug skip: SensorMultilevelReport(precision:2, scale:0, sensorType:20, sensorValue:[0, 7], size:2, scaledSensorValue:0.07)
dev:8982022-11-27 09:17:34.276 AM debug skip: SensorMultilevelReport(precision:2, scale:0, sensorType:20, sensorValue:[0, 7], size:2, scaledSensorValue:0.07)

That's why I sort of implied that it was the hubitat device handler code that was doing that, as I just don't see output from my driver that would match those entries in the log.

Here's an example of the same log entry from my driver:

dev:8982022-11-27 09:21:37.012 AM debug Parsed SensorMultilevelReport(precision:2, scale:0, sensorType:20, sensorValue:[0, 7], size:2, scaledSensorValue:0.07) to null

i think that skip log statement is coming from the zwave.parse call in my parse method.

except, that there's this statement as the first statement in the method, and I don't see that.
I can reproduce this behavior.

    log.debug "Non-parsed event: ${description}"

[bertabcd1234]

I don't think zwave.parse() ever logs anything on its own (I've never seen it do so), so my assumption is again that it must be coming from your driver somewhere. Without seeing the full thing, it's really hard to say.

In your "catchall" method, logging() is not a built-in method, so assuming you've implemented that, what (if anything) you see would depend on the body of that method. But that is what I was thinking of, as it's a common practice (and demonstrated in most example drivers) to log "skip" here for reports/etc. that the driver isn't handling.

The only other odd thing I can think of is that you might not get predictable behavior if your device does not support SensorMultiLevel (0x31) v7, though it seems it might since it matched at least once (though the output from that method still looks odd--do you expect null there?). A quick search of their docs suggests v8 is the max, so this should be good. But if you don't depend on any features from a more recent version, you could try an older one...

[lcstyle]

ok, it's clear to me now that I have absolutely no idea what I'm doing, but based on your comments, I have slightly more of a clue. I was wondering where that null was coming from.

So this is what I have now:

def parse(String description)
{
    log.debug "parse: Entering parse"
    hubitat.zwave.commands.sensormultilevelv5.SensorMultilevelReport report = zwave.parse(description, [0x31: 5])
    if (report) {
            result = zwaveEvent(report)
            log.debug "parse: Parsed ${report} to ${result.inspect()}"
        } else {
            log.debug "parse: Non-parsed event: ${description}"
        }
    
    return result
}

def zwaveEvent(hubitat.zwave.commands.sensormultilevelv5.SensorMultilevelReport cmd) {
    log.debug "zwaveEvent: Entering multiLevel Report Zwave Event"
    log.debug "zwaveEvent: Sensor Multilevel Report - Sensor Type: ${cmd.sensorType}, Sensor Value: ${cmd.scaledSensorValue}"
    Map evt = [:]
    switch (cmd.sensorType) {
        case 20:  // 0x14 Multilevel Sensor Distance
            evt.unit = "in" // distance in the example code is sent in Meters
            evt.name = "distance"
            def value = (String) (((cmd.scaledSensorValue * 100) * 0.3937007874).toFloat().round(1))
            evt.value = value
            evt.descriptionText = "${device.displayName}: Distance is ${value}${evt.unit}"
            return evt
    }
}

The log output is now much better:

dev:8982022-11-27 03:46:23.127 PMdebugparse: Parsed SensorMultilevelReport(precision:2, scale:0, sensorType:20, sensorValue:[0, 7], size:2, scaledSensorValue:0.07) to ['unit':'in', 'name':'distance', 'value':'2.8', 'descriptionText':Pellet Level Sensor: Distance is 2.8in]
dev:8982022-11-27 03:46:23.124 PMdebugzwaveEvent: Sensor Multilevel Report - Sensor Type: 20, Sensor Value: 0.07
dev:8982022-11-27 03:46:23.121 PMdebugzwaveEvent: Entering multiLevel Report Zwave Event
dev:8982022-11-27 03:46:23.119 PMdebugparse: Entering parse

However, I do not see any events showing up in the devices event log, when you click on "Events" in the device dialog page. Any idea why that might be?

[bertabcd1234]

@lcstyle

However, I do not see any events showing up in the devices event log, which you click on "Events" in the device dialog page.

First, I know what you mean, but I'd avoid using "log" to describe this since normally people use that term to refer to Logs as accessed from the left-side menu of the hub interface. (By convention, the "Enable descriptionText logging" preference in a driver writes an "info" entry to logs every time you generate an event, but the event will show up in Events--the authoritative source--regardless.)

What you need to do is actually generate an event to get it to show up here. There are two ways you can do this, one of which I remember poorly and is something like returning an event map from your parse() method using createEvent(), likely as a return value of one of your other methods you call from parse() (and then ultimately also return this value from parse()). This almost looks like what your code is doing, except you're not ultimately returning the return value of any of your zwaveEvent() methods from parse(), which would probably take care of that.

Alternativey: the way I always do it is by calling sendEvent() myself, which you can do anywhere--and, IMHO, makes things clearer. I usually do this somewhere inside my zwaveEvent() methods, then I don't have to return anything from them or worry about event generation inside (or by return value) of parse(), and all of these methods can be void if you want.

An example:

sendEvent(name: "switch", value: "on", descriptionText: "${device.displayName} switch is on")

You can specify unit here, too, which you might want since it looks like you're measuring distance in inches. BTW, distance isn't a standard attribute name in any capability I know of, so you'll probably also have to declare a a custom attribute in your code to make this really work (though you'll see it temporarily appear on the device detail page and I think still in Events even if you don't).

[lcstyle]

gotcha,

ok, I've got it working with sendEvent now and I see the events appearing in the device events dialog.
Thank you!!!!!

BTW, I discovered that if I return the event back to parse, and in turn return the event from parse, i do see an entry in the device events dialog. However, the 'produced by' column field is empty for these events. If I instead opt for sendEvent, the 'produced by' field shows the device label. Not a big deal either way, just thought I would mention it.

Final question, do events that exactly match the last event get consolidated or ignored, i.e. events with the same value?

Because that's the behavior I am noticing, and BTW that behavior is absolutely fine with me, was just curious.

[bertabcd1234]

@lcstyle

Final question, do events that exactly match the last event get consolidated or ignored, i.e. events with the same value?

Yes, that is the default behavior (and is desired in most cases). However, you can bypass this by passing isStateChange: true. The classics example for this is button events (where you need an event even if you press the same button number twice in a row) and often battery reports (likely so the driver still generates "activity" and the history of reports can be seen, especially for devices that don't do much on their own normally).

[lcstyle]

@bertabcd1234

In your "catchall" method, logging() is not a built-in method, so assuming you've implemented that, what (if anything) you see would depend on the body of that method. But that is what I was thinking of, as it's a common practice (and demonstrated in most example drivers) to log "skip" here for reports/etc. that the driver isn't handling.

You know, I hadn't noticed that I was using logging() in that particular method. That was a copy/paste from some sample code, and I had already updated all the other calls using logging() to log.debug(). Since logging() wasn't implemented, I doubt this was the source of the skip string, as if "skip" was coming from logging(), because logging wasn't implemented in my driver, I assume that the call would have bombed (unless there's a standard logging method somewhere that got imported).

In any event, it's all working nicely now, and I'm going to work on the device firmware to avoid sending reports unless the distance value has changed.

Thank you once again for all your help!