Struggling with how code executes

jshimota · October 18, 2021, 5:24pm

Sorry to ask - it's embarrassing.
I'm fighting with how a variable changes state in groovy. There is no doubt in my mind it's just something I'm supposed to already know but don't.

I'm trying to understand why a value doesn't update on first execution but does on the second.
This is to debug a toggling problem I have in a larger context and think my root problem is around this area:
here is the code -
def on() {
sendEvent(name: "switch", value: "on")
state.device = true
parent?.componentOn(this.device)
if (txtEnable) log.info "${device.displayName} turned ON."
autotoggle()
}

def off() {
sendEvent(name: "switch", value: "off")
state.device = false
parent?.componentOff(this.device)
if (txtEnable) log.info "${device.displayName} turned OFF."
autotoggle()
}

def autotoggle() {
if (autoOff.toInteger() > 0) {
runIn(autoOff.toInteger(), toggle)
return
}
def switchvalue = device.currentValue("switch")
log.info "Turned on/off: switchvalue is $switchvalue"
return
}

When I run this driver it starts out fine. I push the 'On' button but the log message says 'switchvalue' = Off. but switch state is on. I push the on button again, and now both values show On. Same occurs with the Off button. It's as if switchvalue can't update dynamically within the function. Does anyone have the time to take a peek and edumacate me on what if obviously a simple thing? I'm very frustrated!

bertabcd1234 · October 18, 2021, 5:43pm

Have you tried seeing if this returns anything different? Instead of

device.currentValue("switch"), try:

device.currentValue("switch", true)

Per the docs, this will read the current value from the database rather than using the cache. If the value recently changed, it's possible that the cache (which is the default retrieval method) could have outdated information, and it's not clear to me when or how that is updated. So, I'd try this just to rule that out.

If not, it might be helpful to see the whole driver, and formatting the text as code in the post (or linking to it elsewhere) would make it easier to read.

jshimota · October 19, 2021, 12:16am

I gave that a try, while I got no error when I saved the driver it didn't change the log results.

I found this:

In the end, I did away altogether with sending that to the log - I think it's bugged - I tried making it a bool and tried a few other tricks but I'm dropping it!

bertabcd1234 · October 19, 2021, 12:22am

I don't think the linked post refers to the same issue. That appears to be asking about "real" devices, where generally with a command like on(), you'd send something to the device and then not update the state on Hubitat (e.g., via sendEvent()) until you hear back. Your device is virtual, and you're just doing the sendEvent() right away. That should never fail.

If you still want to troubleshoot, I'd consider posting the entire driver code or at least a complete, minimal non-working example that demonstrates the problem. Good luck!

jshimota · October 19, 2021, 12:31am

much obliged! It did occur to me from an academic POV to learn why it didn't/doesn't work - but my desire level to troubleshoot with HE isn't what it once was. I'm now really only concerned with my work (or what pertains to other dev's I'm using). I do appreciate your honest and constantly positive effort to help!

jshimota · October 19, 2021, 12:36am

Oh - btw - if you had a chance to read that thread - there was some great dialog about sendEvent (?? I think) and isStateChange = True... I also tried that to no avail but I really thought I was onto something there!

bertabcd1234 · October 19, 2021, 1:18am

I don't see anything about isStateChange: true in that thread, but that is an option you can provide to sendEvent() that will cause an event to get generated even if the current attribute value is the same as the one you're sending. It shouldn't affect the actual outcome in terms of the current device state. If you do a sendEvent(name: "switch", value: "on"), the switch attribute should change to on if it isn't already; isStateChange won't affect that, nor should it affect what you get from currentValue("switch"). If the former isn't working, there is a pretty big problem; if the latter isn't working, I'm not sure what to suggest without seeing the full code, aside from the cache issue that you've already ruled out.

The classic example of when you'd need this is for button devices. The pushed event should generate an event for a value of 1 every time you push button 1 on that device, for example, even if that button number (the event value here) isn't different from the last button number that you pressed. So you'd definitely want isStateChange: true for these events if you were writing a driver for such a device.

Here, I don't see any reason it should matter (though you certainly could do it if you want your virtual device to generate events with every command, regardless of the previous state).

PS - I assume you've declared capability "Switch", without which I'm not sure what trying to read the attribute value for an undefined attribute will return, but you'd likely have run into other problems already if you didn't...

jshimota · October 19, 2021, 9:20am

I might have confused the isStateChange with the , true for bypass cache.
It's late - I'll cut my work down to it's minimum size to demonstrate the issue. I already have some new ideas on how to work make what I want work but I'm willing to play a bit even if it's just to prove I'm not nutz.

jshimota · October 19, 2021, 4:16pm

Okay @bertabcd1234

