using SQLAlchemyDataStore not execute

wuyuhang409 commented 11 months ago

Things to check first

[X] I have checked that my issue does not already have a solution in the FAQ
[X] I have searched the existing issues and didn't find my bug already reported there
[X] I have checked that my bug is still present in the latest release

Version

4.0.0a3

What happened?

I do not understand English. The following content is translated by Google. Please forgive me

When I executed this code, I found that I couldn't print the content of the tick method. After debugging, I found that there was a looping sleep bug due to the current time exceeding the next execution time. It should have automatically updated this field

This issue does not exist when I use MemoryDataStore

this code is examples/web/asgi_fastapi.py

"""
Example demonstrating use with the FastAPI web framework.

Requires the "postgresql" service to be running.
To install prerequisites: pip install sqlalchemy asycnpg fastapi uvicorn
To run: uvicorn asgi_fastapi:app

It should print a line on the console on a one-second interval while running a
basic web app at http://localhost:8000.
"""
from __future__ import annotations
import logging
logging.basicConfig(level=logging.DEBUG)

from datetime import datetime

from fastapi import FastAPI
from fastapi.middleware import Middleware
from fastapi.requests import Request
from fastapi.responses import PlainTextResponse, Response
from sqlalchemy.ext.asyncio import create_async_engine
from starlette.types import ASGIApp, Receive, Scope, Send

from apscheduler import AsyncScheduler
from apscheduler.datastores.sqlalchemy import SQLAlchemyDataStore
from apscheduler.eventbrokers.asyncpg import AsyncpgEventBroker
from apscheduler.triggers.interval import IntervalTrigger

def tick():
    print("Hello, the time is", datetime.now())

class SchedulerMiddleware:
    def __init__(
            self,
            app: ASGIApp,
            scheduler: AsyncScheduler,
    ) -> None:
        self.app = app
        self.scheduler = scheduler

    async def __call__(self, scope: Scope, receive: Receive, send: Send) -> None:
        if scope["type"] == "lifespan":
            async with self.scheduler:
                await self.scheduler.add_schedule(
                    tick, IntervalTrigger(seconds=1), id="tick"
                )
                await self.scheduler.start_in_background()
                await self.app(scope, receive, send)
        else:
            await self.app(scope, receive, send)

async def root(request: Request) -> Response:
    return PlainTextResponse("Hello, world!")

engine = create_async_engine("mysql+asyncmy://root:123456@localhost/pydep-db?charset=utf8mb4")
data_store = SQLAlchemyDataStore(engine)
scheduler = AsyncScheduler(data_store)
middleware = [Middleware(SchedulerMiddleware, scheduler=scheduler)]
app = FastAPI(middleware=middleware)
app.add_api_route("/", root)

if __name__ == '__main__':
    import uvicorn

    uvicorn.run(app, port=8004)

Log

DEBUG:asyncio:Using proactor: IocpProactor
INFO:     Started server process [16104]
INFO:     Waiting for application startup.
DEBUG:tzlocal:Looking up time zone info from registry
INFO:apscheduler._schedulers.async_:Added new schedule (task=Task(id='__main__:tick', func=<function tick at 0x000001D2B04BB130>, executor='async', max_running_jobs=None, misfire_grace_time=None, state=None), trigger=IntervalTrigger(seconds=1, start_time='2023-10-24 15:13:35.673591+08:00')); next run time at 2023-10-24 15:13:35.673591+08:00
INFO:apscheduler._schedulers.async_:Scheduler started
INFO:     Application startup complete.
INFO:     Uvicorn running on http://127.0.0.1:8004 (Press CTRL+C to quit)
DEBUG:apscheduler._schedulers.async_:Sleeping -0.133 seconds until the next fire time (2023-10-24 15:13:35.673591+08:00)
DEBUG:apscheduler._schedulers.async_:Sleeping -0.140 seconds until the next fire time (2023-10-24 15:13:35.673591+08:00)
DEBUG:apscheduler._schedulers.async_:Sleeping -0.148 seconds until the next fire time (2023-10-24 15:13:35.673591+08:00)
DEBUG:apscheduler._schedulers.async_:Sleeping -0.159 seconds until the next fire time (2023-10-24 15:13:35.673591+08:00)
DEBUG:apscheduler._schedulers.async_:Sleeping -0.169 seconds until the next fire time (2023-10-24 15:13:35.673591+08:00)
DEBUG:apscheduler._schedulers.async_:Sleeping -0.177 seconds until the next fire time (2023-10-24 15:13:35.673591+08:00)
DEBUG:apscheduler._schedulers.async_:Sleeping -0.186 seconds until the next fire time (2023-10-24 15:13:35.673591+08:00)
DEBUG:apscheduler._schedulers.async_:Sleeping -0.193 seconds until the next fire time (2023-10-24 15:13:35.673591+08:00)
DEBUG:apscheduler._schedulers.async_:Sleeping -0.201 seconds until the next fire time (2023-10-24 15:13:35.673591+08:00)
DEBUG:apscheduler._schedulers.async_:Sleeping -0.213 seconds until the next fire time (2023-10-24 15:13:35.673591+08:00)
DEBUG:apscheduler._schedulers.async_:Sleeping -0.224 seconds until the next fire time (2023-10-24 15:13:35.673591+08:00)
DEBUG:apscheduler._schedulers.async_:Sleeping -0.235 seconds until the next fire time (2023-10-24 15:13:35.673591+08:00)
DEBUG:apscheduler._schedulers.async_:Sleeping -0.242 seconds until the next fire time (2023-10-24 15:13:35.673591+08:00)
DEBUG:apscheduler._schedulers.async_:Sleeping -0.250 seconds until the next fire time (2023-10-24 15:13:35.673591+08:00)
DEBUG:apscheduler._schedulers.async_:Sleeping -0.258 seconds until the next fire time (2023-10-24 15:13:35.673591+08:00)
DEBUG:apscheduler._schedulers.async_:Sleeping -0.265 seconds until the next fire time (2023-10-24 15:13:35.673591+08:00)
DEBUG:apscheduler._schedulers.async_:Sleeping -0.272 seconds until the next fire time (2023-10-24 15:13:35.673591+08:00)
DEBUG:apscheduler._schedulers.async_:Sleeping -0.281 seconds until the next fire time (2023-10-24 15:13:35.673591+08:00)
....

How can we reproduce the bug?

asyncmy==0.2.8 SQLAlchemy==2.0.19 uvicorn==0.23.2

agronholm commented 11 months ago

I haven't run the code yet, but I think this relates to a problem I discovered last weekend where the resolution of the interval type fields was insufficient on MySQL. It's not a problem on sqlite or PostgreSQL. I have a fix locally which I will push this week, and it will be part of the next release.

agronholm commented 11 months ago

On another note, I suggest switching to PostgreSQL if you possibly can.

wuyuhang409 commented 11 months ago

You're right, there's no such issue in PostgreSQL. Currently, I'm using peewee-async, and I see a significant gap in benchmark testing between asyncpg and aiopg. Perhaps I should consider migrating from peewee to sqlalchemy

nuno-andre commented 11 months ago

FWIW: I've found a similar error that it resolved setting the env var TZ=UTC.

Also, if I set this through os.environ['TZ'] = 'UTC', instead of checking the fire time every few miliseconds, sets the next fire time for one hour from now (I'm at UTC+01:00).

agronholm commented 10 months ago

I've pushed a number of fixes for MySQL and SQLite. Please try again against the current master.

EDIT: These fixes are in v4.0.0a4 too.

agronholm / apscheduler