I'm noticing that positions run but it is missing actions at times. Very strange. I will need to more research, but it stated (example. locking the door) but it doesn't actually do it.
Try turning command optimizations off (Edit, click on piston title line, click on gear icon); that will always force the command to be sent even if webCoRE thinks the device is already in the intended state). Useful when the hub's copy of the device's state and the actual state are not the same.
What actions in particular? If it is mostly a door lock, then the door lock could be the problem. I have implemented Webcore to do a refresh, wait 2 seconds, and then lock/unlock as needed.
I find especially with door locks, they don't update very well. Sometimes if the door is manually locked or unlocked, it won't update properly in Hubitat. As an example, if you lock the door and it does not update properly, then Hubitat thinks it is unlocked. If you then try to unlock it, it will not do anything as it thinks the door is already unlocked. Typically a refresh will update the locked / unlocked status, and then issuing the command works (at least for me it does).
Disabling command optimizations should work here as well. This forces the command, even if it is currently in that state. But personally, I would start with a refresh and wait to see if that works
1 Like
Two days ago noticed that one of my piston was not working anymore. According log it seems that piston is not able to receive location mode changes anymore. I get that null error too and piston log shows just weird xvnmljgffjkk or something when mode changes.
I removed location if's from piston and now use security system status. Anyone else having this issue?
I'm running latest released version on webcore and Hubitat too.
It would be good to have paused /resumed the piston
Next would have been to reboot the hub
It would otherwise be good to see piston (green) and logs
Did a new piston
And logs:
08/06/2021, 05:00:28 +540ms
+4ms ╔Received event [HubitatHome].test = 1623117628540 with a delay of 1ms, canQueue: true, calledMyself: false
+10ms ║RunTime initialize > 9 LockT > 1ms > rtDT > 1ms > pistonT > 0ms (first state access 7 5 4)
+12ms ║Runtime (5567 bytes) successfully initialized in 1ms (v0.3.113.20210510_HE)
+13ms ║╔Execution stage started
+18ms ║║Comparison (string) :7c76bcf13f4437d56396ddf04776b595: changes_to (string) :7c76bcf13f4437d56396ddf04776b595: = false (0ms)
+20ms ║║Condition #2 evaluated false (4ms)
+21ms ║║Condition group #1 evaluated false (state did not change) (5ms)
+24ms ║╚Execution stage complete. (12ms)
+27ms ╚Event processed successfully (24ms)
..and no need to worry about that AND.. it should be OR I know but it does not make a difference. Location mode is not recognised.
Edit: also started with hub reboot of course and did also hpm repair. No help.
So you seem to be using changes_to vs. is.
If you want changes, the mode has to change when the piston runs. Running a test is not a mode change. (mode was the same before and after).
I suggest you use the comparison is, and if needed have the piston subscribe to mode changes. (always subscribe, or a dummy if statement for mode changes).
Not sure what happend but changing piston IF mode changes THEN... and changing mode -> works.
Went back to old piston which was not working and now location mode changes works there too.
What is the reason for piston log to show location mode changes as "7c76bcf13f4437d56396ddf04776b595" ?
8.6.2021 klo 7.12.30 +648ms
+15ms ╔Subscribing to devices...
+412ms ║Device missing from piston. Loading all from parent (394ms)
+421ms ║Subscribing to HubitatHome.mode...
+438ms ║Piston controls Outlet Infouscreen...
+440ms ║Piston controls Tablet_screen_vswitch...
+528ms ╚Finished subscribing (517ms)
+567ms ║Comparison (string) :7c76bcf13f4437d56396ddf04776b595: changes_to_any_of (string) :80ff8adc87cc6d0d790b1bb31708f282:,:db51cd17b1529242205547665623a183: = false (0ms)
+576ms ║Comparison (string) :7c76bcf13f4437d56396ddf04776b595: changes_to (string) :7c76bcf13f4437d56396ddf04776b595: = false (1ms)
+586ms ╔Starting piston... (v0.3.113.20210510_HE)
+588ms ╚Piston successfully started (579ms)
Not sure I see it working here.
It would be good to see logs when a mode change actually occurs.
I use mode changes as both triggers and conditions, so I know they work. You might re-create the if statement completely.
I use in mine:
if Location Mode changes. ....
in some
In others I use
if Location mode receives Evening
These are how I control mode changes, so they do work...
I will try that.
It just happened today. Note this has been working for at least a year without issue.
This just happened today:
Time to be concerned with is 7:56AM
6/8/2021, 7:56:50 AM +94ms
+36ms ╔Received event [Kate ].presence = not present with a delay of 132ms, canQueue: true, calledMyself: false
+156ms ║RunTime initialize > 155 LockT > 0ms > rtDT > 118ms > pistonT > 117ms (first state access 37 36 119)
+161ms ║Runtime (10914 bytes) successfully initialized in 118ms (v0.3.113.20210510_HE)
+163ms ║╔Execution stage started
+182ms ║║Comparison (enum) not present changes_to (string) present = false (0ms)
+184ms ║║Cancelling condition #2's schedules...
+186ms ║║Condition #2 evaluated false (11ms)
+188ms ║║Cancelling condition #1's schedules...
+190ms ║║Condition group #1 evaluated false (state changed) (15ms)
+199ms ║║Comparison (enum) not present changes_to (string) not present = true (0ms)
+300ms ║║Condition #8 evaluated true (108ms)
+316ms ║║Comparison (enum) closed is (string) closed = true (1ms)
+319ms ║║Condition #9 evaluated true (18ms)
+388ms ║║Comparison (long) 40575631 is_greater_than_or_equal_to (integer) 600000 = true (3ms)
+390ms ║║Condition #10 evaluated true (70ms)
+397ms ║║Comparison (enum) unlocked is (string) unlocked = true (2ms)
+399ms ║║Cancelling condition #11's schedules...
+401ms ║║Condition #11 evaluated true (9ms)
+403ms ║║Cancelling condition #7's schedules...
+404ms ║║Condition group #7 evaluated true (state changed) (212ms)
+406ms ║║Cancelling statement #12's schedules...
+444ms ║║Executed physical command [Alfred Z-Wave Lock].lock() (35ms)
+446ms ║║Executed [Alfred Z-Wave Lock].lock (38ms)
+517ms ║╚Execution stage complete. (355ms)
+554ms ╚Event processed successfully (520ms)
The lock didn't lock when she had left.
Lock log
I test the lock just to make sure it did responds to z wave commends.
Not this doesn't do it all the time. This position has very stable until recently, but nothing had changed.
Rule
Yep, this is weird.
I have 6 pistons where I use location mode.
One of those is:
..and it's built just a way like yours. And it works, so no worries.
Log is just weird:
8.6.2021 klo 13.29.32 +59ms
+43ms ╔Received event [HubitatHome].mode = Day with a delay of 333ms, canQueue: true, calledMyself: false
+49ms ║RunTime initialize > 48 LockT > 3ms > rtDT > 1ms > pistonT > 0ms (first state access 44 47 1)
+52ms ║Runtime (6033 bytes) successfully initialized in 1ms (v0.3.113.20210510_HE)
+53ms ║╔Execution stage started
+75ms ║║Comparison (string) :7c76bcf13f4437d56396ddf04776b595: changes_to_any_of (string) :80ff8adc87cc6d0d790b1bb31708f282:,:db51cd17b1529242205547665623a183: = false (14ms)
+77ms ║║Cancelling condition #2's schedules...
+79ms ║║Condition #2 evaluated false (21ms)
+81ms ║║Cancelling condition #1's schedules...
+82ms ║║Condition group #1 evaluated false (state changed) (25ms)
+88ms ║║Comparison (string) :7c76bcf13f4437d56396ddf04776b595: changes_to (string) :7c76bcf13f4437d56396ddf04776b595: = true (0ms)
+91ms ║║Cancelling condition #6's schedules...
+92ms ║║Condition #6 evaluated true (7ms)
+94ms ║║Cancelling condition #5's schedules...
+96ms ║║Condition group #5 evaluated true (state changed) (11ms)
+97ms ║║Cancelling statement #7's schedules...
+561ms ║║Executed physical command [Outlet Infouscreen].on() (413ms)
+578ms ║║Executed [Outlet Infouscreen].on (460ms)
+625ms ║║Executed physical command [Tablet_screen_vswitch].on() (44ms)
+626ms ║║Executed [Tablet_screen_vswitch].on (46ms)
+632ms ║╚Execution stage complete. (580ms)
+636ms ╚Event processed successfully (593ms)
Hubitat log has one line:
2021-06-08 13:29:32.726 Released Lock and exiting
and system event gets:
So no idea why it shows that string in piston log.
I don't think that turning command optimizations will help with this scenario as evidenced by the logs; when it might be relevant is when you see the logs indicate that the command was skipped because it would make no change to the state of the device (or words to that effect). In your case the logs indicate that the command was executed by WebCoRE.
@Tony I turned off the optimization, parallel and pre-scheduling. Just see if there was a change even within Hubitat OS that was changed that is now affecting this. Let's see what happens from here. Thank you for your help. Would have another advice for troubleshooting this? Thanks again.
You should turn on logging for the device in question to see what it displays it is receiving
I guess I'd start by first making sure that the device was absolutely reliable (when operated from the device page). There seem to be lots of issues with the reliability of Z-Wave locks unrelated to WebCoRE; you'd want to rule out any device issues first before focusing on the automations. Have you ever been able to reliably automate this device, or have these problems started recently?
No I've never had problems with this device before. I believe it started happening after the hub update of .126. That's why maybe I thought there was some sort of conflict between the update and the settings with that position. I can't say I've had any other issues with any other positions. Although, this position is used quite often. I am using a hubconnect to the other device so I have the S2 compatibility. Again, never had issues and I've tested it manually and didn't see any issues. It logged accordingly and responded appropriately. However when this position kicks off it doesn't show that the device was actually attempted to lock or unlock. This is why I thought maybe it was a webcore issue. Thanks again for your help.
So far so good. I disabled optimization, prescheduling, and parallel processing. So far this has been working well. Need to give it a few more days but this seemed to address my issue.
1 Like
Here's a bit of a fun one in the logs today. No external influences or pistons acting up so maybe just an internal opps.
pp:122021-06-17 03:02:10.660 errorjava.lang.RuntimeException: java.lang.RuntimeException: java.sql.SQLException: The object is already closed [90007-197] Query: SELECT APPSET.ID, APPSET.VERSION, APPSET.INSTALLED_APP_ID, APPSET.NAME, APPSET.TYPE, APPSET.VALUE, APPSET.MULTIPLE, ASDL.DEVICE_ID FROM APP_SETTING APPSET LEFT JOIN APP_SETTING_DEVICE_LINK ASDL ON ASDL.APP_SETTING_ID = APPSET.ID WHERE APPSET.INSTALLED_APP_ID = ? ORDER BY APPSET.ID Parameters: [33] on line 2554 (finishRecovery)
That sounds like your HE DB (vs webcore).
If a hub reboot does not resolve this, you may be into doing soft reset and db restore.
