Timing issue in (or exposed by?) Rule Machine 4.0

TexasAggie97 · October 24, 2019, 10:02pm

This is more of an FYI since at least for me, the work around was very simple.

I have a Rule-4.0 rule that is triggered by a change of state of a virtual switch.
In the actions, I have a IF-ELSE-ENDIF based on the current state of that switch, and this correctly sees the new state.
After the ENDIF, I invoke the actions of another Rule4.0 rule. These actions ALSO look at the state of the same virtual switch. What I have found is that this other rule does not always see the new state. If I put in a delay before calling the actions, it will. I have not determined the minimum time since this particular rule doesn't need to respond immediately.

I can give all the gory details of these rules if it would help.

Ryan780 · October 24, 2019, 10:05pm

Is either rule changing the state of the virtual switch?

TexasAggie97 · October 24, 2019, 10:11pm

No. This virtual switch is changed by something else. Generally Google Assistant but sometime manually on the dashboard.

Ryan780 · October 24, 2019, 10:12pm

I would be very interested to see the rule you are talking about. Also, does the virtual switch use the auto-off function?

TexasAggie97 · October 25, 2019, 12:50am

The switch does not use the auto-off function.

Here is the triggered rule:

Here is the rule it calls:

I have tried both "Run Actions" (like it is now) and pushing the virtual button and I got the same behavior both ways.

Ryan780 · October 25, 2019, 2:22am

So, you're saying that when Goodnight? is turned on, the 1st rule evaluates it as On but the 2nd, which is run after, evaluates it as Off. Well, that would be a huge bug. You're talking about a fundamental problem with evaluation of a binary state switch. I would think that every user would be experiencing this. Do you have any logs for this happening? It would be helpfully if you have logging on for both rules and the virtual switches in question.

Also, have you ever considered using Modes to help you manage this?

destructure00 · October 25, 2019, 1:15pm

What symptoms are you seeing that tell you the state of the switch is being read wrong by the thermostat rule?

Terk · October 25, 2019, 4:19pm

You're missing an end-if in the second rule

TexasAggie97 · November 14, 2019, 5:41am

Sorry it has taken so long to get back to this issue but it started working for a while. It just started messing up again so I was able to get a log.

First to address some of the other comments.

I'm pretty sure I have all the conditionals correct and with the correct end-if.
The symptoms were that the wrong temperature was being set on the thermostat
I have thought about modes but I am tracking and looking at three different conditions:
1. Is everyone gone?
2. Are we in bed?
3. Is it dark outside?
These are not mutually exclusive so modes don't really work well

Anyway, on to the update.
I recently rebooted hubitat and it started acting incorrectly again. I don't know if rebooting is what caused it to start acting up or not though. It may be coincidence.
I was able to get a log:

