search

agronholm / apscheduler

Task scheduling library for Python
MIT License
5.98k stars 694 forks source link

Scheduled tasks are run multiple times instead of once per-day #864

Closed nrathaus closed 6 days ago

nrathaus commented 5 months ago

Things to check first

Version

4.0.0a4

What happened?

There seems to be a major bug causing tasks (scheduled) to run more than they are scheduled, in my example one should run every 1 second, and the other once a day, after about 30seconds (I am not sure what this number caused by), the once a day task is launched (again)

Python 3.11.2

Expected

python3 tests/test_scheduler.py 
INFO:apscheduler._schedulers.sync:Scheduler started
INFO:apscheduler._schedulers.sync:Added new schedule (task=Task(id='__main__:first', func='__main__:first', job_executor='threadpool', max_running_jobs=None, misfire_grace_time=None), trigger=IntervalTrigger(days=1, start_time='2024-02-15 16:56:59.158877+00:00')); next run time at 2024-02-15 16:56:59.158877+00:00
INFO:apscheduler._schedulers.sync:Added new schedule (task=Task(id='__main__:second', func='__main__:second', job_executor='threadpool', max_running_jobs=1, misfire_grace_time=None), trigger=IntervalTrigger(seconds=1, start_time='2024-02-15 16:56:59.165256+00:00')); next run time at 2024-02-15 16:56:59.165256+00:00
count=1
second
INFO:apscheduler._schedulers.sync:Job 1238f5f5-dfa1-4332-a9ed-fede81f2eeb8 completed successfully
count=2
count=3
second
INFO:apscheduler._schedulers.sync:Job 0e7ce2ca-fd48-4930-a856-93f6799dac20 completed successfully
count=4
second
count=5
INFO:apscheduler._schedulers.sync:Job 9a7caad2-3ae4-4147-a795-557183870e58 completed successfully
count=6
second
count=7
INFO:apscheduler._schedulers.sync:Job 0ebc6795-e033-411c-90ec-3fc4e2dec105 completed successfully
count=8
second
INFO:apscheduler._schedulers.sync:Job fb04de1f-522d-4ee4-aad6-093cdedce3c6 completed successfully
count=9
count=10
second
INFO:apscheduler._schedulers.sync:Job b4e2051a-aa2c-4acc-9ad5-61c73655c0fa completed successfully
count=11
count=12
second
count=13
INFO:apscheduler._schedulers.sync:Job be7fd8f9-f7a5-47d2-9987-656618962d91 completed successfully
count=14
second
INFO:apscheduler._schedulers.sync:Job afc99076-1158-4a32-b3e7-0274aa8b7ec9 completed successfully
count=15
count=16
second
INFO:apscheduler._schedulers.sync:Job 2986d634-30a5-4280-9b49-a03455c69c84 completed successfully
count=17
count=18
second
INFO:apscheduler._schedulers.sync:Job d3543a26-c9c2-405a-9d63-926d7191c45c completed successfully
count=19
count=20
second
INFO:apscheduler._schedulers.sync:Job 750e90da-c5a6-4f77-ac93-992e7da062f5 completed successfully
count=21
count=22
second
INFO:apscheduler._schedulers.sync:Job 2a06f668-1eca-4d83-b6b7-16c9bf4f8c4f completed successfully
count=23
count=24
second
INFO:apscheduler._schedulers.sync:Job fe54aa4d-917d-4ec9-b8e7-fd142aa895d4 completed successfully
count=25
count=26
second
INFO:apscheduler._schedulers.sync:Job e17377d2-f971-4667-ba1b-e87c232cdbab completed successfully
count=27
count=28
second
INFO:apscheduler._schedulers.sync:Job e0feb499-a83c-4788-9eeb-18b69aa65c6d completed successfully
count=29
count=30
second
INFO:apscheduler._schedulers.sync:Job 0a80a32d-7472-4af8-a44d-8576e68d05bd completed successfully
count=31
count=32
second
INFO:apscheduler._schedulers.sync:Job 6c81675a-e7ef-4278-9784-7d45c467923e completed successfully
count=33
count=34
second
INFO:apscheduler._schedulers.sync:Job 32728aa8-617f-4b4a-a636-7e84ad3c9850 completed successfully
count=35
count=36
second
INFO:apscheduler._schedulers.sync:Job cfe5189b-6c06-4b08-ba03-5b9bbee4db79 completed successfully
count=37
count=38
second
INFO:apscheduler._schedulers.sync:Job 9b95e29a-8c26-41e5-990b-202460be6d9a completed successfully
count=39
count=40
second
INFO:apscheduler._schedulers.sync:Job eac01ada-c2a0-4c0e-aa0c-9628374de26a completed successfully
count=41
count=42
second
INFO:apscheduler._schedulers.sync:Job aacd996b-1fa5-41b1-9451-4222bb0edbd1 completed successfully
count=43
count=44
second
INFO:apscheduler._schedulers.sync:Job eba75d9a-a7aa-4472-8859-96898c5db8fb completed successfully
count=45
count=46
second
INFO:apscheduler._schedulers.sync:Job b9ab0045-f014-4954-bbb7-1a83d9730e3d completed successfully
count=47
count=48
second
INFO:apscheduler._schedulers.sync:Job 678f7cb8-0518-420b-b4ee-12e744a7a4cf completed successfully
count=49
count=50
second
INFO:apscheduler._schedulers.sync:Job 16f3e029-3859-4f02-a656-ac5a8eed923f completed successfully
count=51
count=52
second
INFO:apscheduler._schedulers.sync:Job 752edfa0-1569-4888-ab73-3b64ffe20c34 completed successfully
count=53
count=54
second
INFO:apscheduler._schedulers.sync:Job 31ae3f50-ed83-4af6-a9f2-fccd3cca9403 completed successfully
count=55
count=56
second
INFO:apscheduler._schedulers.sync:Job b645c8b0-f08d-4e76-96b4-a1840e440892 completed successfully
count=57
count=58
second
INFO:apscheduler._schedulers.sync:Job c3b41159-ff61-4a99-a3e5-85df0cbc702f completed successfully
count=59
count=60
second
INFO:apscheduler._schedulers.sync:Job 1aad6e9c-3632-446e-8dea-53f532d573dc completed successfully
count=61
count=62
second
INFO:apscheduler._schedulers.sync:Job 9b162e95-cde6-4202-9b86-0c7b81525473 completed successfully
count=63
count=64
second
INFO:apscheduler._schedulers.sync:Job 3cbe5d5d-2de2-46a9-a3a9-498053f95a9a completed successfully
count=65
count=66
second
INFO:apscheduler._schedulers.sync:Job d2469f65-0054-4003-b66f-888ac2231c36 completed successfully
count=67
count=68

