Z-Wave Commands not sending when called from refresh() function, but working from others

viertaxa · December 19, 2020, 12:44am

I have a weird one here, or at least it's baffling to me.

I'm working on a driver that has the refresh capability, so there's a refresh() method defined.

I also, for development purposes, have command aaDebug defined in the definition so I can easily test stuff out.

Here's the weirdness: when I call my method to run Z-Wave commands from aaDebug(), I can see that they are getting formatted, security encapsulated, and passed into delayBetween(). I then get responses from my device, and all is well in the world.

However, when I call the exact same (as in copy-pasted to be sure) command in my refresh() method, I see that the commands are being formatted, security encapsulated, and sent to delayBetween(), but nothing happens after that. Radio (literally) silence.

I'm literally logging out the zwave numeric commands and comparing them. They are identical.

relevant code snippets:

def getRefreshCumulativeDataCommands() {
    [
        // Whole HEM
        zwave.meterV4.meterGet(scale: 0), //kWh
        zwave.meterV4.meterGet(scale: 1), //kVAh
        zwave.meterV4.meterGet(scale: 2), //W
        zwave.meterV4.meterGet(scale: 3), //Pulse count
        zwave.meterV4.meterGet(scale: 4), //V
        zwave.meterV4.meterGet(scale: 5), //A
        zwave.meterV4.meterGet(scale: 6), //Power Factor
        zwave.meterV4.meterGet(scale: 7, scale2: 0), //kVar
        zwave.meterV4.meterGet(scale: 7, scale2: 1), //kVarh
    ]
}

def refresh() {
    logTrace "Entering refresh"
    logTrace "Calling runCommandsWithInterstitialDelay"
    runCommandsWithInterstitialDelay refreshCumulativeDataCommands
    logTrace "Exiting refresh"
}

def runCommandsWithInterstitialDelay(commands, delay = 1000) {
    delayBetween(commands.collect { generateFormattedCommand(it) }, delay)
}

def generateFormattedCommand(hubitat.zwave.Command cmd) {
    if (state.secure) {
        logTrace 'Generating secure message'
        logTrace "${cmd.format()} => ${zwaveSecureEncap(cmd.format())}"
        zwaveSecureEncap(cmd.format())
    }
    else {
        logTrace 'Generating unsecure message'
        cmd.format()
    }
}

Here's what's logged:

dev:4082020-12-18 07:43:31.387 pm trace Exiting refresh
dev:4082020-12-18 07:43:31.384 pm trace 600D000232013801 => 988100600D000232013801
dev:4082020-12-18 07:43:31.380 pm trace Generating secure message
dev:4082020-12-18 07:43:31.377 pm trace 600D000232013800 => 988100600D000232013800
dev:4082020-12-18 07:43:31.373 pm trace Generating secure message
dev:4082020-12-18 07:43:31.370 pm trace 600D0002320130 => 988100600D0002320130
dev:4082020-12-18 07:43:31.366 pm trace Generating secure message
dev:4082020-12-18 07:43:31.363 pm trace 600D0002320128 => 988100600D0002320128
dev:4082020-12-18 07:43:31.360 pm trace Generating secure message
dev:4082020-12-18 07:43:31.356 pm trace 600D0002320120 => 988100600D0002320120
dev:4082020-12-18 07:43:31.353 pm trace Generating secure message
dev:4082020-12-18 07:43:31.349 pm trace 600D0002320118 => 988100600D0002320118
dev:4082020-12-18 07:43:31.346 pm trace Generating secure message
dev:4082020-12-18 07:43:31.342 pm trace 600D0002320110 => 988100600D0002320110
dev:4082020-12-18 07:43:31.339 pm trace Generating secure message
dev:4082020-12-18 07:43:31.335 pm trace 600D0002320108 => 988100600D0002320108
dev:4082020-12-18 07:43:31.332 pm trace Generating secure message
dev:4082020-12-18 07:43:31.329 pm trace 600D0002320100 => 988100600D0002320100
dev:4082020-12-18 07:43:31.325 pm trace Generating secure message
dev:4082020-12-18 07:43:31.322 pm trace 600D000132013801 => 988100600D000132013801
dev:4082020-12-18 07:43:31.318 pm trace Generating secure message
dev:4082020-12-18 07:43:31.315 pm trace 600D000132013800 => 988100600D000132013800
dev:4082020-12-18 07:43:31.312 pm trace Generating secure message
dev:4082020-12-18 07:43:31.308 pm trace 600D0001320130 => 988100600D0001320130
dev:4082020-12-18 07:43:31.305 pm trace Generating secure message
dev:4082020-12-18 07:43:31.302 pm trace 600D0001320128 => 988100600D0001320128
dev:4082020-12-18 07:43:31.298 pm trace Generating secure message
dev:4082020-12-18 07:43:31.295 pm trace 600D0001320120 => 988100600D0001320120
dev:4082020-12-18 07:43:31.292 pm trace Generating secure message
dev:4082020-12-18 07:43:31.288 pm trace 600D0001320118 => 988100600D0001320118
dev:4082020-12-18 07:43:31.285 pm trace Generating secure message
dev:4082020-12-18 07:43:31.282 pm trace 600D0001320110 => 988100600D0001320110
dev:4082020-12-18 07:43:31.278 pm trace Generating secure message
dev:4082020-12-18 07:43:31.275 pm trace 600D0001320108 => 988100600D0001320108
dev:4082020-12-18 07:43:31.272 pm trace Generating secure message
dev:4082020-12-18 07:43:31.268 pm trace 600D0001320100 => 988100600D0001320100
dev:4082020-12-18 07:43:31.262 pm trace Generating secure message
dev:4082020-12-18 07:43:31.258 pm trace 32013801 => 98810032013801
dev:4082020-12-18 07:43:31.255 pm trace Generating secure message
dev:4082020-12-18 07:43:31.251 pm trace 32013800 => 98810032013800
dev:4082020-12-18 07:43:31.248 pm trace Generating secure message
dev:4082020-12-18 07:43:31.244 pm trace 320130 => 988100320130
dev:4082020-12-18 07:43:31.241 pm trace Generating secure message
dev:4082020-12-18 07:43:31.237 pm trace 320128 => 988100320128
dev:4082020-12-18 07:43:31.234 pm trace Generating secure message
dev:4082020-12-18 07:43:31.231 pm trace 320120 => 988100320120
dev:4082020-12-18 07:43:31.227 pm trace Generating secure message
dev:4082020-12-18 07:43:31.224 pm trace 320118 => 988100320118
dev:4082020-12-18 07:43:31.220 pm trace Generating secure message
dev:4082020-12-18 07:43:31.217 pm trace 320110 => 988100320110
dev:4082020-12-18 07:43:31.213 pm trace Generating secure message
dev:4082020-12-18 07:43:31.210 pm trace 320108 => 988100320108
dev:4082020-12-18 07:43:31.207 pm trace Generating secure message
dev:4082020-12-18 07:43:31.203 pm trace 320100 => 988100320100
dev:4082020-12-18 07:43:31.198 pm trace Generating secure message
dev:4082020-12-18 07:43:31.099 pm trace Calling runCommandsWithInterstitialDelay
dev:4082020-12-18 07:43:31.096 pm trace Entering refresh