dev:3712019-11-13 11:20:46.454 pm infoLiving Room Motion is inactive
dev:3712019-11-13 11:20:34.280 pm infoLiving Room Motion is inactive
dev:3712019-11-13 11:20:31.432 pm infoLiving Room Motion is active
dev:3672019-11-13 11:20:31.392 pm debugLiving Room Motion
dev:3712019-11-13 11:20:30.091 pm infoLiving Room Motion is inactive
dev:392019-11-13 11:20:25.752 pm infoHome Thermostat thermostatSetpoint is 71°F
dev:392019-11-13 11:20:20.828 pm infoHome Thermostat temperature is 73°F
dev:392019-11-13 11:20:20.826 pm infoHome Thermostat temperature is 73°F
dev:392019-11-13 11:20:20.766 pm infoHome Thermostat thermostatOperatingState is idle
dev:392019-11-13 11:20:20.746 pm infoHome Thermostat thermostatOperatingState is idle
dev:392019-11-13 11:20:20.692 pm infoHome Thermostat heatingSetpoint is 71°F
dev:392019-11-13 11:20:20.681 pm infoHome Thermostat heatingSetpoint is 71°F
dev:3712019-11-13 11:20:19.381 pm infoLiving Room Motion is inactive
dev:3712019-11-13 11:20:15.069 pm infoLiving Room Motion is active
dev:3672019-11-13 11:20:15.048 pm debugLiving Room Motion
dev:392019-11-13 11:19:28.482 pm infoHome Thermostat thermostatSetpoint is 71°F
dev:392019-11-13 11:19:25.320 pm infoHome Thermostat thermostatOperatingState is idle
dev:972019-11-13 11:19:24.745 pm warnCommandResponse skipped clusterId:0006, descMap:[raw:catchall: 0000 0006 00 00 0040 00 5A87 00 00 0000 00 00 02FDFF040101190000, profileId:0000, clusterId:0006, clusterInt:6, sourceEndpoint:00, destinationEndpoint:00, options:0040, messageType:00, dni:5A87, isClusterSpecific:false, isManufacturerSpecific:false, manufacturerId:0000, command:00, direction:00, data:[02, FD, FF, 04, 01, 01, 19, 00, 00]]
dev:972019-11-13 11:19:24.733 pm debugparseCommandResponse: [raw:catchall: 0000 0006 00 00 0040 00 5A87 00 00 0000 00 00 02FDFF040101190000, profileId:0000, clusterId:0006, clusterInt:6, sourceEndpoint:00, destinationEndpoint:00, options:0040, messageType:00, dni:5A87, isClusterSpecific:false, isManufacturerSpecific:false, manufacturerId:0000, command:00, direction:00, data:[02, FD, FF, 04, 01, 01, 19, 00, 00]]
dev:392019-11-13 11:19:23.452 pm infoHome Thermostat coolingSetpoint is 73°F
dev:972019-11-13 11:19:23.111 pm infoFront Door Lock battery is 73%
dev:972019-11-13 11:19:23.107 pm debugparseAttributeResponse: [raw:5A870100010821002049, dni:5A87, endpoint:01, cluster:0001, size:08, attrId:0021, encoding:20, command:0A, value:49, clusterInt:1, attrInt:33]
dev:972019-11-13 11:19:22.773 pm warnCommandResponse skipped clusterId:0006, descMap:[raw:catchall: 0000 0006 00 00 0040 00 5A87 00 00 0000 00 00 01FDFF0401010A0000, profileId:0000, clusterId:0006, clusterInt:6, sourceEndpoint:00, destinationEndpoint:00, options:0040, messageType:00, dni:5A87, isClusterSpecific:false, isManufacturerSpecific:false, manufacturerId:0000, command:00, direction:00, data:[01, FD, FF, 04, 01, 01, 0A, 00, 00]]
dev:972019-11-13 11:19:22.768 pm debugparseCommandResponse: [raw:catchall: 0000 0006 00 00 0040 00 5A87 00 00 0000 00 00 01FDFF0401010A0000, profileId:0000, clusterId:0006, clusterInt:6, sourceEndpoint:00, destinationEndpoint:00, options:0040, messageType:00, dni:5A87, isClusterSpecific:false, isManufacturerSpecific:false, manufacturerId:0000, command:00, direction:00, data:[01, FD, FF, 04, 01, 01, 0A, 00, 00]]
dev:392019-11-13 11:19:21.228 pm infoHome Thermostat thermostatOperatingState is idle
dev:1742019-11-13 11:19:21.050 pm infoLiving Room Home is idle
dev:1742019-11-13 11:19:20.424 pm infoLiving Room Home is playing
dev:972019-11-13 11:19:20.055 pm infoFront Door Lock was locked by digital command
dev:972019-11-13 11:19:20.046 pm debugparseCommandResponse: [raw:catchall: 0104 0101 01 01 0040 00 5A87 01 00 0000 20 01 0101FFFF00E54F5F2500, profileId:0104, clusterId:0101, clusterInt:257, sourceEndpoint:01, destinationEndpoint:01, options:0040, messageType:00, dni:5A87, isClusterSpecific:true, isManufacturerSpecific:false, manufacturerId:0000, command:20, direction:01, data:[01, 01, FF, FF, 00, E5, 4F, 5F, 25, 00]]
dev:392019-11-13 11:19:19.137 pm infoHome Thermostat heatingSetpoint is 71°F
dev:392019-11-13 11:19:19.134 pm infoHome Thermostat heatingSetpoint is 71°F
dev:352019-11-13 11:19:19.077 pm infoBedroom Overhead Light was turned off [digital]
dev:972019-11-13 11:19:19.053 pm debugparseCommandResponse: [raw:catchall: 0104 0101 01 01 0040 00 5A87 01 00 0000 00 01 00, profileId:0104, clusterId:0101, clusterInt:257, sourceEndpoint:01, destinationEndpoint:01, options:0040, messageType:00, dni:5A87, isClusterSpecific:true, isManufacturerSpecific:false, manufacturerId:0000, command:00, direction:01, data:[00]]
dev:972019-11-13 11:19:19.036 pm debugparseCommandResponse: [raw:catchall: 0104 0101 01 01 0040 00 5A87 01 00 0000 00 01 00, profileId:0104, clusterId:0101, clusterInt:257, sourceEndpoint:01, destinationEndpoint:01, options:0040, messageType:00, dni:5A87, isClusterSpecific:true, isManufacturerSpecific:false, manufacturerId:0000, command:00, direction:01, data:[00]]
dev:1612019-11-13 11:19:18.469 pm infoOffice Mini media source is Hubitat
dev:1622019-11-13 11:19:18.463 pm infoMaster Bedroom Mini media source is Hubitat
dev:1742019-11-13 11:19:18.448 pm infoLiving Room Home media source is Hubitat
app:2982019-11-13 11:19:16.984 pm infoAction: END-IF
app:2982019-11-13 11:19:16.977 pm infoAction:     Thermostats: Home Thermostat: 
                                                                                                  --> Heat: 73 
                                                                                                  --> Cool: 76  (skipped)
