Scheduler key doesn't work

[Vitalii Solodilov]

Key should squash delayed calls but it doesn't. We can see on action_execution_checker example.

2018-06-08 18:00:12.739 23 DEBUG mistral.services.scheduler [req-a8305106-b9e5-41f2-b28c-9cbe128b2645 - - - - -] Scheduler captured 8 delayed calls. _capture_calls /opt/stack/mistral/mistral/services/scheduler.py:205
2018-06-08 18:00:12.740 23 DEBUG mistral.services.scheduler [req-a8305106-b9e5-41f2-b28c-9cbe128b2645 - - - - -] Preparing next delayed call. [ID=ea737f54-95f0-4d4b-98c8-c3ef2ec54905, factory_method_path=None, target_method_name=mistral.services.action_execution_checker.handle_expired_actions, method_arguments={}] _prepare_calls /opt/stack/mistral/mistral/services/scheduler.py:229
2018-06-08 18:00:12.740 23 DEBUG mistral.services.scheduler [req-a8305106-b9e5-41f2-b28c-9cbe128b2645 - - - - -] Preparing next delayed call. [ID=c3a25445-1d27-4254-8a34-0a27bf1d5cbb, factory_method_path=None, target_method_name=mistral.services.action_execution_checker.handle_expired_actions, method_arguments={}] _prepare_calls /opt/stack/mistral/mistral/services/scheduler.py:229
2018-06-08 18:00:12.741 23 DEBUG mistral.services.scheduler [req-a8305106-b9e5-41f2-b28c-9cbe128b2645 - - - - -] Preparing next delayed call. [ID=e2b1e263-1d1f-46ea-9c6f-8c96babb17ee, factory_method_path=None, target_method_name=mistral.services.action_execution_checker.handle_expired_actions, method_arguments={}] _prepare_calls /opt/stack/mistral/mistral/services/scheduler.py:229
2018-06-08 18:00:12.742 23 DEBUG mistral.services.scheduler [req-a8305106-b9e5-41f2-b28c-9cbe128b2645 - - - - -] Preparing next delayed call. [ID=f7f45ba7-af16-4cdd-af1e-a32239eb6536, factory_method_path=None, target_method_name=mistral.services.action_execution_checker.handle_expired_actions, method_arguments={}] _prepare_calls /opt/stack/mistral/mistral/services/scheduler.py:229
2018-06-08 18:00:12.742 23 DEBUG mistral.services.scheduler [req-a8305106-b9e5-41f2-b28c-9cbe128b2645 - - - - -] Preparing next delayed call. [ID=c9931f5d-db16-491c-ace0-419c25554462, factory_method_path=None, target_method_name=mistral.services.action_execution_checker.handle_expired_actions, method_arguments={}] _prepare_calls /opt/stack/mistral/mistral/services/scheduler.py:229
2018-06-08 18:00:12.743 23 DEBUG mistral.services.scheduler [req-a8305106-b9e5-41f2-b28c-9cbe128b2645 - - - - -] Preparing next delayed call. [ID=04394cdf-cfcd-4a88-befa-9a7e78329258, factory_method_path=None, target_method_name=mistral.services.action_execution_checker.handle_expired_actions, method_arguments={}] _prepare_calls /opt/stack/mistral/mistral/services/scheduler.py:229
2018-06-08 18:00:12.743 23 DEBUG mistral.services.scheduler [req-a8305106-b9e5-41f2-b28c-9cbe128b2645 - - - - -] Preparing next delayed call. [ID=646d6cd8-593e-4c78-ac52-1c1f65f10a87, factory_method_path=None, target_method_name=mistral.services.action_execution_checker.handle_expired_actions, method_arguments={}] _prepare_calls /opt/stack/mistral/mistral/services/scheduler.py:229
2018-06-08 18:00:12.744 23 DEBUG mistral.services.scheduler [req-a8305106-b9e5-41f2-b28c-9cbe128b2645 - - - - -] Preparing next delayed call. [ID=122d095c-1639-4381-9d58-bfa64b44ffb2, factory_method_path=None, target_method_name=mistral.services.action_execution_checker.handle_expired_actions, method_arguments={}] _prepare_calls /opt/stack/mistral/mistral/services/scheduler.py:229
2018-06-08 18:00:12.745 23 DEBUG mistral.services.action_execution_checker [req-a8305106-b9e5-41f2-b28c-9cbe128b2645 - - - - -] Running heartbeat checker... handle_expired_actions /opt/stack/mistral/mistral/services/action_execution_checker.py:35
2018-06-08 18:00:12.748 23 DEBUG mistral.services.action_execution_checker [req-a8305106-b9e5-41f2-b28c-9cbe128b2645 - - - - -] Found 0 running and expired actions. handle_expired_actions /opt/stack/mistral/mistral/services/action_execution_checker.py:47
2018-06-08 18:00:12.754 23 DEBUG mistral.services.action_execution_checker [req-a8305106-b9e5-41f2-b28c-9cbe128b2645 - - - - -] Running heartbeat checker... handle_expired_actions /opt/stack/mistral/mistral/services/action_execution_checker.py:35
2018-06-08 18:00:12.757 23 DEBUG mistral.services.action_execution_checker [req-a8305106-b9e5-41f2-b28c-9cbe128b2645 - - - - -] Found 0 running and expired actions. handle_expired_actions /opt/stack/mistral/mistral/services/action_execution_checker.py:47
2018-06-08 18:00:12.763 23 DEBUG mistral.services.action_execution_checker [req-a8305106-b9e5-41f2-b28c-9cbe128b2645 - - - - -] Running heartbeat checker... handle_expired_actions /opt/stack/mistral/mistral/services/action_execution_checker.py:35
2018-06-08 18:00:12.765 23 DEBUG mistral.services.action_execution_checker [req-a8305106-b9e5-41f2-b28c-9cbe128b2645 - - - - -] Found 0 running and expired actions. handle_expired_actions /opt/stack/mistral/mistral/services/action_execution_checker.py:47
2018-06-08 18:00:12.771 23 DEBUG mistral.services.action_execution_checker [req-a8305106-b9e5-41f2-b28c-9cbe128b2645 - - - - -] Running heartbeat checker... handle_expired_actions /opt/stack/mistral/mistral/services/action_execution_checker.py:35
2018-06-08 18:00:12.773 23 DEBUG mistral.services.action_execution_checker [req-a8305106-b9e5-41f2-b28c-9cbe128b2645 - - - - -] Found 0 running and expired actions. handle_expired_actions /opt/stack/mistral/mistral/services/action_execution_checker.py:47
2018-06-08 18:00:12.779 23 DEBUG mistral.services.action_execution_checker [req-a8305106-b9e5-41f2-b28c-9cbe128b2645 - - - - -] Running heartbeat checker... handle_expired_actions /opt/stack/mistral/mistral/services/action_execution_checker.py:35
2018-06-08 18:00:12.782 23 DEBUG mistral.services.action_execution_checker [req-a8305106-b9e5-41f2-b28c-9cbe128b2645 - - - - -] Found 0 running and expired actions. handle_expired_actions /opt/stack/mistral/mistral/services/action_execution_checker.py:47
2018-06-08 18:00:12.788 23 DEBUG mistral.services.action_execution_checker [req-a8305106-b9e5-41f2-b28c-9cbe128b2645 - - - - -] Running heartbeat checker... handle_expired_actions /opt/stack/mistral/mistral/services/action_execution_checker.py:35
2018-06-08 18:00:12.791 23 DEBUG mistral.services.action_execution_checker [req-a8305106-b9e5-41f2-b28c-9cbe128b2645 - - - - -] Found 0 running and expired actions. handle_expired_actions /opt/stack/mistral/mistral/services/action_execution_checker.py:47
2018-06-08 18:00:12.797 23 DEBUG mistral.services.action_execution_checker [req-a8305106-b9e5-41f2-b28c-9cbe128b2645 - - - - -] Running heartbeat checker... handle_expired_actions /opt/stack/mistral/mistral/services/action_execution_checker.py:35
2018-06-08 18:00:12.801 23 DEBUG mistral.services.action_execution_checker [req-a8305106-b9e5-41f2-b28c-9cbe128b2645 - - - - -] Found 0 running and expired actions. handle_expired_actions /opt/stack/mistral/mistral/services/action_execution_checker.py:47
2018-06-08 18:00:12.806 23 DEBUG mistral.services.action_execution_checker [req-a8305106-b9e5-41f2-b28c-9cbe128b2645 - - - - -] Running heartbeat checker... handle_expired_actions /opt/stack/mistral/mistral/services/action_execution_checker.py:35
2018-06-08 18:00:12.809 23 DEBUG mistral.services.action_execution_checker [req-a8305106-b9e5-41f2-b28c-9cbe128b2645 - - - - -] Found 0 running and expired actions. handle_expired_actions /opt/stack/mistral/mistral/services/action_execution_checker.py:47
2018-06-08 18:00:12.825 23 DEBUG mistral.services.scheduler [req-a8305106-b9e5-41f2-b28c-9cbe128b2645 - - - - -] Scheduler deleted 8 delayed calls. delete_calls /opt/stack/mistral/mistral/services/scheduler.py:310

