Power Comparison Failed

ipaterson · 2018-02-24 17:27:04 UTC

It would be good to see the enum one as well as one of the decimal power pistons.

TonyK1321 · 2018-02-24 18:40:55 UTC

Here’s one of the logs that shows an OK comparison and one that is wrong.

2/24/2018, 11:38:00 AM +365ms
+5ms ╔Received event [Home].time = 1519497481403 with a delay of -1048ms
+268ms ║RunTime Analysis CS > 46ms > PS > 127ms > PE > 100ms > CE
+277ms ║Runtime (39934 bytes) successfully initialized in 127ms (v0.2.102.20180116) (265ms)
+282ms ║╔Execution stage started
+427ms ║║Comparison (enum) on is (string) on = true (7ms)
+434ms ║║Condition #7 evaluated true (47ms)
+503ms ║║valueWas [i::294904ea719da70376d4625934e3c493::power, v:[t:decimal, v:0.2, d::294904ea719da70376d4625934e3c493:, a:power, i:null, x:false, vt:string]]
+514ms ║║new comparison: true
+514ms ║║original: true
+514ms ║║event duration: 18579
+515ms ║║total duration: 0
+515ms ║║value: [i::294904ea719da70376d4625934e3c493::power, v:[t:decimal, v:0.2]]
+515ms ║║rightValue: [i:9:1:0, v:[t:integer, v:20, d:0, vt:decimal]]
+515ms ║║rightValue2: null
+520ms ║║new comparison: true
+520ms ║║original: true
+520ms ║║event duration: 1009
+521ms ║║total duration: 18579
+521ms ║║value: [i::294904ea719da70376d4625934e3c493::power, v:[t:decimal, v:1.1]]
+521ms ║║rightValue: [i:9:1:0, v:[t:integer, v:20, d:0, vt:decimal]]
+521ms ║║rightValue2: null
+527ms ║║new comparison: false
+527ms ║║original: true
+527ms ║║event duration: 1003
+527ms ║║total duration: 19588
+527ms ║║value: [i::294904ea719da70376d4625934e3c493::power, v:[t:decimal, v:21.9]]
+528ms ║║rightValue: [i:9:1:0, v:[t:integer, v:20, d:0, vt:decimal]]
+528ms ║║rightValue2: null
+529ms ║║Comparison (decimal) 0.2 was_less_than (integer) 20 = false (84ms)
+531ms ║║Condition #9 evaluated false (96ms)
+533ms ║║Condition group #2 evaluated false (state did not change) (151ms)
+549ms ║║Comparison (enum) on is (string) off = false (4ms)
+551ms ║║Condition #19 evaluated false (12ms)
+552ms ║║Condition group #16 evaluated false (state did not change) (15ms)
+567ms ║╚Execution stage complete. (289ms)
+584ms ║Setting up scheduled job for Sat, Feb 24 2018 @ 11:40:01 AM MST (in 120.458s)
+594ms ╚Event processed successfully (597ms)

2/24/2018, 11:36:00 AM +405ms
+1ms ╔Received event [Home].time = 1519497361403 with a delay of -999ms
+214ms ║RunTime Analysis CS > 25ms > PS > 117ms > PE > 72ms > CE
+216ms ║Runtime (39932 bytes) successfully initialized in 117ms (v0.2.102.20180116) (214ms)
+217ms ║╔Execution stage started
+240ms ║║Comparison (enum) on is (string) on = true (5ms)
+241ms ║║Condition #7 evaluated true (13ms)
+281ms ║║valueWas [i::294904ea719da70376d4625934e3c493::power, v:[t:decimal, v:76.6, d::294904ea719da70376d4625934e3c493:, a:power, i:null, x:false, vt:string]]
+285ms ║║new comparison: false
+285ms ║║original: true
+285ms ║║event duration: 2416
+285ms ║║total duration: 0
+285ms ║║value: [i::294904ea719da70376d4625934e3c493::power, v:[t:decimal, v:76.6]]
+286ms ║║rightValue: [i:9:1:0, v:[t:integer, v:20, d:1, vt:decimal]]
+286ms ║║rightValue2: null
+286ms ║║Comparison (decimal) 76.6 was_less_than (integer) 20 = false (36ms)
+288ms ║║Condition #9 evaluated false (46ms)
+289ms ║║Condition group #2 evaluated false (state did not change) (61ms)
+300ms ║║Comparison (enum) on is (string) off = false (2ms)
+301ms ║║Condition #19 evaluated false (9ms)
+303ms ║║Condition group #16 evaluated false (state did not change) (12ms)
+306ms ║╚Execution stage complete. (89ms)
+308ms ║Setting up scheduled job for Sat, Feb 24 2018 @ 11:38:01 AM MST (in 120.691s)
+317ms ╚Event processed successfully (317ms)

