automation: unreliable execution after restart

[maggu2810]

There seems to be still some race condition.
I have a system running on an RPi2B (so a very slow system).

Sometimes after a restart rules are not executed.
Other times rules are working after a restart.
So it seems to be timing related how the stuff gets activated.

Here some information:

System is up and running.
Rules are not executed.

Two rules exist:

karaf@root()> smarthome:automation listRules
----------------------------------------------------------------------------------------------------
ID     UID                                 NAME                                STATUS         
----------------------------------------------------------------------------------------------------
1      279961ca-ca2b-42c4-a522-72dda72331ee Wohnzimmer 1 - A                    IDLE           
2      e5c125f3-8e81-47d4-b96d-b5d983ea2d2a Wohnzimmer 1 - B                    IDLE           
----------------------------------------------------------------------------------------------------

The rules should be triggered by a button press and switch an energy plug.
Rule 1 for rocker 1 and energy plug 1.
Rule 2 for rocker 2 and energy plug 2.

Test press down of rocker 1

20:51:00.123 INFO [safeCall-9] my_rocker_buttonAO updated to ON
20:51:00.135 INFO [safeCall-7] my_rocker_buttonAO changed from OFF to ON
20:51:00.283 INFO [safeCall-9] my_rocker_buttonAO updated to OFF
20:51:00.295 INFO [safeCall-2] my_rocker_buttonAO changed from ON to OFF

Test press up of rocker 1

20:51:01.831 INFO [safeCall-9] my_rocker_buttonAI updated to ON
20:51:01.841 INFO [safeCall-7] my_rocker_buttonAI changed from OFF to ON
20:51:02.023 INFO [safeCall-9] my_rocker_buttonAI updated to OFF
20:51:02.030 INFO [safeCall-5] my_rocker_buttonAI changed from ON to OFF

Test press down of rocker 2

20:51:03.226 INFO [safeCall-9] my_rocker_buttonBO updated to ON
20:51:03.235 INFO [safeCall-5] my_rocker_buttonBO changed from OFF to ON
20:51:03.433 INFO [safeCall-9] my_rocker_buttonBO updated to OFF
20:51:03.442 INFO [safeCall-7] my_rocker_buttonBO changed from ON to OFF

Test press up of rocker 2

20:51:05.156 INFO [safeCall-5] my_rocker_buttonBI updated to ON
20:51:05.169 INFO [safeCall-7] my_rocker_buttonBI changed from OFF to ON
20:51:05.316 INFO [safeCall-5] my_rocker_buttonBI updated to OFF
20:51:05.328 INFO [safeCall-5] my_rocker_buttonBI changed from ON to OFF

Now let's disable the RuleRegistryImpl service for a moment:

karaf@root()> scr:disable org.eclipse.smarthome.automation.core.internal.RuleRegistryImpl
20:52:19.538 INFO [safeCall-5] Rule 'e5c125f3-8e81-47d4-b96d-b5d983ea2d2a' has been removed.
20:52:19.548 INFO [safeCall-7] Rule '279961ca-ca2b-42c4-a522-72dda72331ee' has been removed.

and let's enable it again:

karaf@root()> scr:enable org.eclipse.smarthome.automation.core.internal.RuleRegistryImpl
20:53:14.455 INFO [safeCall-12] Rule 'e5c125f3-8e81-47d4-b96d-b5d983ea2d2a' has been added.
20:53:14.466 INFO [safeCall-13] e5c125f3-8e81-47d4-b96d-b5d983ea2d2a updated: UNINITIALIZED
20:53:14.475 INFO [safeCall-12] Rule '279961ca-ca2b-42c4-a522-72dda72331ee' has been added.
20:53:14.483 INFO [safeCall-13] 279961ca-ca2b-42c4-a522-72dda72331ee updated: UNINITIALIZED
20:53:14.637 INFO [SCR Component Actor] Get storage with explicit classloader: automation_rules_disabled
20:53:14.685 INFO [safeCall-13] e5c125f3-8e81-47d4-b96d-b5d983ea2d2a updated: IDLE
20:53:14.696 INFO [safeCall-12] 279961ca-ca2b-42c4-a522-72dda72331ee updated: IDLE
20:53:15.185 INFO [safeCall-12] e5c125f3-8e81-47d4-b96d-b5d983ea2d2a updated: INITIALIZING
20:53:15.279 INFO [safeCall-12] e5c125f3-8e81-47d4-b96d-b5d983ea2d2a updated: IDLE
20:53:15.295 INFO [safeCall-13] 279961ca-ca2b-42c4-a522-72dda72331ee updated: INITIALIZING
20:53:15.349 INFO [safeCall-13] 279961ca-ca2b-42c4-a522-72dda72331ee updated: IDLE

After that all four presses trigger the rule execution and the expected result is observed:

20:53:32.558 INFO [safeCall-11] my_rocker_buttonAO updated to ON
20:53:32.565 WARN [pool-32-thread-1] Execute RULE
20:53:32.571 INFO [safeCall-5] my_rocker_buttonAO changed from OFF to ON
20:53:32.581 INFO [safeCall-7] 279961ca-ca2b-42c4-a522-72dda72331ee updated: RUNNING
20:53:32.594 INFO [safeCall-11] Item 'my_energy_plug_2_sw0' received command OFF
20:53:32.602 INFO [safeCall-5] 279961ca-ca2b-42c4-a522-72dda72331ee updated: IDLE
20:53:32.748 INFO [safeCall-12] my_rocker_buttonAO updated to OFF
20:53:32.753 WARN [pool-32-thread-1] Execute RULE
20:53:32.757 INFO [safeCall-5] my_rocker_buttonAO changed from ON to OFF
20:53:32.770 INFO [safeCall-12] 279961ca-ca2b-42c4-a522-72dda72331ee updated: RUNNING
20:53:32.775 INFO [safeCall-5] 279961ca-ca2b-42c4-a522-72dda72331ee updated: IDLE
20:53:32.794 INFO [safeCall-5] 'aleoncean:Viessmann_Energy_Plug:4fefa12e' updated: ONLINE
20:53:32.803 INFO [safeCall-12] my_energy_plug_2_sw0 updated to OFF
20:53:32.809 INFO [safeCall-11] my_energy_plug_2_sw0 changed from ON to OFF