Here is my code - it is as minimalized as I can make it.

https://raw.githubusercontent.com/jshimota01/hubitat/main/Drivers/virtual_inverse-able_switch/virtswitch-minimal.groovy

Steps to reproduce what I see and can't explain:

Open a separate window on your hub and go to logs.
Create a virtual switch - using this driver.
Push Initialize.
In the log window, set the log window to only display your new virtual switch
Press Initialize a few times (I do this to be sure all values are off)
Press the On button
Notice in the log - it says 'Turned On: switchvalue is off'
Press the On button again.
Notice in the log - it says 'Turned On: switchvalue is on'

This behavior of the switch value not showing the expected result on the first push of a button also happens with Initialize, Off and On. I created a new command button called Read Current - which touches no value - only displays them. It returns a Null for switchValue and I can't explain that either.

bertabcd1234 · October 19, 2021, 8:04pm

OK, so what I think is going on here is related to this sequence (this from on(), but similar things happen elsewhere):

sendEvent(name: "switch", value: "on", isStateChange: true)
switchvalue = device.currentValue("switch", true)

My guess is that there is not enough time for the event to be "committed" (i.e., to the database), so when you attempt to read the current state immediately after, you will still see the previous state. If you just waited some number of milliseconds (10? 100? I don't know, but it's likely to vary, and this isn't really how I'd approach solving this problem), then you'd likely see different results. You can test this by using pauseExecution(), but again, that's not really how I'd solve this.

Here's how I'd actually approach this problem. For the on() and off() commands, you are setting the (virtual) device to a specific state. Thus, you don't really need to read it after sending the event; you already know what it is. So instead of this:

def on() {
    // ...
    sendEvent(name: "switch", value: "on", isStateChange: true)
    switchvalue = device.currentValue("switch", true) 
    // ...
}

you could do this:

def on() {
    // ...
   String switchValue = "on"
    sendEvent(name: "switch", value: switchValue, isStateChange: true)
    // ...
}