TonyK1321 · 2018-02-24 18:44:21 UTC

Here’s the piston if you want to see that.

ipaterson · 2018-02-24 19:04:09 UTC

The logs show that the piston run at 11:38:00 AM was about 20 seconds after a 21.9W reading. Additionally since the power was 76.6W at 11:36:00 AM we wouldn’t expect the 15 minutes to be elapsed yet, right?

TonyK1321 · 2018-02-24 20:07:06 UTC

Right, the 15 min has not up yet. But I did not run it long enough to see what would have happened at 11:53. I was just looking at the result of the comparison that said Comparison (decimal) 0.2 was_less_than (integer) 20 = false (84ms). If it’s OK, then I will keep that version running for now and let it go through some normal cycles to see if anything hiccups.

BTW, that piston that I showed before for the recirc pump that failed the enum test is now running fine with this version with no failures that I can detect. Would it be useful for me to try your original changed version again? Maybe something got screwed up when I did the change the 1st time.

ipaterson · 2018-02-24 20:12:30 UTC

The version you are using will be fine, we plan to do a release today so you can just update later to get rid of the debug code.

The condition is returning false because of the duration rather than the value, it’s just not clear from the “Comparison (decimal) 0.2 was_less_than (integer) 20 = false (84ms)” log text. I can’t edit that specific text but I could add a debug message above it to specify that the condition check failed because of the duration - I think that would avoid a lot of confusion since the was operator is more complicated than the logs show.

ipaterson · 2018-02-24 21:13:21 UTC

How do you feel about changing the log to the following to clarify the failure? I can add a log line before the comparison:

+711ms	║║Duration 191344ms for was_greater_than >= 900000ms threshold = false
+712ms	║║Comparison (decimal) 5762.0 was_greater_than (integer) 1040 = false (72ms)

Caveat – frequently updated attributes

I will leave this discussion with a final important note: was comparisons only look at the last 100 events in your device state. If you are trying to observe a 15 minute time window on an attribute that is updated every second your condition will never be true! You could only inspect a window of up to about 100 seconds under those conditions. Instead, consider building your logic around stays which monitors a state going forward rather than looking back at past values.

TonyK1321 · 2018-02-24 22:21:24 UTC

For the log line, sure, that makes sense. For the WAS comparison, I’m only looking at 7 or 8 past events to get to 15 min (once every 2 min). But when the TV is on, it looks like the power adapter is sending 11-15 updates/min back to the hub that I can see in the mobile app, so likely only 7 min worth of data in the 100 samples. But as it is shutting off, it sends less and less data, so that when it’s off, it is sending no data. Used in this way, there might not be a problem at 15 min. But I will look at using STAY instead. And thanks, I did not know or think about a restriction on WAS.

Again, thanks for finding a fix to this problem.

ipaterson · 2018-02-24 22:41:38 UTC

Yep, exactly. The was condition can be quite tricky but I’m very glad that you were persistent with this issue until it was identified and fixed!

ipaterson · 2018-02-24 23:59:26 UTC

Oops! To address any lingering confusion you may have about the first bit of code that I posted, it turned out to have a serious typo. Rather than casting the power value to a decimal value it was trying to cast the word “decimal” to a number because I switched the order of the parameters. The actual comparison ended up being "decimal" < 10.0 which was… not right

