Capture & Restore

[lflorack]

My logs show that the capturing is not happening - but it actually is - in spite of my piston saying that the capture should only occur when the store is empty.

This piston works (i.e., the lights act as expected when the doorbell rings or one/both of us arrive at home when it’s dark), but the extra log entries are not expected and were not seen until recently. It seems like the capture and store are being attempted a second time. Although I don’t think that’s unusual or unexpected, the log entries about not being able to capture the info is both unexpected and before recently, did not occur.

Note: The accelerator device is my doorbell.

Here’s my piston:

and here’s the associated log foe a single sequence (an arrival):

[E_Sch]

Can you show medium logs

I’m not seeing the wakeup events

[lflorack]

Can you show medium logs

I’m not seeing the wakeup events

Yeah. I normally don’t need the logs on at any level, so what I posted earlier was with the logs off. It kinda surprised me that anything other than what I intentionally added to the logs was showing up.

To further explain the event I showed previously… My wife and I arrived home (i.e., we became present) with our iPhones. As is normal, although we were in the same car, our phones never arrive at exactly the same time - and therefore there were two arrival events. But that’s why the ‘only if the store is empty’ part of the capture command is there. Maybe it happened because the second arrival occurred so fast that the data writing to store hadn’t completed yet? Normally, it’s all handled well and no extra info is logged about the uneven arrival.

The piston can be activated for the above scenario or by pressing the doorbell. So to test without actually driving away and returning, I set logging to medium and pressed the doorbell three times in quick succession. Everything worked as expected and the ‘could not store’ messages that I showed before did not happen. So I’ll have to leave and then return for a better test since I’m sure this has something to do with the speed of the two iPhones arriving home at almost the same time. I’ll post those results when I get a chance to do the test. However, this has never occurred previously so I’m unsure why it happened now.

Anyway, here are the logs for the 3-doorbell-press event
(Edit: I pasted more easily readable logs here to replace what I originally posted. However, the original action had been cut off by the time I went back to get the better log. So, the full version of the initial action is shown as text too.)

2/9/2023, 7:33:39 AM +127ms
+7ms ╔Received event [Doorbell Sensor].acceleration = active with a delay of 37ms, canQueue: true, calledMyself: false
+25ms ║Runtime (11435 bytes) initialized in 3ms (v0.3.114.20230130_HE)
+26ms ║╔Execution stage started
+161ms ║║Executed virtual command [Carriage Lights].saveStateLocally (7ms)
+167ms ║║Executed virtual command [Chandelier].saveStateLocally (4ms)
+172ms ║║Executed virtual command [Front Door].saveStateLocally (3ms)
+178ms ║║Executed virtual command [Carriage Lights, Chandelier, Front Door].wait [1000] (1ms)
+183ms ║║Requesting wake up at Thu, Feb 9 2023 @ 7:33:40 AM EST (in 998ms) for 9 (st:11)
+188ms ║╚Execution stage complete. (161ms)
+322ms ║Setting up scheduled job for Thu, Feb 9 2023 @ 7:33:40 AM EST (in 985ms)
+326ms ╚Event processed successfully (320ms)

[E_Sch]

ok, it is a logging issue (too noisy), I push a fix to quiet it down).

I don’t see a webcore error.

If you think there is an error please help point it out to me.

[lflorack]

ok, it is a logging issue (too noisy), I push a fix to quiet it down).

I don’t see a webcore error.

If you think there is an error please help point it out to me.

Yes, I guess that’s what it is – webCoRE logging that it couldn’t write to the store, when that’s what I set webCoRE to do when multiple sensors (iPhones) quickly report as present. Thanks for the pushed update. I’ll go install that now.

Anyway, I ran another test - this time with our iPhones. The logging about not being able to write to the store came up again.

Here’s just the section with the “Could not store” messages:

And, here’s the complete log for that full event with the “Could not store…” messages in bold:

2/9/2023, 12:26:08 PM +88ms
+4ms ╔Received event [Florack Hubitat].time = 1675963568062 with a delay of 26ms, canQueue: true, calledMyself: false
+19ms ║Runtime (11337 bytes) initialized in 3ms (v0.3.114.20230130_HE)
+26ms ║╔Execution stage started
+48ms ║║Executed device command [Carriage Lights].off() (16ms)
+51ms ║╚Execution stage complete. (24ms)
+57ms ║Processing timer time = 1675963568091
+58ms ║╔Execution stage started
+78ms ║║Executed device command [Chandelier].off() (15ms)
+81ms ║╚Execution stage complete. (23ms)
+86ms ║Processing timer time = 1675963568121
+87ms ║╔Execution stage started
+108ms ║║Executed device command [Front Door].off() (15ms)
+111ms ║╚Execution stage complete. (24ms)
+117ms ║Processing timer time = 1675963568125
+118ms ║╔Execution stage started
+142ms ║║The Carriage Lights, Chandelier and Front Door have been reset to their previous On/Off and Level status.
+145ms ║║Executed virtual command [Carriage Lights, Chandelier, Front Door].log (4ms)
+149ms ║╚Execution stage complete. (32ms)
+154ms ╚Event processed successfully (151ms)
2/9/2023, 12:26:06 PM +681ms
+5ms ╔Received event [Florack Hubitat].time = 1675963566652 with a delay of 29ms, canQueue: true, calledMyself: false
+20ms ║Runtime (11737 bytes) initialized in 2ms (v0.3.114.20230130_HE)
+26ms ║╔Execution stage started
+80ms ║║Executed device command [Carriage Lights].setLevel(80) (32ms)
+83ms ║║Requesting a device command wake up at Thu, Feb 9 2023 @ 12:26:08 PM EST (in 1299ms) for 9 (st:-3 / [d::1ea55b15e1ce6d86a5f1850435698c91:, c:off, p:null, task:15])
+84ms ║║Executed virtual command [Carriage Lights].loadStateLocally (45ms)
+110ms ║║Executed device command [Chandelier].setLevel(22) (17ms)
+112ms ║║Requesting a device command wake up at Thu, Feb 9 2023 @ 12:26:08 PM EST (in 1299ms) for 9 (st:-3 / [d::11418c163410f866bebb5acb77c8711a:, c:off, p:null, task:15])
+114ms ║║Executed virtual command [Chandelier].loadStateLocally (28ms)
+140ms ║║Executed device command [Front Door].setLevel(80) (18ms)
+143ms ║║Requesting a device command wake up at Thu, Feb 9 2023 @ 12:26:08 PM EST (in 1299ms) for 9 (st:-3 / [d::82254f2796046f4c46d510b152e794ee:, c:off, p:null, task:15])
+144ms ║║Executed virtual command [Front Door].loadStateLocally (28ms)
+146ms ║║Requesting wake up at Thu, Feb 9 2023 @ 12:26:08 PM EST (in 1299ms) for 9 (st:15)
+150ms ║╚Execution stage complete. (123ms)
+197ms ║Setting up scheduled job for Thu, Feb 9 2023 @ 12:26:08 PM EST (in 1225ms),with 3 more jobs pending
+199ms ╚Event processed successfully (196ms)
2/9/2023, 12:21:07 PM +264ms
+3ms ╔Received event [Paula].presence = present with a delay of 2342ms, canQueue: true, calledMyself: false
+21ms ║Runtime (11722 bytes) initialized in 3ms (v0.3.114.20230130_HE)
+24ms ║╔Execution stage started
+82ms ║╚Execution stage complete. (58ms)
+246ms ║Setting up scheduled job for Thu, Feb 9 2023 @ 12:26:06 PM EST (in 299267ms)
+248ms ╚Event processed successfully (247ms)
2/9/2023, 12:21:06 PM +346ms
+5ms ╔Received event [Florack Hubitat].time = 1675963266121 with a delay of 225ms, canQueue: true, calledMyself: false
+19ms ║Runtime (11728 bytes) initialized in 2ms (v0.3.114.20230130_HE)
+27ms ║╔Execution stage started
+101ms ║║Executed device command [Carriage Lights].setLevel(100,0.0) (60ms)
+189ms ║║Executed device command [Chandelier].setLevel(100,0.0) (84ms)
+278ms ║║Executed device command [Front Door].setLevel(100,0.0) (84ms)
+296ms ║║The Doorbell/Arrival Lights (Carriage Lights, Chandelier and Front Door) have been activated and set to 100%.
+299ms ║║Executed virtual command [Carriage Lights, Chandelier, Front Door].log (3ms)
+305ms ║║Executed virtual command [Carriage Lights, Chandelier, Front Door].wait [300000] (0ms)
+308ms ║║Requesting wake up at Thu, Feb 9 2023 @ 12:26:06 PM EST (in 299999ms) for 9 (st:14)
+313ms ║╚Execution stage complete. (286ms)
+384ms ║Setting up scheduled job for Thu, Feb 9 2023 @ 12:26:06 PM EST (in 299987ms)
+393ms ╚Event processed successfully (389ms)
2/9/2023, 12:21:05 PM +897ms
+4ms ╔Received event [Paula].presence = present with a delay of 1618ms, canQueue: true, calledMyself: false
+20ms ║Runtime (11706 bytes) initialized in 2ms (v0.3.114.20230130_HE)
+22ms ║╔Execution stage started
+101ms ║╚Execution stage complete. (79ms)
+319ms ║Setting up scheduled job for Thu, Feb 9 2023 @ 12:21:06 PM EST (in 94ms)
+322ms ╚Event processed successfully (319ms)
2/9/2023, 12:21:04 PM +971ms
+3ms ╔Received event [Paula].presence = present with a delay of 721ms, canQueue: true, calledMyself: false
+18ms ║Runtime (11708 bytes) initialized in 3ms (v0.3.114.20230130_HE)
+21ms ║╔Execution stage started
+62ms ║║Cancelling statement #9’s schedules…9 (st:14)
+71ms ║║Could not store Carriage Lights level (99) to local store DoorbellArrivalLights::1ea55b15e1ce6d86a5f1850435698c91::level curVal: 80
+98ms ║║Could not store Carriage Lights switch (on) to local store DoorbellArrivalLights::1ea55b15e1ce6d86a5f1850435698c91::switch curVal: off
+111ms ║║Executed virtual command [Carriage Lights].saveStateLocally (42ms)
+115ms ║║Could not store Chandelier level (99) to local store DoorbellArrivalLights::11418c163410f866bebb5acb77c8711a::level curVal: 22
+127ms ║║Could not store Chandelier switch (on) to local store DoorbellArrivalLights::11418c163410f866bebb5acb77c8711a::switch curVal: off
+131ms ║║Executed virtual command [Chandelier].saveStateLocally (18ms)
+135ms ║║Could not store Front Door level (99) to local store DoorbellArrivalLights::82254f2796046f4c46d510b152e794ee::level curVal: 80
+139ms ║║Could not store Front Door switch (on) to local store DoorbellArrivalLights::82254f2796046f4c46d510b152e794ee::switch curVal: off
+143ms ║║Executed virtual command [Front Door].saveStateLocally (11ms)
+149ms ║║Executed virtual command [Carriage Lights, Chandelier, Front Door].wait [1000] (0ms)
+153ms ║║Requesting wake up at Thu, Feb 9 2023 @ 12:21:06 PM EST (in 999ms) for 9 (st:11)
+157ms ║╚Execution stage complete. (137ms)
+342ms ║Setting up scheduled job for Thu, Feb 9 2023 @ 12:21:06 PM EST (in 859ms)
+345ms ╚Event processed successfully (342ms)
2/9/2023, 12:20:38 PM +680ms
+3ms ╔Received event [Lee].presence = present with a delay of 1724ms, canQueue: true, calledMyself: false
+17ms ║Runtime (11684 bytes) initialized in 3ms (v0.3.114.20230130_HE)
+20ms ║╔Execution stage started
+61ms ║╚Execution stage complete. (41ms)
+107ms ║Processing timer time = 1675963238760
+108ms ║╔Execution stage started
+320ms ║║Executed device command [Carriage Lights].setLevel(100,0.0) (188ms)
+482ms ║║Executed device command [Chandelier].setLevel(100,0.0) (158ms)
+561ms ║║Executed device command [Front Door].setLevel(100,0.0) (76ms)
+578ms ║║The Doorbell/Arrival Lights (Carriage Lights, Chandelier and Front Door) have been activated and set to 100%.
+582ms ║║Executed virtual command [Carriage Lights, Chandelier, Front Door].log (4ms)
+590ms ║║Executed virtual command [Carriage Lights, Chandelier, Front Door].wait [300000] (3ms)
+593ms ║║Requesting wake up at Thu, Feb 9 2023 @ 12:25:39 PM EST (in 299998ms) for 9 (st:14)
+598ms ║╚Execution stage complete. (490ms)
+728ms ║Setting up scheduled job for Thu, Feb 9 2023 @ 12:25:39 PM EST (in 299985ms)
+731ms ╚Event processed successfully (728ms)
2/9/2023, 12:20:37 PM +647ms
+3ms ╔Received event [Lee].presence = present with a delay of 726ms, canQueue: true, calledMyself: false
+16ms ║Runtime (11220 bytes) initialized in 3ms (v0.3.114.20230130_HE)
+18ms ║╔Execution stage started
+90ms ║║Executed virtual command [Carriage Lights].saveStateLocally (3ms)
+95ms ║║Executed virtual command [Chandelier].saveStateLocally (3ms)
+99ms ║║Executed virtual command [Front Door].saveStateLocally (3ms)
+113ms ║║Executed virtual command [Carriage Lights, Chandelier, Front Door].wait [1000] (0ms)
+115ms ║║Requesting wake up at Thu, Feb 9 2023 @ 12:20:38 PM EST (in 999ms) for 9 (st:11)
+119ms ║╚Execution stage complete. (101ms)
+403ms ║Setting up scheduled job for Thu, Feb 9 2023 @ 12:20:38 PM EST (in 835ms)
+406ms ╚Event processed successfully (404ms)

[E_Sch]

If you turn off logging, you will find it is quiet.

If you have logging medium or higher, it will tell you (for debugging purposes) that it could not write to the store.

[lflorack]

That makes sense. I appreciate your assistance and thank you for this change.