(or a variety of other ways you could write that, the idea being that you don't need to retrieve that value--you just set it and know what it is, or at least what it will be when the event actually happens in a few milliseconds.) In your original code, it looks like you have some sort of toggle thing going on, so if you need to read the current state in that case, you should just be able to do so before changing it, and then you'll know you're going to set it to and again don't need to retrieve the value afterwards (assuming your toggle just does an on if off or an off if on--maybe that's not what you're going for).

PS - Some unrelated notes on logging, if you care to follow convention.

Generally, the "Enable descriptionText logging" does a log.info with information from events you send (as the name suggests, the descriptionText, though you aren't explicitly setting that here; something like "{device.displayName} switch is ${switchValue}" is pretty common). Whether the driver checks to see if the device is already in that state before logging the event or not varies from driver to driver (I like to do it myself since there is a better chance it will match when events actually happen, though "Events" is the authoritative source for that regardless).

The "Enable debug logging" setting normally does a log.debug with data coming in from the device, which is common for Z-Wave and Zigbee but not really a thing for virtual devices, but a newer trend (which I happen to like) is to also do debug logging when commands are executed. So, at the beginning of your on() command, it would be more conventional to do something like this:

if (logEnable) log.debug "on()"

instead of this:

if (txtEnable) log.info "ON button pushed."

But, of course, that is totally up to you.

PPS - You likely don't need isStateChange: true, though that really depends on the behavior you want. If you do a sendEvent(name: "switch", value: "on") and the switch attribute (name) is already on (value), then the platform will just filter that out instead of generating another event. This is how most real-world devices work and usually reflects what users want to happen in apps that subscribe to these devices (usually nothing). But if you want an event to be generated each time regardless, you can keep the isStateChange: true. It isn't related to your issue, and I know I mentioned this above--just wanted to bring it up again.

aaiyar · October 19, 2021, 8:21pm

This is really good advice. Also if you add "isStateChange: true" it generates additional events, even if the state doesn't really change. I added this to one of the virtual drivers I use (a virtual contact/switch driver), and repeatedly pushing on generates events ....... (see below).

I can think of no good coding reason to force the same event in a real or virtual driver.

ogiewon · October 20, 2021, 1:03am

The one exception is for 'Button' devices, where the same physical action must generate a new Event each time the same button is pushed multiple times in a row.

aaiyar · October 20, 2021, 1:05am

Good point! I didn't think about that. Button devices would definitely be the exception.

bertabcd1234 · October 20, 2021, 2:45am

One use case I've heard is virtual switches with voice assistants like Alexa; if you want to say, "Turn on X" and have an app that subscribes to the "switch: on" event from X do its thing even if the switch never turned off in between (which, conventionally, is the only case that would generate an event), then that is one way to make it happen. (This does depend on Alexa not attempting any "optimization," like not turning on something it already thinks is on, but that--no attempts at this--does appear to be the way it works now, so it works.) I'm not particularly fond of this solution and think a "momentary"/"auto off" switch is a bettter solution, but I remember someone being insistent a while back that they wanted something like this, and it does technically work.

But yeah, as mentioned above, button-related events are the classic case of when you'd want to use isStateChange: true for sure! I think some built-in drivers have also started doing it for battery events so it updates "Last Activity At" and gives you a better idea that the device is actually checking in (even if the battery report is the same as last time), which doesn't seem like a bad idea to me, either (though on the other hand, it would be nice to just have a way to update that metadata by having received something via Z-Wave or Zigbee without needing to generate an event at the platform level, but I don't make those rules, and it appears they didn't want to change them either ).

aaiyar · October 20, 2021, 2:56am

Agreed.

jshimota · October 20, 2021, 6:32am

I've read all the responses, and understand completely what you've all said.

First, being the direct person I am, the answer to my question was:
Put pauseExecution().
I added that, and tested first with 1000, then 500, then 250, then 100 then 10 and finally 2.
It worked. When I used 2ms, it failed, but at 10ms it worked. I set to 20ms for safety.

Now - my complaint is that a virtual switch is code. As a PHP/SQL person we don't think about timing - horsepower is horsepower -crystal frequency is the defining speed - so the concept of hardware timing is new to me - and I'll adjust. BUT. It's a virtual switch! how can a switch get latency?!?! Anyways. don't answer - I sort of already do know.

Regarding to assuming the value - I get your point - BUT. the reason I've added all these lines to post the state of the value to the log was specifically for debugging my problem. In my driver, I was checking the "switch" value to determine the state I was changing from and to, so having the real value was necessary. however the device state works and I've already modded the code to use device.state as the monitored value for my If true statements. As I said, and I want to be clear, this had become an educational dialog, and it was valuable!
thanks gents. Your efforts moved me forward!

kevin · October 20, 2021, 1:07pm

This is always a worrying thing to have to do. At one time I had a few of these delays in my mqtt code and you can't really be sure it's going to work. Maybe other processes running on the hub might slow it further and your delay becomes not long enough. Not a comfortable solution from a coders perspective as you said.

I had a lot of trouble inparticular with state variables not updating in drivers and ended up thinking it was due to scope. The attribute values worked better. In the end IIRC I used call events back to the parent app passing updated values and actioning logic or storing state there where I could use atomicState or even @field. That seemed solid

bertabcd1234 · October 20, 2021, 2:39pm

But...but...

That was really just intended to test whether that might be the issue. I would, again, not really do this in your driver. You already know what the value is beforehand and what it will become, so to be clear, my suggestion is to read it before you generate the event, then work with the knowledge you have of what it was and will be afterwards. (Using state to track the status instead certainly also works--and won't be subject to the event-generation "delay"--but I'm not sure why you'd need to put effectively the same information in two different places.)

Further, just because a specific number of milliseconds worked in one instance doesn't mean it always will; this will likely depend on how busy the hub is. Reading the value after pauseExecution() is a pretty hack-y, possibly fragile workaround.

OK, I can't help myself. The "latency" is likely just due to how the platform works: you tell your driver to generate an event, then Hubitat commits that event to its database. I don't know their implementation details, but it's clear from this behavior that it is either effectively asynchronous and/or threaded. You are unlikely to get the value you're committing right now back if you ask for it in the very next line of code for this reason (I would not be surprised if in rare instances you really did)--and your driver will, indeed, continue with executing that next line of code rather than "blocking" at the sendEvent() (manipulating state is likely blocking, which would explain the difference; we again don't know implementation details, but it seems to be some kind of Map, a data stored as part of the driver instance itself--but note that this alone won't help with concurrent execution, unlikely to be an issue with a simple virtual device).

jshimota · October 20, 2021, 4:00pm

I hope I've not misdirected anybody! I learned from what you said - Honest!
Recall the reason this got brought up - I was testing a driver and frustrated because I'd toggle a switch and it wasn't toggling. I had already abandoned this method of verifying the 'switch' state. @Kevin is spot on about delays in threaded code where the call passes to outside code influence which can vary.

@bertabcd1234 suggested I post my code, and we dug in... I won't be using this method in the future - but it was a glorious way to 'find' the problem and resolve it from a purely academic point of view and I learned tons - the best part of this forum IMHO. THanks for all the input!

aaiyar · October 20, 2021, 4:28pm

This method is used in a set of zigbee drivers that I used in the past. My zigbee hub was fine when I had a small number of devices that used these drivers. But when the hub had around 50-60 zigbee devices using these drivers, I started seeing missed events and several other issues.