Skip to content

Commit

Permalink
Log full job details rather than just job_id
Browse files Browse the repository at this point in the history
A partial revert of c43eb24 which didn't include any reasoning/justification for the log simplification.

It's useful to be able to log details of the job, particularly the job_class and arguments; if this additional detail isn't desired then it can be removed by using a custom `Que.log_formatter`, for example:

```ruby
Que.log_formatter = proc do |data|
  if (job = data.delete(:job))
    data[:job_id] = job[:id]
  end

  JSON.dump(data)
end
```
  • Loading branch information
owst authored and ZimbiX committed Jul 24, 2024
1 parent e717fee commit 3975dfd
Show file tree
Hide file tree
Showing 3 changed files with 6 additions and 5 deletions.
2 changes: 1 addition & 1 deletion docs/README.md
Original file line number Diff line number Diff line change
Expand Up @@ -349,7 +349,7 @@ que --worker-count 1
By default, Que logs important information in JSON to either Rails' logger (when running in a Rails web process) or STDOUT (when running via the `que` executable). So, your logs will look something like:

```
I, [2017-08-12T05:07:31.094201 #4687] INFO -- : {"lib":"que","hostname":"lovelace","pid":21626,"thread":21471100,"event":"job_worked","job_id":6157665,"elapsed":0.531411}
I, [2017-08-12T05:07:31.094201 #4687] INFO -- : {"lib":"que","hostname":"lovelace","pid":98240,"thread":42660,"event":"job_worked","job":{"priority":1,"run_at":"2024-07-24T11:07:10.056514Z","id":2869885284504751564,"job_class":"WorkerJob","error_count":0,"last_error_message":null,"queue":"default","last_error_backtrace":null,"finished_at":null,"expired_at":null,"args":[1],"data":{},"job_schema_version":2,"kwargs":{}},"elapsed":0.001356}
```

Of course you can have it log wherever you like:
Expand Down
4 changes: 2 additions & 2 deletions lib/que/worker.rb
Original file line number Diff line number Diff line change
Expand Up @@ -114,7 +114,7 @@ def work_job(metajob)
if VALID_LOG_LEVELS.include?(log_level)
log_message = {
level: log_level,
job_id: metajob.id,
job: metajob.job,
elapsed: elapsed,
}

Expand All @@ -133,7 +133,7 @@ def work_job(metajob)
Que.log(
level: :debug,
event: :job_errored,
job_id: metajob.id,
job: metajob.job,
error: {
class: error.class.to_s,
message: error.message,
Expand Down
5 changes: 3 additions & 2 deletions spec/que/worker_spec.rb
Original file line number Diff line number Diff line change
Expand Up @@ -74,7 +74,8 @@ def finished_job_ids

events = logged_messages.select{|m| m[:event] == 'job_worked'}
assert_equal 3, events.count
assert_equal job_ids, events.map{|m| m[:job_id]}
assert_equal [1, 2, 3], events.map{|m| m.dig(:job, :priority) }
assert_equal job_ids, events.map{|m| m.dig(:job, :id) }
end

it "should handle namespaced job subclasses" do
Expand Down Expand Up @@ -228,7 +229,7 @@ def assert_retry_cadence(

# Error should be logged.
event = events.first
assert_equal job_ids.first, event[:job_id]
assert_equal job_ids.first, event.dig(:job, :id)
assert_equal "RuntimeError: Error!", event[:error]

# Errored job should still be in the DB.
Expand Down

0 comments on commit 3975dfd

Please sign in to comment.