app:2982019-11-13 11:19:16.943 pm infoAction: ELSE (skipped)
app:2982019-11-13 11:19:16.942 pm infoAction:     Thermostats: Home Thermostat: 
                                                                                                  --> Heat: 64 
                                                                                                  --> Cool: 82  (skipped)
app:2982019-11-13 11:19:16.939 pm infoAction: ELSE-IF (Is Gone?(off) is on(F) [FALSE]) THEN (skipping)
dev:392019-11-13 11:19:16.823 pm debugsetCoolingSetpoint(73.0) was called
dev:392019-11-13 11:19:16.538 pm debugsetHeatingSetpoint(64.0) was called
app:3042019-11-13 11:19:16.432 pm infoHSM Alert: armedHome
app:2982019-11-13 11:19:16.414 pm infoAction:     Thermostats: Home Thermostat: 
                                                                                                  --> Heat: 64 
                                                                                                  --> Cool: 73 
app:2982019-11-13 11:19:16.390 pm infoAction: IF (Is Goodnight?(on) is on(T) [TRUE]) THEN
dev:342019-11-13 11:19:16.334 pm infoLiving Room Overhead Light was turned off [digital]
app:32019-11-13 11:19:16.188 pm infoArmed Home
app:2982019-11-13 11:19:16.186 pm infoUpdate Thermostat Setpoints: Actions run by Goodnight (triggered)
dev:2252019-11-13 11:19:16.137 pm infoOffice fan and light  light was turned off
dev:3552019-11-13 11:19:15.572 pm infoIs Goodnight? was turned on
--- Live Log Started, waiting for events ---

It looks like the correct condition is executed, but the wrong temperature is set. This is with the delay removed. If I have the delay, the correct temperature is set.

I am not sure where 71F is coming from since I don't set that temperature.

Here is the log from when it set the temperature correctly

dev:2252019-11-13 11:32:44.497 pm infoOffice fan and light  light was turned on
dev:392019-11-13 11:30:57.477 pm infoHome Thermostat thermostatSetpoint is 71°F
dev:392019-11-13 11:30:54.386 pm infoHome Thermostat thermostatOperatingState is idle
dev:392019-11-13 11:30:52.423 pm infoHome Thermostat coolingSetpoint is 73°F
dev:392019-11-13 11:30:50.791 pm infoHome Thermostat thermostatOperatingState is idle
dev:392019-11-13 11:30:48.181 pm infoHome Thermostat heatingSetpoint is 71°F
dev:3212019-11-13 11:30:48.143 pm infoMark Silva has arrived
app:2982019-11-13 11:30:45.941 pm infoAction: END-IF
app:2982019-11-13 11:30:45.939 pm infoAction:     Thermostats: Home Thermostat: 
                                                                                                  --> Heat: 73 
                                                                                                  --> Cool: 76  (skipped)
app:2982019-11-13 11:30:45.935 pm infoAction: ELSE (skipped)
app:2982019-11-13 11:30:45.934 pm infoAction:     Thermostats: Home Thermostat: 
                                                                                                  --> Heat: 64 
                                                                                                  --> Cool: 82  (skipped)
app:2982019-11-13 11:30:45.929 pm infoAction: ELSE-IF (Is Gone?(off) is on(F) [FALSE]) THEN (skipping)
dev:392019-11-13 11:30:45.896 pm debugsetCoolingSetpoint(73.0) was called
dev:392019-11-13 11:30:45.876 pm debugsetHeatingSetpoint(64.0) was called
app:2982019-11-13 11:30:45.867 pm infoAction:     Thermostats: Home Thermostat: 
                                                                                                  --> Heat: 64 
                                                                                                  --> Cool: 73 
