Missed jobs although misfire_grace_time is set

[maxnoe]

Using the apscheduler together with an sqlite datebase and a daily cron at 11:00 I get missed run times by 1 or two minutes although I set the misfire gracetime to 15 Minutes:

self.scheduler = BackgroundScheduler(
    logger=log,
    jobstores={'sqlite': SQLAlchemyJobStore(url='sqlite:///clients.sqlite'    )},
    misfire_grace_time=15*60, 
)

Run time of job "send_menu (trigger: cron[day_of_week='mon-fri', hour='11'], next run 
at: 2016-05-31 11:00:00 CEST)" was missed by 0:00:01.51075
Run time of job "send_menu (trigger: cron[day_of_week='mon-fri', hour='11'], next run 
at: 2016-05-31 11:00:00 CEST)" was missed by 0:00:01.562219
...

[agronholm]

You're right – the global value isn't being applied! I will look into this ASAP.

[agronholm]

As a workaround, give the misfire grace time value to each job individually. That at least works.

[agronholm]

Ah, this is not a bug but a user error. The misfire_grace_time setting must be passed in the job_defaults argument, like so:

self.scheduler = BackgroundScheduler(
    logger=log,
    jobstores={'sqlite': SQLAlchemyJobStore(url='sqlite:///clients.sqlite'    )},
    job_defaults={'misfire_grace_time': 15*60},
)

[maxnoe]

Ah, I understand. Thanks for the fast reply. But shouldn't then BackgroundScheduler.__init__ complain about an unused or unkown keyword argument? This would be really helpful.

[maxnoe]

Oh, and also the message that is generated on the miss seems to be a print not a log.

[agronholm]

Yes, the configuration system was initially thought out differently. I intend to replace it in the next major version with something simpler.

[agronholm]

Wait, what? No, logger.warning() is used to emit the message.

[maxnoe]

Strange, my logger instance has a FileHandler and a StreamHandler and the message is not in the logfile.

[agronholm]

Are you using a process pool executor?

[maxnoe]

I use it like I posted, which should be threading, right?

[agronholm]

Right. But there is no print anywhere as you can see: https://github.com/agronholm/apscheduler/blob/master/apscheduler/executors/base.py#L120

[agronholm]

Can I see your logging configuration?

[maxnoe]

log = logging.getLogger('mensabot')
log.setLevel(logging.INFO)
formatter = logging.Formatter(
    fmt='%(asctime)s|%(levelname)s|%(name)s|%(message)s',
    datefmt='%Y-%m-%d %H:%M:%S',
)
stream_handler = logging.StreamHandler()
file_handler = logging.FileHandler('mensabot.log', encoding='utf-8')
stream_handler.setFormatter(formatter)
file_handler.setFormatter(formatter)
log.addHandler(stream_handler)
log.addHandler(file_handler)

[agronholm]

You're only configuring logging for the "mensabot" logger. There is no configuration here that would match "apscheduler".

[maxnoe]

I thought passing the logger instance to BackgroundScheduler would make it use that logger. Why else should I pass a logger to the scheduler instance?

From the docs:

Parameters:

• logger (str|logging.Logger) – logger to use for the scheduler’s logging (defaults to apscheduler.scheduler)

[agronholm]

Ah, sorry again. Multitasking is clearly not doing me any good :(
I wonder if run_job() is being passed the correct logger name. If not, that's on me.

[agronholm]

Got it. The logger parameter only affects scheduler logging, not executor logging. Those are still logged to apscheduler.executors.

[agronholm]

But if I make the executors share the logger now, it will break things for people who expect this :(

[maxnoe]

Can I somehow set the logger of the executor?

[agronholm]

Yes, it's the _logger attribute of the executor.