Figured this out when testing was greater than and it was saying that 3000 was not greater than 1000.

Does not affect the second bit of code that was posted, and I went back to correct the original one in case anyone finds this thread later.

TonyK1321 · 2018-02-25 00:26:27 UTC

Ah, that explains why all my pistons that used the WAS condition failed. The 2nd code, the whole function, seems to work well.

ipaterson · 2018-02-25 22:41:03 UTC

This should be fixed in today’s 0.3.0 release.

TonyK1321 · 2018-02-26 00:27:26 UTC

Thanks.

TonyK1321 · 2018-02-26 04:46:17 UTC

Ian - I just updated to the newest WebCore version. Just after I did, it ran my WAS piston. Here are the logs. I like the additional logging for the time restriction of the WAS, thanks, and it shut off the bulb as it was supposed to. But then it was followed by a Skip Execution statement for the 2nd device, but then it tried to Off the device anyway. Hmmm. It does not really matter, just a non-consequential contradiction. Am I interpreting those statements correctly?

2/25/2018, 9:32:40 PM +387ms
+1ms ╔Received event [Home].time = 1519619561101 with a delay of -714ms
+206ms ║RunTime Analysis CS > 14ms > PS > 87ms > PE > 105ms > CE
+209ms ║Runtime (40577 bytes) successfully initialized in 87ms (v0.3.000.20180224) (208ms)
+210ms ║╔Execution stage started
+231ms ║║Comparison (enum) on is (string) on = true (2ms)
+233ms ║║Condition #7 evaluated true (9ms)
+285ms ║║Comparison (time) 77560621 is_between (time) 75600000 … (time) 1519565880000 = true (11ms)
+287ms ║║Time restriction check passed
+288ms ║║Condition #22 evaluated true (55ms)
+327ms ║║Duration 935852ms for was_less_than >= 900000ms threshold = true
+328ms ║║Comparison (decimal) 0.3 was_less_than (integer) 20 = true (33ms)
+330ms ║║Cancelling condition #23’s schedules…
+331ms ║║Condition #23 evaluated true (41ms)
+332ms ║║Cancelling condition #2’s schedules…
+332ms ║║Condition group #2 evaluated true (state changed) (109ms)
+335ms ║║Cancelling statement #10’s schedules…
+578ms ║║Executed physical command [Living Room Bulb].off() (240ms)
+579ms ║║Executed [Living Room Bulb].off (241ms)
+583ms ║║Skipped execution of physical command [Living Room Light].off([]) because it would make no change to the device. (2ms)
+584ms ║║_Executed [Living Room Light].off (4ms)_
+595ms ║║Comparison (enum) on is (string) off = false (2ms)
+596ms ║║Condition #19 evaluated false (8ms)
+597ms ║║Condition group #16 evaluated false (state did not change) (10ms)
+600ms ║╚Execution stage complete. (391ms)
+602ms ║Setting up scheduled job for Sun, Feb 25 2018 @ 9:34:41 PM MST (in 120.113s)
+609ms ╚Event processed successfully (609ms)

ipaterson · 2018-02-26 12:00:22 UTC

Nothing to worry about there, the “Executed” line is always logged after calling the smart app function that performs (or in this case does not perform) the physical command or after calling a command built into webCoRE like setColorTemperature.

TonyK1321 · 2018-02-26 14:07:40 UTC

Got that, but did the next line execute when it should not have?

ipaterson · 2018-02-26 14:52:35 UTC

This one?

+584ms ║║Executed [Living Room Light].off (4ms)

That one will always be logged regardless of whether the command is physical or virtual and whether it actually interacts with the device or not.

            def msg = timer "Executed [$device].${task.c}"
        	try {
            	delay = "cmd_${task.c}"(rtData, device, params)
            } catch(all) {
	            executePhysicalCommand(rtData, device, task.c, params)
			}
            if (rtData.logging > 1) trace msg, rtData  // <-- here

TonyK1321 · 2018-02-26 18:06:04 UTC

It’s just confusing. The previous statement said it was not going to execute followed by a statement that said it did execute.