Power Comparison Failed

[TonyK1321]

In other pistons I’m using the “Was Less Than for At Least xx min” on other devices and none of them seem to be failing.

Yes you are right about the 2nd statement. I’m sure WC would let me do all sorts of things that would kill the system.

I’m using an appliance switch to monitor my TV power to indicate when my TV is on. If it is off (because the power is less than 20W), and has been off for at least 15 min, and it is after 9pm, then kill the light in that room. What this gives me is that once the TV manually shut off (as in, I’m done watching the Olympics for today), then I want the light to stay on for 15 min before it shuts off. I am investigating eliminating the appliance module and using a different way to detect if the TV is on, by using my router to determine if that TV has an IP address, and if yes, then set a virtual switch that can then be tested by WC. But until I get that working, I’d like for the power technique to work.

[ipaterson]

I’m seeing a lot of wrong comparisons now with the logging and do believe that this is due to a lack of casting. Not on your end, though.

The value coming out of the device (at least out of my device) is a decimal [t:decimal, v:117.0] but the values coming out of the history state for that device are integers. It is pulling those old values from the state, which are integers, and sending them off for comparison as if they were decimals [t:decimal, v:117]. The comparison comes back saying that [t:decimal, v:117] is indeed less than [t:integer v:10].

That explains the behavior, so now let me see what I can do about it either to store the value correctly or cast before comparison.

[ipaterson]

It’s looking a lot better with casting in place. @TonyK1321, would you like to test a fix for this problem? It will be in the next release which will hopefully land next week. Let me know if you want to edit your smart app code to try the fix.

[TonyK1321]

Sure, I’ll test it. Just let me know when and what I need to do.

Will this impact all historical comparisons or only for that device type?

Also, is there anything I can do in the mean time? Maybe convert the value to an integer before doing the comparison? If yes, what would be the way to do that?

[Robin]

Also, is there anything I can do in the mean time? Maybe convert the value to an integer before doing the comparison? If yes, what would be the way to do that?

Maybe:

IF
{integer([device name : power])} was less than 10W for at least 15 minutes
THEN
…

We tried it the other way around last time (making the 10W a decimal)

[TonyK1321]

OK, I’ll try that.

[TonyK1321]

If I use an Expression for the condition in order to use the integer function, then there is no Was Less Than xx for at least yy min option. So I can try this using Stays Less than xx for 15 min. But will this compare the historical data like the Was Less Than expression (I suspect not)? And will this give me the same effect as Was Less than (again, I suspect not if the TV switch was less than 20 initially)? Or, am I missing something in setting up that condition?

[Robin]

Stays is a trigger that will happen once after the defined time… being inside a timer it won’t work as the trigger will never fall at the exact same time as the timer.

[Robin]

Perhaps use a variable with:

Boolean powerMonitor = {(age([device name : power]) =>900000)&&(integer([device name : power])<=10)}

And then:

IF
{powerMonitor} IS true
THEN
…

But the above will not work if power fluctuates during the 15 minutes (900000 milliseconds)

Alternatively, two variables:

Boolean powerBelow = {([device name : power])<=10}

Boolean PowerMonitor = {(age(powerBelow)=>900000)&&(powerBelow==‘true’)}

IF
{powerMonitor} IS true
THEN
…

But maybe just wait for Ian to give you his tweaked webCoRE app to test lol!

[TonyK1321]

OK. Then for now, I’ll do this. It detects when the power is below 20W within the timing window, then waits 15 min, then if power is still below 20W, then it will turn off the light. This has the advantage that if I turn the TV back on within that 15 min, then the light will not extinguish. This is not at good as the Was condition but it will do for now. I also added another IF that if the light is out and I turn on the TV then the light will turn on. That’s just something I thought of now and unrelated to the current discussion. Hmmm, maybe that’s not the best way to handle that case, but that’s why this all continues to be a work-in-progress.

Ian, Robin, and Bob - Thanks for all your help with this problem. I’m glad I was able to help to make WebCore better.

[TonyK1321]

I’ve just been sentitized to the cast issue. When I started my revised piston, I got this log:

