agronholm / apscheduler

Task scheduling library for Python
MIT License
5.94k stars 690 forks source link

Logger not logging events of the scheduler instance #895

Open franraknic opened 2 months ago

franraknic commented 2 months ago

Things to check first

Version

3.9.1

What happened?

First off, thank you very much for this library it has served me a long time on various projects!

The scheduler is instantiated & setup the scheduler like this:

scheduler = BackgroundScheduler()

aps_logger = logging.getLogger('apscheduler')
aps_logger.propagate = True
aps_logger.setLevel(logging.DEBUG)
handler = RotatingFileHandler(
    CONFIG['logging']['path'] + "reporting-aps.log", mode='a', maxBytes=5242880, backupCount=5)
handler.setLevel(logging.DEBUG)
formatter = logging.Formatter('[%(asctime)s] - %(levelname)s %(message)s')
handler.setFormatter(formatter)
aps_logger.addHandler(handler)

The script that contains the code gets executed and I get logs in the reporting-aps.log:

[2024-04-22 08:00:49,130] - INFO Scheduler started
[2024-04-22 08:00:49,133] - DEBUG Looking for jobs to run
[2024-04-22 08:00:49,177] - INFO Added job "dummyjob" to job store "default"
[2024-04-22 08:00:49,233] - DEBUG Next wakeup is due at 2024-04-22 08:00:59.134749+00:00 (in 9.996554 seconds)

The dummyjob just logs some text to a different logger and I can see that in the console where it is expected, however the reporting-aps.log never has events for job execution, not only that but it basicaly stops logging after the last line Next wakeup even though the dummy job continues to be executed. I know for a fact that the logger used to log adding, removing, executing and failed executing jobs (when a job would have an exception the log would contain something like Job failed with exception), with the same logger configuration:

[2023-10-26 12:58:23,621] Looking for jobs to run
[2023-10-26 12:58:23,895] Running job "liveReport6 (trigger: date[2023-10-26 12:58:23 CEST], next run at: 2023-10-26 12:58:23 CEST)" (scheduled at 2023-10-26 12:58:23.571559+02:00)

I have tried getting the logger with various strings apscheduler.scheduler and apscheduler.executor.default. I have also checked if the scheduler has the provided handler with scheduler._logger and everything seems right.

Can anyone please help me enable the logging that has information about executing, deleting and exceptions in the jobs?

How can we reproduce the bug?

scheduler = BackgroundScheduler()

aps_logger = logging.getLogger('apscheduler')
aps_logger.propagate = True
aps_logger.setLevel(logging.DEBUG)
handler = RotatingFileHandler("./logger.log", mode='a', maxBytes=5242880, backupCount=5)
handler.setLevel(logging.DEBUG)
formatter = logging.Formatter('[%(asctime)s] - %(levelname)s %(message)s')
handler.setFormatter(formatter)
aps_logger.addHandler(handler)

scheduler.add_jobstore('sqlalchemy', engine=engine_portal)
scheduler.start()

def dummyjob():
    console_logger = logging.getLogger('console')
    console_logger.setLevel(logging.DEBUG)
    console_logger.addHandler(logging.StreamHandler(sys.stdout))
    console_logger.info('Dummy job executed')

scheduler.add_job(dummyjob, 'interval', seconds=10, id='dummyjob')

#scheduler.remove_job('dummyjob')