Scheduler sending task twice

[sector119]

Hello,

My task scheduled once. CreatedSchedule(id=7fc23130208e4086b685ce6bedaaeed1, time=None, cron=*/1 * * * *, cron_offset=Europe/Kyiv, task_name=billing:sync-payments, args=[], kwargs={'schema': 'aaa', 'external_source': 'bbb', 'rpc_source': 'ccc'})

redis has only one key "schedule:7fc23130208e4086b685ce6bedaaeed1"

But Task sending twice (

[2024-02-21 11:27:51,467][INFO ][run:run_scheduler:208] Startup completed.
first run - ok
[2024-02-21 11:27:51,502][INFO ][run:delayed_send:130] Sending task billing:sync-payments.

run 2 - ok
[2024-02-21 11:28:00,001][INFO ][run:delayed_send:130] Sending task billing:sync-payments.

send twice
[2024-02-21 11:29:00,001][INFO ][run:delayed_send:130] Sending task billing:sync-payments.
[2024-02-21 11:29:00,002][INFO ][run:delayed_send:130] Sending task billing:sync-payments.

send twice
[2024-02-21 11:30:00,000][INFO ][run:delayed_send:130] Sending task billing:sync-payments.
[2024-02-21 11:30:00,002][INFO ][run:delayed_send:130] Sending task billing:sync-payments.

and so on

[sector119]

It happens only with cron scheduled task that is called every minute. Maybe the source of problem is that "scheduler gathers tasks every minute" as mentioned in delayed_send function ?

No.. Got it with minutes: "*/2" too

[2024-02-21 13:40:59,625][INFO ][run:run_scheduler:208] Startup completed.
[2024-02-21 13:40:59,657][INFO ][run:delayed_send:130] Sending task billing:sync-payments.
[2024-02-21 13:42:00,003][INFO ][run:delayed_send:130] Sending task billing:sync-payments.
[2024-02-21 13:44:00,002][INFO ][run:delayed_send:130] Sending task billing:sync-payments.
[2024-02-21 13:46:00,074][INFO ][run:delayed_send:130] Sending task billing:sync-payments.
[2024-02-21 13:48:00,001][INFO ][run:delayed_send:130] Sending task billing:sync-payments.

duplicated
[2024-02-21 13:50:00,001][INFO ][run:delayed_send:130] Sending task billing:sync-payments.
[2024-02-21 13:50:00,003][INFO ][run:delayed_send:130] Sending task billing:sync-payments.

[2024-02-21 13:52:00,002][INFO ][run:delayed_send:130] Sending task billing:sync-payments.

[sector119]

Trying to debug. Putting
print("Delay: %s" % delay)
print("Delay total seconds: %s" % delay.total_seconds())
at run_scheduler_loop

I get following delays on duplicated entries

Delay: 0:00:00.000373
Delay total seconds: 0.000373

Delay: 0:00:59.997624
Delay total seconds: 59.997624

[sector119]

One more example

Next minute: 2024-02-22 14:13:00
Now: 2024-02-22 14:13:00.000299
Delay: -1 day, 23:59:59.999701
Delay total seconds: -0.000299
[2024-02-22 14:13:00,000][INFO ][run:delayed_send:130] Sending task billing:sync-payments.

Next minute: 2024-02-22 14:14:00
Now: 2024-02-22 14:13:00.001998
Delay: 0:00:59.998002
Delay total seconds: 59.998002
[2024-02-22 14:13:00,002][INFO ][run:delayed_send:130] Sending task billing:sync-payments.

[sector119]

in run_scheduler_loop function in next_minute calculation if datetime.now() = 17:22:59.55555 and we replace seconds and microseconds with 0 and add timedelta(minutes=1) we get next_minute=17:23:00
and when we calculate delay with delay = next_minute - datetime.now(), current time can be > or just a bit lower than next_minute, so we get negative delay like -0.000299 or positive like 0.000373

Don't you think that we should check delay like:

delay = (next_minute - datetime.now()).total_seconds()

if int(delay) <= 0:
    delay = 60.0

await asyncio.sleep(delay)

[rcholic]

Have same problem, did you find a solution yet? @sector119
If we cannot solve it at the scheduler level, I'm considering at a filter at the task function level.

btw: I turned off the reload mode in FastAPI, I was suspecting whether we could do something similar to issues in Flask to detect the reload process of the scheduler or worker:

if os.environ.get("WERKZEUG_RUN_MAIN") != "true":
        print(not in reloaded process')

[s3rius]

This problem should have been solved in #319.