2/23/2018, 5:35:00 PM +214ms
+1ms ╔Starting piston… (v0.2.102.20180116)
+519ms ║╔Subscribing to devices…
+667ms ║║Subscribing to Living Room Light…
+668ms ║╚Finished subscribing (160ms)
+745ms ║Comparison (enum) on is (string) on = true (1ms)
+748ms ║Cancelling condition #7’s schedules…
+821ms ║Comparison (time) 63300963 is_between (time) 75600000 … (time) 1519393260000 = false (5ms)
+831ms ║Comparison (decimal) 0.3 is_less_than (integer) 20 = true (3ms)
+840ms ║Comparison (decimal) 0.3 is_less_than (integer) 20 = true (1ms)
+841ms ║Cancelling condition #15’s schedules…
+841ms ║Cancelling condition #12’s schedules…
+851ms ║Comparison (enum) on is (string) off = false (0ms)
+858ms ║Comparison (time) 63301065 is_between (time) 75600000 … (time) 1519393260000 = false (5ms)
+867ms ║Comparison (decimal) 0.3 is_greater_than (integer) 40 = false (3ms)
+880ms ║Setting up scheduled job for Fri, Feb 23 2018 @ 9:01:00 PM MST (in 12359.829s)
+894ms ╚Piston successfully started (894ms)

Since the system is now comparing a decimal value to an integer, will I run into the same cast problem as before, where a decimal value will be less than an integer value even though the values say otherwise?

[ipaterson]

The particular cast that was fixed is not something that you can control. It is a one-line fix in webCoRE Piston smart app. Replace line 4052 with the following then save and publish

if (!("comp_$func"(rtData, [i: comparisonValue.i, v: [t: comparisonValue.v.t, v: cast(rtData, state.value, comparisonValue.v.t)]], rightValue, rightValue2, timeValue))) break

The problem is not comparing a decimal to an integer but rather that the code was declaring that an integer is a decimal without actually converting it to a decimal.

[TonyK1321]

if (!(“comp_$func”(rtData, [i: comparisonValue.i, v: [t: comparisonValue.v.t, v: cast(rtData, comparisonValue.v.t, state.value)]], rightValue, rightValue2, timeValue))) break

OK, I’ll try it.

[TonyK1321]

Ian - Here are the logs from my test. I replaced that statement with yours, published it for me, then resaved the pistons in order to get them going. But something still is not right. Take a look. We happened to shut the TV off right near 9pm, so these are the few logs after that point.

