rails / mission_control-jobs

Dashboard and Active Job extensions to operate and troubleshoot background jobs
MIT License
625 stars 71 forks source link

In progress jobs > running since: shows time in future #215

Open ronald opened 4 days ago

ronald commented 4 days ago

Hi there, thx for the gem :smile:

I just noticed that the running since column in the in progress jobs tab shows times from the future: image (The page was loaded before 2024-11-29 16:25:12.126 CET = 2024-11-29 15:25:12.126 UTC)

So the job looks like

The job in database looks like this:

{
  "id": 210110,
  "queue_name": "default",
  "class_name": "SomeJobClass",
  "arguments": {
    "job_class": "SomeJobClass",
    "job_id": "09a81861-3c13-4bfd-b014-2d8612d755dd",
    "provider_job_id": null,
    "queue_name": "default",
    "priority": null,
    "arguments": [
      12734
    ],
    "executions": 0,
    "exception_executions": {},
    "locale": "de",
    "timezone": "Berlin",
    "enqueued_at": "2024-11-29T15:22:20.695549816Z",
    "scheduled_at": "2024-11-29T15:22:20.695433371Z"
  },
  "priority": 0,
  "active_job_id": "09a81861-3c13-4bfd-b014-2d8612d755dd",
  "scheduled_at": "2024-11-29T16:22:20.695+01:00",
  "finished_at": "2024-11-29T16:25:12.126+01:00",
  "concurrency_key": null,
  "created_at": "2024-11-29T16:22:20.696+01:00",
  "updated_at": "2024-11-29T16:25:12.126+01:00"
}
rosa commented 4 days ago

What time zone have you set for your app where you're mounting Mission Control?

ronald commented 4 days ago

application.rb

    config.time_zone = 'Berlin'
rosa commented 4 days ago

Thank you! And what do you get if you open a rails console in the server where that's running and run:

SolidQueue::ClaimedExecution.last.created_at
SolidQueue::ClaimedExecution.last.created_at.in_time_zone
Time.parse("2024-11-29T15:22:20.695549816Z")
Time.parse("2024-11-29T15:22:20.695549816Z").in_time_zone.strftime("%Y-%m-%d %H:%M:%S.%3N %Z")
ronald commented 3 days ago

Rails 7.2.2 / Ruby 3.3.6

SolidQueue::ClaimedExecution.last.created_at
SolidQueue::ClaimedExecution.last.created_at.in_time_zone
# NoMethodError: undefined method `created_at' for nil
# (will try that again with job running)

Time.parse("2024-11-29T15:22:20.695549816Z")
# => 2024-11-29 15:22:20.695549816 UTC
Time.parse("2024-11-29T15:22:20.695549816Z").in_time_zone.strftime("%Y-%m-%d %H:%M:%S.%3N %Z")
# => "2024-11-29 16:22:20.695 CET"
ronald commented 14 hours ago
SolidQueue::ClaimedExecution.last.created_at
# => Tue, 03 Dec 2024 11:52:23.402971000 CET +01:00

SolidQueue::ClaimedExecution.last.created_at.in_time_zone
# => Tue, 03 Dec 2024 11:52:23.402971000 CET +01:00

Time.current
# => Tue, 03 Dec 2024 10:54:00.548698691 CET +01:00
rosa commented 14 hours ago

Thanks @ronald! Huh, that's very interesting, because it's wrong 😅 What DB are you using and what time zone have you configured there? It's as if the value was being stored as CET, but disguised as UTC.

ronald commented 14 hours ago

It's mysqld

ActiveRecord::Base.connection.execute('SELECT @@VERSION, @@global.time_zone, @@session.time_zone;').to_a
# => [["8.0.39-0ubuntu0.22.04.1", "SYSTEM", "SYSTEM"]]
# cat /etc/timezone 
Europe/Berlin
rosa commented 9 hours ago

Ok, so, you're storing times in the DB in CET. My guess now is that Solid Queue doesn't know that, and since Rails by default would assume your DB is using UTC (which is recommended), that's causing the mismatch 🤔 . You could also check created_at or updated_at in the jobs table to see if these times are also wrong. However, since you're setting the time zone in application.rb, Solid Queue should be picking that up... 🤔 How are you running Solid Queue?

rosa commented 9 hours ago

Could you also let me know the value for this?

ActiveRecord.default_timezone
ronald commented 9 hours ago
ActiveRecord.default_timezone
# => :utc

I think all other values work exactly as expected. May be there's an issue only for SolidQueue::ClaimedExecution?

How are you running Solid Queue?

bin/jobs 

(If I have understood the question correctly)

rosa commented 9 hours ago

I think all other values work exactly as expected. May be there's an issue only for SolidQueue::ClaimedExecution?

Is this the case too for solid_queue_jobs.finished_at? Just wondering if the difference is between DB writes from your app vs. Solid Queue 🤔

ronald commented 5 hours ago

Sorry, what's solid_queue_jobs.finished_at and how to check it?

My assumption "everything else works fine" is based on the information in the first note because the values are stored in UTC their:

puts JSON.pretty_generate SolidQueue::Job.find(210110).attributes_before_type_cast
{
  "id": 210110,
  "queue_name": "default",
  "class_name": "SomeJobClass",
  "arguments": "{\"job_class\":\"SomeJobClass\",\"job_id\":\"09a81861-3c13-4bfd-b014-2d8612d755dd\",\"provider_job_id\":null,\"queue_name\":\"default\",\"priority\":null,\"arguments\":[12734],\"executions\":0,\"exception_executions\":{},\"locale\":\"de\",\"timezone\":\"Berlin\",\"enqueued_at\":\"2024-11-29T15:22:20.695549816Z\",\"scheduled_at\":\"2024-11-29T15:22:20.695433371Z\"}",
  "priority": 0,
  "active_job_id": "09a81861-3c13-4bfd-b014-2d8612d755dd",
  "scheduled_at": "2024-11-29 15:22:20 UTC",
  "finished_at": "2024-11-29 15:25:12 UTC",
  "concurrency_key": null,
  "created_at": "2024-11-29 15:22:20 UTC",
  "updated_at": "2024-11-29 15:25:12 UTC"
}