each log line appearing twice

[caljess599]

For as long as I can recall, every log line produced by delayed_job appears twice, in two different formats. I'd love to disable this (because it's just noise) but especially because I can only manipulate one of the copies.

My log config:

   # config/environments/development.rb
   ...
   # use a custom formatter for delayed jobs
   Delayed::Worker.logger = ActiveSupport::Logger.new(STDOUT)
   Delayed::Worker.logger.formatter = DelayedJobFormatter.new
    
   # print the output as it comes
   STDOUT.sync = true
   ...

The first copy has just the Worker host and pid and the message, e.g.:

[Worker(host:9b3bea8e62b5 pid:1)] Starting job worker

The second copy includes more information, but it clearly refers to the same event:

["INFO", 2020-01-08 14:44:05 -0500, nil, "2020-01-08T14:44:05-0500: [Worker(host:9b3bea8e62b5 pid:1)] Starting job worker"]

My custom formatter can change the second format into whatever I want, but the first format still appears.

Please help! We're using v4.1.4 of this gem on Ruby 2.6.5 with Rails 5.0.0.rc2

Thanks.

P.S. I am using lograge, but I don't think that its use is related to this problem. (When I disable lograge, I still see duplicate lines for delayed_jobs.)

P.P.S. The code of my custom formatter:

# app/models/delayed_job_formatter.rb

class DelayedJobFormatter
  
  def call(*data)
    # data is an Array
    "{\"level\":\"#{format_level(data)}\",\"content\":\"#{format_content(data)}\"\}\n"
  end  

  protected

  def format_content(data)
    if data.fourth.match?("queue=default")
      # this is a status message
      content = data.fourth.split('(queue=default) ').second
    else
      # this is another message
      content = data.fourth.split(')] ').second
    end
    content
  end

  def format_level(data)
    # this output will be a string that is the level
    starting_level = data.first
    if starting_level == "INFO" && format_content(data).match?("failed")
      level = "ERROR"
    else
      level = starting_level
    end
    level
  end
  
end

[caljess599]

I now understand why this happens, but it leads me to a different question...

Basically, by specifying a logger for Delayed::Jobs in my Rails config, I'm telling it to duplicate the logging that the gem already outputs to STDOUT.

So: new question #1: Can this output be suppressed, leaving me with ONLY my specified logger output?

That would be helpful, but since I've also learned that I can format the default output by making a plugin, at a minimum I won't have to tolerate duplicate output.

[caljess599]

Also, adding QUIET=true to my environment variables has removed all the messages that I wasn't able to catch by using the lifecycle hooks, e.g.:

[Worker(host:13782e20caa1 pid:1)] Starting job worker
[Worker(host:13782e20caa1 pid:1)] Job ActiveJob::QueueAdapters::DelayedJobAdapter::JobWrapper (id=19) (queue=default) RUNNING
[Worker(host:13782e20caa1 pid:1)] Job ActiveJob::QueueAdapters::DelayedJobAdapter::JobWrapper (id=19) (queue=default) FAILED (8 prior attempts) with NoMethodError: undefined method `update' for nil:NilClass

[jacobjlevine]

Whew. I've been struggling with this myself. Adding some additional context for future folks who stumble on this page.

In case you're curious, the duplication is caused by the statement puts text unless @quiet in Delayed::Worker#say.

The default duplicate logging is still an issue and is fixed by #987 (unmerged). Although the default for the quiet option is supposed to be true, there's a bug due to the way ENV['QUIET'] is handled when you run rake jobs:work (see /lib/delayed/tasks.rb) coupled with the way the quiet option is handled when initializing new instances of Delayed::Worker (specifically @quiet = options.key?(:quiet) ? options[:quiet] : true).

And to reiterate @caljess599, you can eliminate the duplication issue in the meantime by setting ENV['QUIET'] = true.

[satriajanaka09]

Hi I already tried to add these lines in development.rb but I still didn't see any logging happen directly in rails application, does anyone know why?

 Delayed::Worker.logger = ActiveSupport::Logger.new(STDOUT)
 STDOUT.sync = true

The goal is to write the delayed job log in the Rails application, so that I can see the log in the pod log, not in log/delayed_job.log file. The application is hosted in openshift.

[martinstreicher]

I spent the last few days connecting ActiveJob and Delayed Job to New Relic, providing New Relic with structured data for jobs.

There are many moving parts in the logs for jobs:

1. Delayed Job will emit messages to STDOUT if ENV['QUIET'] is not set to true. If your logging system is consuming STDOUT in any way, those messages are going to appear in the log. Set ENV['QUIET'] = true to squelch those.

2. DelayedJob::Worker.logger emits messages. The messages that go to STDOUT, mentioned immediately above, are sent to this logger, in addition to other messages. If you don't want these, you have to set Delayed::Worker.logger = Logger.new('/dev/null') or something similar.

3. ActiveJob::Base.logger also emits messages. Typically, the originator of the messages is the ActiveJob::LogSubscriber, which reacts to notifications from ActiveJob and produces a lot of those activities, such as enqueueing, exceptions, retries, failures, and completions. ActiveJob::Base.logger is a tagged logger emitting to STDOUT, unless changed.

In addition, each ActiveJob job can have its own logger by setting SomeJobClass.logger = .... If nothing is set for a job, the job's logger is ActiveJob::Base.logger.

Hence, with no squelching, your logs could contain messages from at least these four sources.

I believe Sidekiq also has its own logger, if you are using it instead of Delayed Job.

To make my code work with New Relic, I set ENV['QUIET'] = true; set ActiveJob::Base.logger = Logger.new('/dev/null'); and then set my own ActiveJob subscriber logger to my custom logger. Then, the only output I get, is from the latter. It appears in STDOUT and not log/production.log, and is sent to NR via the agent.