2/23/2018, 9:07:19 PM +314ms
+1ms ╔Received event [Home].time = 1519445240108 with a delay of -795ms
+143ms ║RunTime Analysis CS > 18ms > PS > 100ms > PE > 26ms > CE
+146ms ║Runtime (40401 bytes) successfully initialized in 100ms (v0.2.102.20180116) (144ms)
+147ms ║╔Execution stage started
+171ms ║║Comparison (enum) on is (string) on = true (7ms)
+173ms ║║Condition #7 evaluated true (14ms)
+234ms ║║Comparison (time) 76039488 is_between (time) 75600000 … (time) 1519393260000 = true (26ms)
+236ms ║║Time restriction check passed
+238ms ║║Condition #8 evaluated true (65ms)
+564ms ║║Comparison (decimal) 0.1 was_less_than (integer) 20 = true (317ms)
+569ms ║║Cancelling condition #9’s schedules…
+570ms ║║Condition #9 evaluated true (331ms)
+571ms ║║Cancelling condition #2’s schedules…
+573ms ║║Condition group #2 evaluated true (state changed) (415ms)
+587ms ║║Cancelling statement #10’s schedules…
+887ms ║║Executed physical command [Living Room Bulb].off() (254ms)
+888ms ║║Executed [Living Room Bulb].off (260ms)
+895ms ║║Skipped execution of physical command [Living Room Light].off([]) because it would make no change to the device. (2ms)
+896ms ║║***
+909ms ║║Comparison (enum) on is (string) off = false (1ms)
+912ms ║║Condition #19 evaluated false (10ms)
+913ms ║║Condition group #16 evaluated false (state did not change) (11ms)
+931ms ║╚Execution stage complete. (785ms)
+933ms ║Setting up scheduled job for Fri, Feb 23 2018 @ 9:09:20 PM MST (in 119.862s)
+939ms ╚Event processed successfully (940ms)
2/23/2018, 9:05:19 PM +424ms
+5ms ╔Received event [Home].time = 1519445120108 with a delay of -692ms
+168ms ║RunTime Analysis CS > 44ms > PS > 90ms > PE > 37ms > CE
+178ms ║Runtime (40399 bytes) successfully initialized in 90ms (v0.2.102.20180116) (166ms)
+183ms ║╔Execution stage started
+344ms ║║Comparison (enum) on is (string) on = true (9ms)
+351ms ║║Condition #7 evaluated true (52ms)
+407ms ║║Comparison (time) 75919776 is_between (time) 75600000 … (time) 1519393260000 = true (20ms)
+409ms ║║Time restriction check passed
+412ms ║║Condition #8 evaluated true (60ms)
+645ms ║║Comparison (decimal) 0.1 was_less_than (integer) 20 = false (221ms)
+647ms ║║Condition #9 evaluated false (233ms)
+648ms ║║Condition group #2 evaluated false (state did not change) (354ms)
+662ms ║║Comparison (enum) on is (string) off = false (2ms)
+665ms ║║Condition #19 evaluated false (10ms)
+666ms ║║Condition group #16 evaluated false (state did not change) (11ms)
+684ms ║╚Execution stage complete. (504ms)
+715ms ║Setting up scheduled job for Fri, Feb 23 2018 @ 9:07:20 PM MST (in 119.98s)
+723ms ╚Event processed successfully (724ms)
2/23/2018, 9:03:19 PM +531ms
+0ms ╔Received event [Home].time = 1519445000108 with a delay of -579ms
+342ms ║RunTime Analysis CS > 17ms > PS > 300ms > PE > 26ms > CE
+345ms ║Runtime (40402 bytes) successfully initialized in 300ms (v0.2.102.20180116) (343ms)
+346ms ║╔Execution stage started
+373ms ║║Comparison (enum) on is (string) on = true (6ms)
+375ms ║║Condition #7 evaluated true (15ms)
+437ms ║║Comparison (time) 75799908 is_between (time) 75600000 … (time) 1519393260000 = true (23ms)
+439ms ║║Time restriction check passed
+442ms ║║Condition #8 evaluated true (65ms)
+939ms ║║Comparison (decimal) 0.1 was_less_than (integer) 20 = false (483ms)
+941ms ║║Condition #9 evaluated false (497ms)
+942ms ║║Condition group #2 evaluated false (state did not change) (581ms)
+957ms ║║Comparison (enum) on is (string) off = false (2ms)
+959ms ║║Condition #19 evaluated false (9ms)
+961ms ║║Condition group #16 evaluated false (state did not change) (13ms)
+965ms ║╚Execution stage complete. (619ms)
+967ms ║Setting up scheduled job for Fri, Feb 23 2018 @ 9:05:20 PM MST (in 119.611s)
+1058ms ╚Event processed successfully (1057ms)
2/23/2018, 9:01:19 PM +331ms
+1ms ╔Received event [Home].time = 1519444880108 with a delay of -777ms
+150ms ║RunTime Analysis CS > 22ms > PS > 85ms > PE > 43ms > CE
+153ms ║Runtime (40393 bytes) successfully initialized in 85ms (v0.2.102.20180116) (151ms)
+154ms ║╔Execution stage started
+190ms ║║Comparison (enum) on is (string) on = true (9ms)
+193ms ║║Condition #7 evaluated true (21ms)
+237ms ║║Comparison (time) 75679526 is_between (time) 75600000 … (time) 1519393260000 = true (21ms)
+238ms ║║Time restriction check passed
+247ms ║║Cancelling condition #8’s schedules…
+248ms ║║Condition #8 evaluated true (53ms)
+598ms ║║Comparison (decimal) 86.2 was_less_than (integer) 20 = false (339ms)
+600ms ║║Condition #9 evaluated false (349ms)
+601ms ║║Condition group #2 evaluated false (state did not change) (429ms)
+616ms ║║Comparison (enum) on is (string) off = false (2ms)
+617ms ║║Condition #19 evaluated false (13ms)
+618ms ║║Condition group #16 evaluated false (state did not change) (14ms)
+658ms ║╚Execution stage complete. (504ms)
+660ms ║Setting up scheduled job for Fri, Feb 23 2018 @ 9:03:20 PM MST (in 120.118s)
+668ms ╚Event processed successfully (667ms)

At 9:01, the comparison was OK. But at 9:03, it was wrong (0.1 less than 20 = false). Same at 9:05. But at 9:07, it was evaluated as True, but then light went out. But the TV had not been off for 15 min.

Here is the piston.

What other info can I give you?

[ipaterson]

The condition is only true after 15 minutes so the first few correctly evaluated to false.

I’m not sure why it evaluated to true earlier than 15 minutes though, based on the logs the TV had only been off for about 6 minutes. I’ll take a look at the time comparison today but the code seems solid at a glance.

I don’t have a good theory for how this could have happened based on the code. It seems like the dates in the event log coming back from SmartThings would have to be off by 9-10 minutes, but that is probably not the case. Are you certain that the piston is still set for 15 minutes, the threshold wasn’t reduced for debugging or anything like that?

[TonyK1321]

No, the piston that executed was as you see it. But I did have trouble starting it up, so maybe that caused the faulty behavior. I’ll try it again but I will change the times so I can test now.

