Cron jobs not getting run

[dehjli85]

We're looking at using good_job to replace delayed_jobs in our app, but I'm running into issues getting the cron jobs to run. It looks like when I start up good_job, that the cron jobs get created, because I see the following in the terminal:
I, [2022-02-10T15:25:46.210058 #89389] INFO -- : GoodJob started cron with 1 job.

But when the time comes actually run the job... nothing happens. Furthermore, when I look at the good_jobs table, nothing is there. This may be a point for clarification, but I assumed that if a cron job gets scheduled, I should expect to see it in the good_jobs table with the scheduled_at column filled out with when the job is supposed to run. Does that still happen with cron jobs?

For what it's worth, if I use the rails console to run my job using the perform_later method, it adds an entry into the good_jobs table, and executes the job as I expected, so jobs not depending on cron seem to be fine. Is there something I'm missing here?

Here's my relevant application.rb code:

config.active_job.queue_adapter = :good_job
      config.good_job.enable_cron = true
      config.good_job.preserve_job_records = true

      config.good_job.cron = {
        email_every_day: {
          cron: 'every day at 9:00am',
          class: 'EmailJob',
          description: 'Test email once a day'
        }
      }

I'm running this on a Rails 5.2 app, ruby 2.7.5 if that makes any difference.

[bensheldon]

@dehjli85 Thanks for opening an issue.

Cron runs its own timer and then enqueues a job at the time it's triggered. So for your example, the job would be enqueued at 9am sharp.

To debug it, could you changing some values to run locally:

GoodJob.on_thread_error = -> (exception) { puts "GOOD_JOB ERROR: #{exception}\n #{exception.backtrace}" }

And then change the cron value to something like cron: "every 10 seconds" so it will trigger more regularly for debugging.

[dehjli85]

Ah ok, great to know. I'm gonna try this out in a little bit and report back if things look ok.

[dehjli85]

Ok, I followed your suggestions on changing the cron to run every 10 seconds, and was able to confirm that every 10 seconds a new row would appear in the table. However, when I changed it back to the every day at 9:00am cron, nothing shows up in the table even after 9:00am. I'm wondering it this is an issue with time zones or UTC? I assumed that it would look at local time on my machine, but perhaps that is a bad assumption.

Thoughts on whether time zone needs to be specified in a certain way?

[bensheldon]

@dehjli85 that's good progress. If you open up Rails console, you could debug the cron string with:

GoodJob::CronEntry.find(:email_every_day).next_at

That will give you a Time object of when it is expected to be enqueued.

[bensheldon]

btw, It looks like the timezone parsing will either use the local timezone of your Rails app, or you can give it one explicitly:

[41] pry(main)> Time.zone.to_s
=> "(GMT+00:00) UTC"
[42] pry(main)> Fugit.parse('every day at 9am').next_time.to_t
=> 2022-02-15 01:00:00 -0800
[43] pry(main)> Time.zone = "America/Los_Angeles"
=> "America/Los_Angeles"
[44] pry(main)> Fugit.parse('every day at 9am').next_time.to_t
=> 2022-02-15 09:00:00 -0800
[45] pry(main)> Fugit.parse('every day at 9am UTC').next_time.to_t
=> 2022-02-15 01:00:00 -0800
[46] pry(main)> Fugit.parse('every day at 9am America/Los_Angeles').next_time.to_t
=> 2022-02-15 09:00:00 -0800

[dehjli85]

It looks like this is a time zone issue. Something funky is definitely going on here...

If I do the following in the initializer:

config.good_job.cron = {
  email_every_day: {
    cron: 'every day at 4:30pm America/Los_Angeles',
    class: 'EmailJob',
    description: 'Test email once a day'
  }
}

This is the output I get from the CronEntry statement:
2022-02-16 04:30:00 -0800

So the timezone offset (-0800) looks right, but the hour is off. It should be 16:30:00, not 04:30:00.

The date is also a day later, (02-16) instead of (02-15). I ran this before 4:30pm PST, so the next time should have been today, not tomorrow.

For reference, in the console if I run Time.now.to_s I get "2022-02-15 16:24:57 -0800"
If I run the same cron string through the Fugit in the console, I get the same output:

Fugit.parse('every day at 4:30pm America/Los_Angeles').next_time.to_t
=> 2022-02-16 04:30:00 -0800

so maybe this is an issue with Fugit?

[bensheldon]

aha, it looks like fugit wants a space between the numbers and the pm. Do you think that's it?

[5] pry(main)> Fugit.parse('every day at 4:30 pm America/Los_Angeles').next_time.to_t
=> 2022-02-16 16:30:00 -0800

[dehjli85]

🤦‍♂️ . Yup... that looks to be it. I think we can close this issue out. I'm surprised Fugit didn't throw a parsing error, because it seems to like throwing errors for other similar types of issues.

I will say the CronEntry debugging was really helpful. Adding that to the README will probably help future users without having to open issues. I can open a PR to try to add some of the documentation if that would be helpful.

Excited to keep trying this gem out!

[bensheldon]

@dehjli85 I'd appreciate it if you could expand the Cron section of the readme. Thanks!