[Dougal Matthews (d0ugal)]

> Key should squash delayed calls but it doesn't. We can see on action_execution_checker example.

Can you explain that a bit more? I don't fully understand this bug.

[Andras Kovi (akovi)]

@Dougal: I guess @Vitalii started several engines and all of them scheduled the heartbeat watchdog functionality. The same thing can happen for all periodic executions that build on delayed calls.

We talked about this feature with Renat and he mentioned that the implementation is not done. I saw a related issue too:

Basically for periodic calls there are several errors that can happen:
1. the new call is scheduled but the old is not deleted -> results in repeated execution
2. the new call is not scheduled and the old is deleted -> the periodic task is lost until service restart
3. the new call is not scheduled and the old is not deleted -> the old is reexecuted

With this setup Single delayed calls are executed at least once.

The issue is not just the key not working but the scheduled execution may behave unexpectedly.

[Dougal Matthews (d0ugal)]

Thanks Andras.

[Renat Akhmerov (rakhmerov)]

Squashing of delayed calls is not implemented, yes. This field is rather a legacy field that left after lots of experiments with Scheduler implementations that I did in the past. I would close this bug because I'm starting to rework Scheduler implementation almost from scratch and I'll need to take lots of things into account.

[Vitalii Solodilov (mcdoker18)]

I'd reopen this ticket. Maybe i should change the ticket name.
Because now if we start\restart a new engine replica we create a delayed call https://github.com/openstack/mistral/blob/master/mistral/services/action_execution_checker.py#L77
For example, if I restart a engine 100 times then I will have the 100 delayed calls. And my engine and database will loaded by handling these delayed calls. When only one a delayed call must be executed. https://github.com/openstack/mistral/blob/master/mistral/services/action_execution_checker.py#L34
I think this ticket should has the high importance.