bug(command): scheduler:stop-worker not stopping when wait and force arguments present

ToshY commented 1 year ago

Situation

Testing with my own setup as described in Issue 295, the newly added scheduler:stop-worker command does not seem to have any effect on actually stopping the worker when the scheduler:consume command is being run with the --wait and --force arguments.

Version: 0.10.0

Guikingone commented 1 year ago

Hi @ToshY 👋🏻

Sorry for the bug, it seems that the listener does not listen when the worker is sleeping, I'm currently working on a fix 🙂

Guikingone commented 1 year ago

Hi @ToshY 👋🏻

It seems to be fixed via dev-issue/305, could you test if it fix your local environment, it fix mine but I prefer to ask for more tests if you have time 🙂

ToshY commented 1 year ago

Hey @Guikingone

Sure. I have time to test it this weekend, so I will report back here with my findings then 😉

ToshY commented 1 year ago

Hey @Guikingone

Let me first start off with saying that it stops the container, so that works 👍

I spinned up a container with --wait --force -vv, and after a couple of minutes I issued the scheduler:stop-worker command:

Service schedule is running; Stopping workers...

 [OK] The worker will be stopped after the current task

After X seconds the container has stopped, and in the logging of the container I see the following info messages:

schedule-1  | 2022-11-26T15:58:34.251903651Z
schedule-1  | 2022-11-26T15:58:34.254713533Z  ! [NOTE] The worker will wait for tasks every minutes
schedule-1  | 2022-11-26T15:58:34.254733610Z
schedule-1  | 2022-11-26T15:58:34.254987788Z  // Quit the worker with CONTROL-C.
schedule-1  | 2022-11-26T15:58:34.254995613Z
schedule-1  | 2022-11-26T15:58:34.255470937Z [2022-11-26T16:58:34.255007+01:00] app.INFO: The worker has been started {"failedTasks":0,"lastExecutedTask":null}
schedule-1  | 2022-11-26T15:58:34.256529116Z  [INFO] The worker is currently sleeping during 26 seconds
schedule-1  | 2022-11-26T15:58:34.256537161Z
schedule-1  | 2022-11-26T15:59:00.256863726Z [2022-11-26T16:59:00.256521+01:00] app.INFO: The worker has been started {"failedTasks":0,"lastExecutedTask":null}
schedule-1  | 2022-11-26T15:59:00.258168508Z  [INFO] The worker is currently sleeping during 60 seconds
schedule-1  | 2022-11-26T15:59:00.258200509Z
schedule-1  | 2022-11-26T16:00:00.258785379Z [2022-11-26T17:00:00.258442+01:00] app.INFO: The worker has been started {"failedTasks":0,"lastExecutedTask":null}
schedule-1  | 2022-11-26T16:00:00.259916288Z  [INFO] The worker is currently sleeping during 60 seconds
schedule-1  | 2022-11-26T16:00:00.259947656Z
schedule-1  | 2022-11-26T16:01:00.260861841Z [2022-11-26T17:01:00.260523+01:00] app.INFO: The worker has been started {"failedTasks":0,"lastExecutedTask":null}
schedule-1  | 2022-11-26T16:01:00.261544222Z  [INFO] The worker is currently sleeping during 60 seconds
schedule-1  | 2022-11-26T16:01:00.261585589Z
schedule-1  | 2022-11-26T16:02:00.261950119Z [2022-11-26T17:02:00.261678+01:00] app.INFO: The worker has been started {"failedTasks":0,"lastExecutedTask":null}
schedule-1  | 2022-11-26T16:02:00.262980799Z  [INFO] The worker is currently sleeping during 60 seconds
schedule-1  | 2022-11-26T16:02:00.263011055Z
schedule-1  | 2022-11-26T16:03:00.263996263Z [2022-11-26T17:03:00.263646+01:00] app.INFO: The worker has been started {"failedTasks":0,"lastExecutedTask":null}
schedule-1  | 2022-11-26T16:03:00.265078360Z [2022-11-26T17:03:00.264721+01:00] app.INFO: Worker will be stopped []
schedule-1  | 2022-11-26T16:03:00.265243317Z [2022-11-26T17:03:00.265120+01:00] app.INFO: The worker has been stopped {"failedTasks":0,"lastExecutedTask":null}
schedule-1  | 2022-11-26T16:03:00.265569261Z [2022-11-26T17:03:00.265188+01:00] app.INFO: The worker has been stopped {"failedTasks":0,"lastExecutedTask":null}
schedule-1  | 2022-11-26T16:03:00.265580622Z [2022-11-26T17:03:00.265262+01:00] app.INFO: The worker has been stopped {"failedTasks":0,"lastExecutedTask":null}
schedule-1  | 2022-11-26T16:03:00.265584349Z [2022-11-26T17:03:00.265315+01:00] app.INFO: The worker has been stopped {"failedTasks":0,"lastExecutedTask":null}
schedule-1  | 2022-11-26T16:03:00.266037800Z [2022-11-26T17:03:00.265353+01:00] app.INFO: The worker has been stopped {"failedTasks":0,"lastExecutedTask":null}
schedule-1  | 2022-11-26T16:03:00.266051125Z [2022-11-26T17:03:00.265449+01:00] app.INFO: The worker has been stopped {"failedTasks":0,"lastExecutedTask":null}

