Here’s the log. I removed the Aurora’s “physical commands” to help with clarity.
The first execution of the script turns on the light, and then there are 3 more execution for some reason.
As a side note, I messed up the “async” part of the Aurora flashing. The flashing on/off happens all at once (instead of spread out at 500ms on/offs). I intended for the “async” to happen so that the Aurora to begin flashing at the same time as the outdoor lights coming on, so I think I need to structure the groups of actions differently.
Anyway, here are the logs:
10/24/2017, 7:05:04 AM +64ms
+1ms ╔Received event [Home].time = 1508850304745 with a delay of -681ms
+106ms ║RunTime Analysis CS > 14ms > PS > 48ms > PE > 44ms > CE
+117ms ║Runtime (38130 bytes) successfully initialized in 48ms (v0.2.0fa.20171011) (116ms)
+118ms ║╔Execution stage started
+130ms ║╚Execution stage complete. (11ms)
+131ms ║Setting up scheduled job for Tue, Oct 24 2017 @ 6:35:00 PM (in 41395.805s)
+148ms ╚Event processed successfully (148ms)
10/24/2017, 7:04:59 AM +83ms
+1ms ╔Received event [Home].time = 1508850300000 with a delay of -917ms
+106ms ║RunTime Analysis CS > 21ms > PS > 47ms > PE > 38ms > CE
+122ms ║Runtime (38125 bytes) successfully initialized in 47ms (v0.2.0fa.20171011) (120ms)
+123ms ║╔Execution stage started
+129ms ║║Cancelling statement #9's schedules...
+560ms ║║Executed virtual command [Aurora].flash (425ms)
+562ms ║║Requesting a wake up for Tue, Oct 24 2017 @ 7:05:04 AM (in 5.1s)
+589ms ║║Comparison (time) 25499649 is_between (time) 1508890800000 .. (time) 1508851200000 = false (6ms)
+590ms ║║Cancelling condition #11's schedules...
+591ms ║║Condition #11 evaluated false (25ms)
+592ms ║║Cancelling statement #11's schedules...
+599ms ║║Requesting time schedule wake up at Tue, Oct 24 2017 @ 6:35:00 PM
+601ms ║║Cancelling condition #6's schedules...
+602ms ║║Condition group #6 evaluated false (state changed) (37ms)
+605ms ║╚Execution stage complete. (483ms)
+607ms ║Setting up scheduled job for Tue, Oct 24 2017 @ 7:05:04 AM (in 5.056s), with 1 more job pending
+734ms ╚Event processed successfully (733ms)
10/24/2017, 7:04:05 AM +199ms
+1ms ╔Received event [Home].time = 1508850245049 with a delay of 149ms
+102ms ║RunTime Analysis CS > 15ms > PS > 56ms > PE > 32ms > CE
+113ms ║Runtime (38124 bytes) successfully initialized in 56ms (v0.2.0fa.20171011) (110ms)
+113ms ║╔Execution stage started
+123ms ║╚Execution stage complete. (10ms)
+125ms ║Setting up scheduled job for Tue, Oct 24 2017 @ 7:05:00 AM (in 54.677s), with 1 more job pending
+139ms ╚Event processed successfully (139ms)
10/24/2017, 7:03:59 AM +288ms
+1ms ╔Received event [Home].time = 1508850240000 with a delay of -712ms
+199ms ║RunTime Analysis CS > 20ms > PS > 140ms > PE > 38ms > CE
+212ms ║Runtime (38127 bytes) successfully initialized in 140ms (v0.2.0fa.20171011) (210ms)
+213ms ║╔Execution stage started
+219ms ║║Cancelling statement #9's schedules...
+659ms ║║Executed virtual command [Aurora].flash (435ms)
+660ms ║║Requesting a wake up for Tue, Oct 24 2017 @ 7:04:05 AM (in 5.1s)
+689ms ║║Comparison (time) 25439952 is_between (time) 1508890800000 .. (time) 1508851200000 = true (6ms)
+690ms ║║Time restriction check passed
+691ms ║║Condition #11 evaluated true (27ms)
+692ms ║║Cancelling statement #11's schedules...
+698ms ║║Requesting time schedule wake up at Tue, Oct 24 2017 @ 7:05:00 AM
+703ms ║║Comparison (string) :291234…aaf9: is_not (string) :f4abcd…5542: = true (1ms)
+705ms ║║Condition #14 evaluated true (4ms)
+706ms ║║Condition group #6 evaluated true (state did not change) (41ms)
+708ms ║║Cancelling statement #7's schedules...
+735ms ║║Executed physical command [Outdoor Lights].on() (24ms)
+735ms ║║Executed [Outdoor Lights].on (25ms)
+738ms ║║Executed virtual command [Outdoor Lights].wait (0ms)
+739ms ║║Requesting a wake up for Tue, Oct 24 2017 @ 7:07:00 AM (in 180.0s)
+744ms ║╚Execution stage complete. (531ms)
+746ms ║Setting up scheduled job for Tue, Oct 24 2017 @ 7:04:05 AM (in 5.016s), with 2 more jobs pending
+931ms ╚Event processed successfully (930ms)