[TonyK1321]

if (!(“comp_$func”(rtData, [i: comparisonValue.i, v: [t: comparisonValue.v.t, v: cast(rtData, comparisonValue.v.t, state.value)]], rightValue, rightValue2, timeValue))) break

I tried it again but I eliminated the time condition so that it would run now. Here is the log. The comparison is still failing, causing the bulb to turn off. I can also tell you that all my other pistons are also failing.

2/24/2018, 8:10:43 AM +512ms
+6ms ╔Received event [Home].time = 1519485044471 with a delay of -968ms
+192ms ║RunTime Analysis CS > 54ms > PS > 90ms > PE > 54ms > CE
+200ms ║Runtime (39966 bytes) successfully initialized in 90ms (v0.2.102.20180116) (185ms)
+204ms ║╔Execution stage started
+317ms ║║Comparison (enum) on is (string) on = true (7ms)
+324ms ║║Cancelling condition #7’s schedules…
+325ms ║║Condition #7 evaluated true (43ms)
+497ms ║║Comparison (decimal) 63.1 was_less_than (integer) 20 = true (164ms)
+499ms ║║Condition #9 evaluated true (173ms)
+501ms ║║Cancelling condition #2’s schedules…
+502ms ║║Condition group #2 evaluated true (state changed) (222ms)
+511ms ║║Cancelling statement #10’s schedules…
+829ms ║║Executed physical command [Living Room Bulb].off() (297ms)
+830ms ║║Executed [Living Room Bulb].off (302ms)
+835ms ║║Skipped execution of physical command [Living Room Light].off([]) because it would make no change to the device. (2ms)
+835ms ║║Executed [Living Room Light].off (4ms)
+846ms ║║Comparison (enum) on is (string) off = false (1ms)
+847ms ║║Cancelling condition #19’s schedules…
+848ms ║║Condition #19 evaluated false (9ms)
+849ms ║║Condition group #16 evaluated false (state did not change) (10ms)
+900ms ║╚Execution stage complete. (699ms)
+923ms ║Setting up scheduled job for Sat, Feb 24 2018 @ 8:12:44 AM MST (in 120.044s)
+931ms ╚Event processed successfully (933ms)

Why the redundant statement at 835ms? That is not in the logic.

Here is the piston.

[TonyK1321]

Here’s an example of another piston that failed when the revised statement was in. The lower log is the failure. See statement at 686. The upper log is with the original 4052 statement back in.

2/24/2018, 8:26:56 AM +163ms
+0ms ╔Received event [Home].time = 1519486017083 with a delay of -921ms
+214ms ║RunTime Analysis CS > 14ms > PS > 78ms > PE > 123ms > CE
+217ms ║Runtime (44561 bytes) successfully initialized in 78ms (v0.2.102.20180116) (216ms)
+218ms ║╔Execution stage started
+255ms ║║Comparison (enum) off was (string) off = true (20ms)
+257ms ║║Cancelling condition #7’s schedules…
+258ms ║║Condition #7 evaluated true (29ms)
+275ms ║║Comparison (decimal) 0.4 is_greater_than (integer) 40 = false (2ms)
+277ms ║║Comparison (decimal) 0.1 is_greater_than (integer) 40 = false (1ms)
+280ms ║║Comparison (decimal) 75.8 is_greater_than (integer) 40 = true (1ms)
+281ms ║║Condition #28 evaluated true (22ms)
+282ms ║║Condition group #27 evaluated true (state did not change) (23ms)
+283ms ║║Cancelling condition #2’s schedules…
+284ms ║║Condition group #2 evaluated true (state changed) (56ms)
+312ms ║║Comparison (enum) off was (string) off = true (19ms)
+313ms ║║Cancelling condition #25’s schedules…
+314ms ║║Condition #25 evaluated true (28ms)
+315ms ║║Cancelling condition #9’s schedules…
+315ms ║║Condition group #9 evaluated true (state changed) (29ms)
+318ms ║║Cancelling statement #16’s schedules…
+337ms ║║Executed physical command [Water Recirculation].on() (17ms)
+338ms ║║Executed [Water Recirculation].on (18ms)
+341ms ║║Executed virtual command [Water Recirculation].wait (1ms)
+342ms ║║Requesting a wake up for Sat, Feb 24 2018 @ 8:39:56 AM MST (in 780.0s)
+351ms ║╚Execution stage complete. (134ms)
+353ms ║Setting up scheduled job for Sat, Feb 24 2018 @ 8:36:57 AM MST (in 600.567s), with 1 more job pending
+361ms ╚Event processed successfully (361ms)