Now I have several questions regarding my findings above:

The message The worker will be stopped after the current task after issueing the stop command may be somewhat confusing (atleast for me), as the worker seems to actually sleep for X (max. 60) seconds before executing the next task and immediatly stopping. My point being that it doesn't actually stop after executing the "current" task.
- Subquestion: Is there also not a possibility to stop the worker while it's sleeping?
  - If no: Maybe either rephrasing or documenting this behaviour that it actually sleeps and stops before it starts the next task? Or is the sleep time configurable (using tasks of type command defined in yaml config)?
- Bit of a nitpick, but for consistency reasons maybe change the message Worker will be stopped to The worker will be stopped?
Why does the message The worker has been stopped show 6 times here?
- If I stop it immediatly after upping the container, I see the following:

schedule-1  | 2022-11-26T16:05:16.122963723Z
schedule-1  | 2022-11-26T16:05:16.125458273Z  ! [NOTE] The worker will wait for tasks every minutes
schedule-1  | 2022-11-26T16:05:16.125478781Z
schedule-1  | 2022-11-26T16:05:16.125480985Z  // Quit the worker with CONTROL-C.
schedule-1  | 2022-11-26T16:05:16.125482999Z
schedule-1  | 2022-11-26T16:05:16.126107020Z [2022-11-26T17:05:16.125789+01:00] app.INFO: The worker has been started {"failedTasks":0,"lastExecutedTask":null}
schedule-1  | 2022-11-26T16:05:16.127290985Z  [INFO] The worker is currently sleeping during 44 seconds
schedule-1  | 2022-11-26T16:05:16.127301915Z
schedule-1  | 2022-11-26T16:06:00.128208697Z [2022-11-26T17:06:00.127734+01:00] app.INFO: The worker has been started {"failedTasks":0,"lastExecutedTask":null}
schedule-1  | 2022-11-26T16:06:00.129138459Z [2022-11-26T17:06:00.128474+01:00] app.INFO: Worker will be stopped []
schedule-1  | 2022-11-26T16:06:00.129725211Z [2022-11-26T17:06:00.129395+01:00] app.INFO: The worker has been stopped {"failedTasks":0,"lastExecutedTask":null}
schedule-1  | 2022-11-26T16:06:00.129759375Z [2022-11-26T17:06:00.129462+01:00] app.INFO: The worker has been stopped {"failedTasks":0,"lastExecutedTask":null}

So now it only shows the message 2 times. Conclusion: the stopped worker message shows the same amount of times as the the amount of times the worker ran tasks. While this is "managable" if it only ran a couple of inutes, you can imagine this running for a day and then stopping the worker to see 1440 of these info messages. Not really desirable 🙃

Guikingone commented 1 year ago

Hi @ToshY 👋🏻

Thanks for the feedback.

The message The worker will be stopped after the current task after issueing the stop command may be somewhat confusing (atleast for me), as the worker seems to actually sleep for X (max. 60) seconds before executing the next task and immediatly stopping. My point being that it doesn't actually stop after executing the "current" task.

Yes, agree, I renamed it to The worker will be stopped after executing the current task or once the sleep phase is over.

Subquestion: Is there also not a possibility to stop the worker while it's sleeping?

Actually, no, I mean, not using the current state of the worker logic, we're using the sleep function and it cannot be reverted during the usage of the method, I have some ideas to improve this but its out of the scope of the current PR.

If no: Maybe either rephrasing or documenting this behaviour that it actually sleeps and stops before it starts the next task? Or is the sleep time configurable (using tasks of type command defined in yaml config)?

The sleep time is based on the following formula:

(current minute + 1 minute) - (current minute + 1)

It cannot be configured outside of the worker, I mean, not for now but I'm open to suggestions to improve it, I agree on the wording that is not adapted, working on a better one.

Bit of a nitpick, but for consistency reasons maybe change the message Worker will be stopped to The worker will be stopped?

Agree.

Why does the message The worker has been stopped show 6 times here?

Need to investigate this one 🙂

Guikingone / SchedulerBundle

bug(command): scheduler:stop-worker not stopping when wait and force arguments present #305