bertabcd1234 · December 19, 2020, 2:00am

Like many developer things, this isn't super-well-documented on Hubitat, but unless you do so "manually" (more on that later), Hubitat only sends Z-Wave commands for drivers when both of these are true:

either a single formatted Z-Wave command or a list of formatted Z-Wave commands (so technically either a String or a List<String>, though the def you have will also work if this is what you end up with) is returned from a method, and
that method is the implementation of (i.e., matches the name of) a driver command (so "command" in a different sense here, things like the refresh() method for capability "Refresh" or any custom command you declare)

So, while we're missing whatever aaDebug() is that you mentioned (but I don't see code for), it's apparent from the refresh() method you provided that it's not returning the formatted commands. Because of that, Hubitat isn't actually sending them for you. You could fix this by moving your log.trace "Exiting refresh" command somewhere before the last line of that method (though I guess that wouldn't quite make sense) so that runCommandsWithInterstitialDelay refreshCumulativeDataCommands would be your last line. If you're not familiar with Groovy, this is equivalent to return runCommandsWithInterstitialDelay(refreshCumulativeDataCommands) (in Groovy or Java)--the return is optional in Groovy and will be the last expression of your method (if not void). But basically, the method needs to return the formatted command(s).

If you want to send a Z-Wave command without it being the return value of a (driver) command, then you can do so manually with the sendHubCommand() method. Something like this, for example: sendHubCommand(new hubitat.device.HubAction(zwaveSecureEncap(zwave.meterV4.meterGet(scale: 0)), hubitat.device.Protocol.ZWAVE))

As an aside, unless there's a reason that isn't apparent from your snippets, you don't need to check whether the device is securely paired: you can just put either a command object or "formatted" string command through zwaveSecureEncap(), and the platform will take care of security for you if needed. (And state.secure will only tell you something if you set that somehow yourself; device.getDataValue("S2") on a C-7 will tell you if it has either S0 or S2, with the exact data value specifying the specific grant[s], and I think .isSecurePairingComplete would be S0 on a C-5).

viertaxa · December 19, 2020, 2:21am

Thanks so much for the detailed reply. I knew there had to be something that made sense happening, but it was totally escaping me.

I didn't realize that delayBetween() was actually returning a value, and that value was being passed on to the rest of the driver stack. It totally makes sense what is happening, though. I figured delayBetween was returning void and passing the data along elsewhere.

I have come across some drivers using sendHubCommand(), I might adopt that. There's definitely lots of room for refactoring as I'm learning the hubitat environment.

That's a good point on the zwaveSecureEncap() function. I had it structured with the branching on secure from some older examples that I had seen, but the new way makes that obsolete.

As an aside, I think that hubitat could attract a valuable and particular niche to their platform if they had some better documentation on developing apps and drivers. Just my 2 cents though.

bertabcd1234 · December 19, 2020, 2:49am

Yeah, delayBetween() takes a list of formatted commands and returns a similar list (again, technically a List<String> in and a List<String> out) with delay "commands" (not really Z-Wave commands, but just something that tells the platform to delay the next command) added between them. That string really ends up just being something like "delay 100" (or however many milliseconds you specified) and you could just build it into your list yourself, but the method is convenient if all the delays should be the same.

And the developer docs are indeed a bit sparse. The SmartThings docs for SmartApp and Device Type Handler (DTH) development are good starts, though besides namespaces, there are some differences between there and Hubitat. Hubitat's docs are usually sufficient to fill in those gaps if you look up the method you're looking for. I wonder if a community "getting started" guide wouldn't be a bad idea here. (I wouldn't hold my breath for a staff effort; I'm sure they'll get around to it some day, but it it's not really billed as a platform, just one that happens to support custom code for those with the know-how.)