2/24/2018, 8:16:56 AM +387ms
+5ms ╔Received event [Home].time = 1519485417083 with a delay of -706ms
+456ms ║RunTime Analysis CS > 210ms > PS > 109ms > PE > 142ms > CE
+464ms ║Runtime (44564 bytes) successfully initialized in 109ms (v0.2.102.20180116) (287ms)
+468ms ║╔Execution stage started
+686ms ║║Comparison (enum) off was (string) off = false (86ms)
+694ms ║║Condition #7 evaluated false (125ms)
+696ms ║║Condition group #2 evaluated false (state did not change) (132ms)
+714ms ║╚Execution stage complete. (249ms)
+735ms ║Setting up scheduled job for Sat, Feb 24 2018 @ 8:26:57 AM MST (in 599.969s)
+744ms ╚Event processed successfully (747ms)

Here’s the piston.

[ipaterson]

Very odd, let’s dig a bit deeper. Please replace the entire valueWas function containing that original line with the following which adds more logging and shows both the modified and old (no cast) comparisons:

private boolean valueWas(rtData, comparisonValue, rightValue, rightValue2, timeValue, func) {
	if (!comparisonValue || !comparisonValue.v || !comparisonValue.v.d || !comparisonValue.v.a || !timeValue || !timeValue.v || !timeValue.vt) {
    	return false
    }
    def device = getDevice(rtData, comparisonValue.v.d)
    if (!device) return false
    def attribute = comparisonValue.v.a
    long threshold = evaluateExpression(rtData, [t: 'duration', v: timeValue.v, vt: timeValue.vt], 'long').v

	def states = listPreviousStates(device, attribute, threshold, (rtData.event.device?.id == device.id) && (rtData.event.name == attribute))
    def result = true
    long duration = 0
    info "valueWas ${comparisonValue}", rtData
    for (state in states) {
    	def value = cast(rtData, state.value, comparisonValue.v.t)
    	def comparison = "comp_$func"(rtData, [i: comparisonValue.i, v: [t: comparisonValue.v.t, v: value]], rightValue, rightValue2, timeValue)
        def originalComparison = "comp_$func"(rtData, [i: comparisonValue.i, v: [t: comparisonValue.v.t, v: state.value]], rightValue, rightValue2, timeValue)
        info "new comparison: ${comparison}\noriginal: ${originalComparison}\nevent duration: ${state.duration}\ntotal duration: ${duration}\nvalue: ${[i: comparisonValue.i, v: [t: comparisonValue.v.t, v: value]]}\nrightValue: ${rightValue}\nrightValue2: ${rightValue2}", rtData
    	if (!comparison) break
        duration += state.duration
    }
    if (!duration) return false
    return (timeValue.f == 'l') ? duration < threshold : duration >= threshold
}

[TonyK1321]

private boolean valueWas(rtData, comparisonValue, rightValue, rightValue2, timeValue, func) {
if (!comparisonValue || !comparisonValue.v || !comparisonValue.v.d || !comparisonValue.v.a || !timeValue || !timeValue.v || !timeValue.vt) {
return false
}
def device = getDevice(rtData, comparisonValue.v.d)
if (!device) return false
def attribute = comparisonValue.v.a
long threshold = evaluateExpression(rtData, [t: ‘duration’, v: timeValue.v, vt: timeValue.vt], ‘long’).v

def states = listPreviousStates(device, attribute, threshold, (rtData.event.device?.id == device.id) && (rtData.event.name == attribute))
def result = true
long duration = 0
info "valueWas ${comparisonValue}", rtData
for (state in states) {
	def value = cast(rtData, state.value, comparisonValue.v.t)
	def comparison = "comp_$func"(rtData, [i: comparisonValue.i, v: [t: comparisonValue.v.t, v: value]], rightValue, rightValue2, timeValue)
    def originalComparison = "comp_$func"(rtData, [i: comparisonValue.i, v: [t: comparisonValue.v.t, v: state.value]], rightValue, rightValue2, timeValue)
    info "new comparison: ${comparison}\noriginal: ${originalComparison}\nevent duration: ${state.duration}\ntotal duration: ${duration}\nvalue: ${[i: comparisonValue.i, v: [t: comparisonValue.v.t, v: value]]}\nrightValue: ${rightValue}\nrightValue2: ${rightValue2}", rtData
	if (!comparison) break
    duration += state.duration
}
if (!duration) return false
return (timeValue.f == 'l') ? duration < threshold : duration >= threshold

}

OK, done. Which piston do you want me to monitor?