20:53:33.949 INFO [safeCall-5] my_rocker_buttonAI updated to ON
20:53:33.958 INFO [safeCall-11] my_rocker_buttonAI changed from OFF to ON
20:53:33.960 WARN [pool-32-thread-1] Execute RULE
20:53:33.969 INFO [safeCall-5] 279961ca-ca2b-42c4-a522-72dda72331ee updated: RUNNING
20:53:33.987 INFO [safeCall-5] Item 'my_energy_plug_2_sw0' received command ON
20:53:33.997 INFO [safeCall-7] 279961ca-ca2b-42c4-a522-72dda72331ee updated: IDLE
20:53:34.111 INFO [safeCall-11] my_rocker_buttonAI updated to OFF
20:53:34.116 WARN [pool-32-thread-1] Execute RULE
20:53:34.127 INFO [safeCall-12] my_rocker_buttonAI changed from ON to OFF
20:53:34.139 INFO [safeCall-11] 279961ca-ca2b-42c4-a522-72dda72331ee updated: RUNNING
20:53:34.147 INFO [safeCall-12] 279961ca-ca2b-42c4-a522-72dda72331ee updated: IDLE
20:53:34.169 INFO [safeCall-7] 'aleoncean:Viessmann_Energy_Plug:4fefa12e' updated: ONLINE
20:53:34.180 INFO [safeCall-5] my_energy_plug_2_sw0 updated to ON
20:53:34.189 INFO [safeCall-7] my_energy_plug_2_sw0 changed from OFF to ON

20:53:35.196 INFO [safeCall-5] my_rocker_buttonBO updated to ON
20:53:35.210 WARN [pool-31-thread-1] Execute RULE
20:53:35.210 INFO [safeCall-11] my_rocker_buttonBO changed from OFF to ON
20:53:35.230 INFO [safeCall-7] e5c125f3-8e81-47d4-b96d-b5d983ea2d2a updated: RUNNING
20:53:35.247 INFO [safeCall-11] Item 'my_energy_plug_1_sw0' received command OFF
20:53:35.257 INFO [safeCall-5] e5c125f3-8e81-47d4-b96d-b5d983ea2d2a updated: IDLE
20:53:35.277 INFO [safeCall-7] my_energy_plug_1_sw0 updated to OFF
20:53:35.287 INFO [safeCall-5] my_energy_plug_1_sw0 changed from NULL to OFF
20:53:35.401 INFO [safeCall-7] my_rocker_buttonBO updated to OFF
20:53:35.408 INFO [safeCall-5] my_rocker_buttonBO changed from ON to OFF
20:53:35.411 WARN [pool-31-thread-1] Execute RULE
20:53:35.415 INFO [safeCall-7] e5c125f3-8e81-47d4-b96d-b5d983ea2d2a updated: RUNNING
20:53:35.424 INFO [safeCall-13] e5c125f3-8e81-47d4-b96d-b5d983ea2d2a updated: IDLE

20:53:36.410 INFO [safeCall-5] my_rocker_buttonBI updated to ON
20:53:36.420 WARN [pool-31-thread-1] Execute RULE
20:53:36.422 INFO [safeCall-5] my_rocker_buttonBI changed from OFF to ON
20:53:36.433 INFO [safeCall-7] e5c125f3-8e81-47d4-b96d-b5d983ea2d2a updated: RUNNING
20:53:36.441 INFO [safeCall-13] Item 'my_energy_plug_1_sw0' received command ON
20:53:36.449 INFO [safeCall-12] e5c125f3-8e81-47d4-b96d-b5d983ea2d2a updated: IDLE
20:53:36.473 INFO [safeCall-12] my_energy_plug_1_sw0 updated to ON
20:53:36.484 INFO [safeCall-5] my_energy_plug_1_sw0 changed from OFF to ON
20:53:36.552 INFO [safeCall-12] my_rocker_buttonBI updated to OFF
20:53:36.575 WARN [pool-31-thread-1] Execute RULE
20:53:36.577 INFO [safeCall-5] my_rocker_buttonBI changed from ON to OFF
20:53:36.587 INFO [safeCall-13] e5c125f3-8e81-47d4-b96d-b5d983ea2d2a updated: RUNNING
20:53:36.595 INFO [safeCall-13] e5c125f3-8e81-47d4-b96d-b5d983ea2d2a updated: IDLE

[kirantpatil]

Hi @maggu2810,

I could see lots of Automation issues pending to be resolved.

Do all those issues affect the next release 0.10.0 which is planned to release this week ie. 7th Dec ?

Thanks.

[maggu2810]

I don't think this will affect the release.

If you need some of them fixed for the release, you could provide a PR and we will see if it could be integrated.
Otherwise your fix can be integrated in the current master.

[5iver]

Possibly related/duplicate of #4324 (check the last comment)?

[maggu2810]

Hm, there should not be any script engine be involved.
The rules contains a trigger "on state update" and an action "update state".

[maggu2810]

Migrated to openhab/openhab-core#746