Viewed Outcome

python3 tests/test_scheduler.py 
INFO:apscheduler._schedulers.sync:Scheduler started
INFO:apscheduler._schedulers.sync:Added new schedule (task=Task(id='__main__:first', func='__main__:first', job_executor='threadpool', max_running_jobs=None, misfire_grace_time=None), trigger=IntervalTrigger(days=1, start_time='2024-02-15 16:56:59.158877+00:00')); next run time at 2024-02-15 16:56:59.158877+00:00
INFO:apscheduler._schedulers.sync:Added new schedule (task=Task(id='__main__:second', func='__main__:second', job_executor='threadpool', max_running_jobs=1, misfire_grace_time=None), trigger=IntervalTrigger(seconds=1, start_time='2024-02-15 16:56:59.165256+00:00')); next run time at 2024-02-15 16:56:59.165256+00:00
count=1
second
INFO:apscheduler._schedulers.sync:Job 1238f5f5-dfa1-4332-a9ed-fede81f2eeb8 completed successfully
count=2
count=3
second
INFO:apscheduler._schedulers.sync:Job 0e7ce2ca-fd48-4930-a856-93f6799dac20 completed successfully
count=4
second
count=5
INFO:apscheduler._schedulers.sync:Job 9a7caad2-3ae4-4147-a795-557183870e58 completed successfully
count=6
second
count=7
INFO:apscheduler._schedulers.sync:Job 0ebc6795-e033-411c-90ec-3fc4e2dec105 completed successfully
count=8
second
INFO:apscheduler._schedulers.sync:Job fb04de1f-522d-4ee4-aad6-093cdedce3c6 completed successfully
count=9
count=10
second
INFO:apscheduler._schedulers.sync:Job b4e2051a-aa2c-4acc-9ad5-61c73655c0fa completed successfully
count=11
count=12
second
count=13
INFO:apscheduler._schedulers.sync:Job be7fd8f9-f7a5-47d2-9987-656618962d91 completed successfully
count=14
second
INFO:apscheduler._schedulers.sync:Job afc99076-1158-4a32-b3e7-0274aa8b7ec9 completed successfully
count=15
count=16
second
INFO:apscheduler._schedulers.sync:Job 2986d634-30a5-4280-9b49-a03455c69c84 completed successfully
count=17
count=18
second
INFO:apscheduler._schedulers.sync:Job d3543a26-c9c2-405a-9d63-926d7191c45c completed successfully
count=19
count=20
second
INFO:apscheduler._schedulers.sync:Job 750e90da-c5a6-4f77-ac93-992e7da062f5 completed successfully
count=21
count=22
second
INFO:apscheduler._schedulers.sync:Job 2a06f668-1eca-4d83-b6b7-16c9bf4f8c4f completed successfully
count=23
count=24
second
INFO:apscheduler._schedulers.sync:Job fe54aa4d-917d-4ec9-b8e7-fd142aa895d4 completed successfully
count=25
count=26
second
INFO:apscheduler._schedulers.sync:Job e17377d2-f971-4667-ba1b-e87c232cdbab completed successfully
count=27
count=28
second
INFO:apscheduler._schedulers.sync:Job e0feb499-a83c-4788-9eeb-18b69aa65c6d completed successfully
count=29
count=30
second
INFO:apscheduler._schedulers.sync:Job 0a80a32d-7472-4af8-a44d-8576e68d05bd completed successfully
count=31
count=32
second
INFO:apscheduler._schedulers.sync:Job 6c81675a-e7ef-4278-9784-7d45c467923e completed successfully
count=33
count=34
second
INFO:apscheduler._schedulers.sync:Job 32728aa8-617f-4b4a-a636-7e84ad3c9850 completed successfully
count=35
count=36
second
INFO:apscheduler._schedulers.sync:Job cfe5189b-6c06-4b08-ba03-5b9bbee4db79 completed successfully
count=37
count=38
second
INFO:apscheduler._schedulers.sync:Job 9b95e29a-8c26-41e5-990b-202460be6d9a completed successfully
count=39
count=40
second
INFO:apscheduler._schedulers.sync:Job eac01ada-c2a0-4c0e-aa0c-9628374de26a completed successfully
count=41
count=42
second
INFO:apscheduler._schedulers.sync:Job aacd996b-1fa5-41b1-9451-4222bb0edbd1 completed successfully
count=43
count=44
second
INFO:apscheduler._schedulers.sync:Job eba75d9a-a7aa-4472-8859-96898c5db8fb completed successfully
count=45
count=46
second
INFO:apscheduler._schedulers.sync:Job b9ab0045-f014-4954-bbb7-1a83d9730e3d completed successfully
count=47
count=48
second
INFO:apscheduler._schedulers.sync:Job 678f7cb8-0518-420b-b4ee-12e744a7a4cf completed successfully
count=49
count=50
second
INFO:apscheduler._schedulers.sync:Job 16f3e029-3859-4f02-a656-ac5a8eed923f completed successfully
count=51
count=52
second
INFO:apscheduler._schedulers.sync:Job 752edfa0-1569-4888-ab73-3b64ffe20c34 completed successfully
count=53
count=54
second
INFO:apscheduler._schedulers.sync:Job 31ae3f50-ed83-4af6-a9f2-fccd3cca9403 completed successfully
count=55
count=56
second
INFO:apscheduler._schedulers.sync:Job b645c8b0-f08d-4e76-96b4-a1840e440892 completed successfully
count=57
count=58
second
INFO:apscheduler._schedulers.sync:Job c3b41159-ff61-4a99-a3e5-85df0cbc702f completed successfully
count=59
count=60
count=1
second
INFO:apscheduler._schedulers.sync:Job 1aad6e9c-3632-446e-8dea-53f532d573dc completed successfully
count=61
count=2
count=62
second
INFO:apscheduler._schedulers.sync:Job 9b162e95-cde6-4202-9b86-0c7b81525473 completed successfully
count=3
count=63
count=4
count=64
second
INFO:apscheduler._schedulers.sync:Job 3cbe5d5d-2de2-46a9-a3a9-498053f95a9a completed successfully
count=5
count=65
count=6
count=66
second
INFO:apscheduler._schedulers.sync:Job d2469f65-0054-4003-b66f-888ac2231c36 completed successfully
count=7
count=67
count=8
count=68