app:2982019-11-13 11:30:45.863 pm infoAction: IF (Is Goodnight?(on) is on(T) [TRUE]) THEN
app:2982019-11-13 11:30:45.822 pm infoUpdate Thermostat Setpoints: Actions run by Goodnight (triggered)
dev:972019-11-13 11:30:39.195 pm warnCommandResponse skipped clusterId:0006, descMap:[raw:catchall: 0000 0006 00 00 0040 00 5A87 00 00 0000 00 00 02FDFF040101190000, profileId:0000, clusterId:0006, clusterInt:6, sourceEndpoint:00, destinationEndpoint:00, options:0040, messageType:00, dni:5A87, isClusterSpecific:false, isManufacturerSpecific:false, manufacturerId:0000, command:00, direction:00, data:[02, FD, FF, 04, 01, 01, 19, 00, 00]]
dev:972019-11-13 11:30:39.186 pm debugparseCommandResponse: [raw:catchall: 0000 0006 00 00 0040 00 5A87 00 00 0000 00 00 02FDFF040101190000, profileId:0000, clusterId:0006, clusterInt:6, sourceEndpoint:00, destinationEndpoint:00, options:0040, messageType:00, dni:5A87, isClusterSpecific:false, isManufacturerSpecific:false, manufacturerId:0000, command:00, direction:00, data:[02, FD, FF, 04, 01, 01, 19, 00, 00]]
dev:972019-11-13 11:30:37.814 pm infoFront Door Lock battery is 73%
dev:972019-11-13 11:30:37.812 pm debugparseAttributeResponse: [raw:5A870100010821002049, dni:5A87, endpoint:01, cluster:0001, size:08, attrId:0021, encoding:20, command:0A, value:49, clusterInt:1, attrInt:33]
dev:972019-11-13 11:30:37.295 pm warnCommandResponse skipped clusterId:0006, descMap:[raw:catchall: 0000 0006 00 00 0040 00 5A87 00 00 0000 00 00 01FDFF0401010A0000, profileId:0000, clusterId:0006, clusterInt:6, sourceEndpoint:00, destinationEndpoint:00, options:0040, messageType:00, dni:5A87, isClusterSpecific:false, isManufacturerSpecific:false, manufacturerId:0000, command:00, direction:00, data:[01, FD, FF, 04, 01, 01, 0A, 00, 00]]
dev:972019-11-13 11:30:37.288 pm debugparseCommandResponse: [raw:catchall: 0000 0006 00 00 0040 00 5A87 00 00 0000 00 00 01FDFF0401010A0000, profileId:0000, clusterId:0006, clusterInt:6, sourceEndpoint:00, destinationEndpoint:00, options:0040, messageType:00, dni:5A87, isClusterSpecific:false, isManufacturerSpecific:false, manufacturerId:0000, command:00, direction:00, data:[01, FD, FF, 04, 01, 01, 0A, 00, 00]]
dev:972019-11-13 11:30:34.465 pm infoFront Door Lock was locked by digital command
dev:972019-11-13 11:30:34.462 pm debugparseCommandResponse: [raw:catchall: 0104 0101 01 01 0040 00 5A87 01 00 0000 20 01 0101FFFF0087525F2500, profileId:0104, clusterId:0101, clusterInt:257, sourceEndpoint:01, destinationEndpoint:01, options:0040, messageType:00, dni:5A87, isClusterSpecific:true, isManufacturerSpecific:false, manufacturerId:0000, command:20, direction:01, data:[01, 01, FF, FF, 00, 87, 52, 5F, 25, 00]]
dev:972019-11-13 11:30:33.449 pm debugparseCommandResponse: [raw:catchall: 0104 0101 01 01 0040 00 5A87 01 00 0000 00 01 00, profileId:0104, clusterId:0101, clusterInt:257, sourceEndpoint:01, destinationEndpoint:01, options:0040, messageType:00, dni:5A87, isClusterSpecific:true, isManufacturerSpecific:false, manufacturerId:0000, command:00, direction:01, data:[00]]
dev:972019-11-13 11:30:33.439 pm debugparseCommandResponse: [raw:catchall: 0104 0101 01 01 0040 00 5A87 01 00 0000 00 01 00, profileId:0104, clusterId:0101, clusterInt:257, sourceEndpoint:01, destinationEndpoint:01, options:0040, messageType:00, dni:5A87, isClusterSpecific:true, isManufacturerSpecific:false, manufacturerId:0000, command:00, direction:01, data:[00]]
app:3042019-11-13 11:30:30.938 pm infoHSM Alert: armedHome
app:32019-11-13 11:30:30.727 pm infoArmed Home
dev:2252019-11-13 11:30:30.720 pm infoOffice fan and light  light was turned off
dev:3552019-11-13 11:30:30.369 pm infoIs Goodnight? was turned on
--- Live Log Started, waiting for events ---

Initially, 71F was the setpoint for the else clause, so I thought it was hitting that condition. Now that I am setting a different value, it is obvious that this number is coming from somewhere else.

The thermostat is a Filtrete branded Radio Thermostat that can take multiple radio modules. Right now there is only the Z-Wave module installed and the device type is set to Generic Z-Wave Thermostat.

Let me know if there is something else to try, or more logs that would help. Since I have a workaround, I don't consider this a high priority or anything.

system · September 19, 2022, 7:11pm

This topic was automatically closed 365 days after the last reply. New replies are no longer allowed.