How can we reproduce the bug?

#!/usr/bin/env python3
import datetime
import logging
import time

from apscheduler import Scheduler
from apscheduler.triggers.interval import IntervalTrigger

SCHEDULER = Scheduler()
logging.basicConfig(level=logging.INFO)

SCHEDULER.start_in_background()

trigger = IntervalTrigger(days=1, start_time=datetime.datetime.now())

def first():
    count = 0
    while True:
        count += 1
        print(f"{count=}")
        time.sleep(0.5)

def second():
    print("second")

SCHEDULER.add_schedule(
    first,
    trigger=trigger,
    id="first",
)

SCHEDULER.add_schedule(
    second,
    trigger=IntervalTrigger(seconds=1),
    id="second",
)
nrathaus commented 5 months ago

I don't think this bug is related to python 3.11, as I am able to recreate this also on 3.10.12

nrathaus commented 5 months ago

I think the issue is related to acquired_until value getting "freed"

nrathaus commented 5 months ago

The value of 30 seems to arrive from self.lock_expiration_delay

nrathaus commented 5 months ago

Do jobs need to finish within 30 seconds?

agronholm commented 5 months ago

This is a known issue (acquired_until isn't refreshed) and should be resolved in the next alpha release.

Serjigg commented 3 months ago

I'm making an application in Django, I used apscheduler, there are two types of methods that I add to the scheduler: copying files and collecting data from these files; if I add copying files to the scheduler, the scheduler works as it should; if I also add analysis, for example, these two tasks every hour, then the execution of these methods is duplicated, reaching 10 identical tasks, coalesce=True - Does not help Please, help me.

agronholm commented 2 months ago

I'm making an application in Django, I used apscheduler, there are two types of methods that I add to the scheduler: copying files and collecting data from these files; if I add copying files to the scheduler, the scheduler works as it should; if I also add analysis, for example, these two tasks every hour, then the execution of these methods is duplicated, reaching 10 identical tasks, coalesce=True - Does not help Please, help me.

If you feel that your issue is separate from this, I think you should create a new ticket with instructions on how to reproduce (without Django).

agronholm commented 1 week ago

Right, I haven't actually fixed this quite yet, but laid the groundwork for the fix. I'll close this again when the real fix is in place.

Serjigg commented 1 week ago

https://github.com/agronholm/apscheduler/issues/864#issuecomment-2105663654 thanks for the reply, the problem was not apscheduler, sorry for the inconvenience, the problem was with the server apache2 had to be run in deamon mode.

agronholm commented 6 days ago

I've just pushed a commit which should eliminate the problem of other schedulers acquiring or cleaning up schedules or jobs belonging to a running scheduler.