0.4.0 / Unicorn Delayed Jobs logs

[yongfook]

I updated my Rails according to this patch:
http://weblog.rubyonrails.org/2013/2/11/SEC-ANN-Rails-3-2-12-3-1-11-and-2-3-17-have-been-released/

and Delayed Job was updated to 0.4.0 at the same time.

I'm running Unicorn.

When I run my app now, Delayed Job seems to be spitting out much more to the logs. Is this expected behaviour?

11:40:37 worker.1 | SQL (0.4ms) UPDATE "delayed_jobs" SET "locked_at" = '2013-02-12 03:40:27.849168', "locked_by" = 'host:my-imac.local pid:13313' WHERE "delayed_jobs"."id" IN (SELECT id FROM "delayed_jobs" WHERE ((run_at <= '2013-02-12 03:40:27.848544' AND (locked_at IS NULL OR locked_at < '2013-02-11 23:40:27.848572') OR locked_by = 'host:my-imac.local pid:13313') AND failed_at IS NULL) ORDER BY priority ASC, run_at ASC LIMIT 1) AND ((run_at <= '2013-02-12 03:40:27.848544' AND (locked_at IS NULL OR locked_at < '2013-02-11 23:40:27.848572') OR locked_by = 'host:my-imac.local pid:13313') AND failed_at IS NULL)

11:40:37 worker.1 | SQL (0.4ms) UPDATE "delayed_jobs" SET "locked_at" = '2013-02-12 03:40:32.851916', "locked_by" = 'host:my-imac.local pid:13313' WHERE "delayed_jobs"."id" IN (SELECT id FROM "delayed_jobs" WHERE ((run_at <= '2013-02-12 03:40:32.851348' AND (locked_at IS NULL OR locked_at < '2013-02-11 23:40:32.851382') OR locked_by = 'host:my-imac.local pid:13313') AND failed_at IS NULL) ORDER BY priority ASC, run_at ASC LIMIT 1) AND ((run_at <= '2013-02-12 03:40:32.851348' AND (locked_at IS NULL OR locked_at < '2013-02-11 23:40:32.851382') OR locked_by = 'host:my-imac.local pid:13313') AND failed_at IS NULL)

11:40:37 worker.1 | SQL (0.4ms) UPDATE "delayed_jobs" SET "locked_at" = '2013-02-12 03:40:37.854636', "locked_by" = 'host:my-imac.local pid:13313' WHERE "delayed_jobs"."id" IN (SELECT id FROM "delayed_jobs" WHERE ((run_at <= '2013-02-12 03:40:37.854057' AND (locked_at IS NULL OR locked_at < '2013-02-11 23:40:37.854091') OR locked_by = 'host:my-imac.local pid:13313') AND failed_at IS NULL) ORDER BY priority ASC, run_at ASC LIMIT 1) AND ((run_at <= '2013-02-12 03:40:37.854057' AND (locked_at IS NULL OR locked_at < '2013-02-11 23:40:37.854091') OR locked_by = 'host:my-imac.local pid:13313') AND failed_at IS NULL)

It seems to be doing this every 5 seconds i.e. every time DJ polls my DB.

Perhaps this is just a new logging feature that I was unaware of or is this not expected behaviour?

[albus522]

Delayed::Job uses your app's settings for logging, so perhaps the DJ process was restarted into development instead of production after you performed the update.

[btoone]

Does that mean that it is normal for DJ to log an UPDATE query every 5 seconds when I run an app in development?

I ended up here after searching for what I thought was a bug. If adding an UPDATE entry every 5 seconds is the expected behavior, then what is the best way to prevent/workaround it? Currently it is very difficult to to read my dev and staging logs for other sql queries because of all the DJ UPDATE entries.

[gautamc]

I have had this issue with my development and staging instances too. For now, I am modifying and restoring ActiveRecord::Base.logger.level in def self.reserve that is present in the file lib/delayed/backend/active_record.rb of the /delayed_job_active_record gem.

Because, this effects only my development and staging instances and because the app runs on unicorn (hence, there isn't anything multi-threaded).. and because from the looks of it, it seems that this def is called by the delayed_job workers (which arn't running any multi-threaded code) ... and because I am root, I wasn't too worried before putting in this modification for now.

--- /usr/local/lib/ruby/gems/1.9.1/gems/delayed_job_active_record-0.4.1/lib/delayed/backend/active_record.rb~   2013-02-13 21:57:15.000000000 -0500
+++ /usr/local/lib/ruby/gems/1.9.1/gems/delayed_job_active_record-0.4.1/lib/delayed/backend/active_record.rb    2013-03-16 19:57:30.000000000 -0400
@@ -41,6 +41,9 @@
         end

         def self.reserve(worker, max_run_time = Worker.max_run_time)
+          restore_level_to = ::ActiveRecord::Base.logger.level
+          ::ActiveRecord::Base.logger.level = 2
+
           # scope to filter to records that are "ready to run"
           readyScope = self.ready_to_run(worker.name, max_run_time)

@@ -61,10 +64,12 @@
             quotedTableName = ::ActiveRecord::Base.connection.quote_column_name(self.table_name)
             subquerySql = nextScope.lock(true).select('id').to_sql
             reserved = self.find_by_sql(["UPDATE #{quotedTableName} SET locked_at = ?, locked_by = ? WHERE id IN (#{subquerySql}) RETURNING *",now,worker.name])
+            ::ActiveRecord::Base.logger.level = restore_level_to
             return reserved[0]
           else
             # This works on MySQL and other DBs that support UPDATE...LIMIT. It uses separate queries to lock and return the job
             count = nextScope.update_all(:locked_at => now, :locked_by => worker.name)
+            ::ActiveRecord::Base.logger.level = restore_level_to
             return nil if count == 0
             return self.where(:locked_at => now, :locked_by => worker.name).first
           end

[t-anjan]

This is still a problem. My "staging" environment is an exact replica of the production environment (the environments/production.rb and environments/staging.rb are exactly the same).

But still, on my staging environment (running using Unicorn), the log/staging.log file has these update queries logged every 5 seconds. I am using the following to start the delayed_job process:

RAILS_ENV=staging script/delayed_job start

So, the DJ process has got to be starting in the staging environment. But why is the log getting bloated with these update queries?

And why is the issue closed?

[trappist]

+1, what's the utility of running all these queries?

[albus522]

The queries are to check for new jobs. A required function of Delayed Job.

[btoone]

@albus522 would you please comment on why this issue is closed? It doesn't seem like you've addressed why the logging is so verbose (writing every 5 seconds). Sorry to be a pain but I would either like to know if this is being looked into or if there is a workaround for the problems it is causing us. Thanks.

[albus522]

The logging is purely a result of the app's log level setting. We do not modify any of the application logging behavior. The only messages we directly control are job processing counts, running, and completed messages and all are sent using INFO level to the app's logger. The messages you are seeing is AR query logging which is controlled completely by AR. The above reference to a staging environment is likely logging at the same level as development, since Rails does not recognize staging as a default environment. You will likely need to set the log level in the environments/staging.rb file. Here is rail's default log level setup:

@log_level ||= Rails.env.production? ? :info : :debug

[srpouyet]

+1 for @caspyin. DJ polls the db every 5 seconds in development, effectively rendering my development.log useless! 😒

A simple way to kill this noise would be much appreciated!

[dsgh]

@caspyin @SErepo Here's a workaround based on @gautamc solution, but a bit cleaner:

in config/initializers/delayed_job_silencer.rb:

if Rails.env.development?
  module Delayed
    module Backend
      module ActiveRecord
        class Job
          class << self
            alias_method :reserve_original, :reserve
            def reserve(worker, max_run_time = Worker.max_run_time)
              previous_level = ::ActiveRecord::Base.logger.level
              ::ActiveRecord::Base.logger.level = Logger::WARN if previous_level < Logger::WARN
              value = reserve_original(worker, max_run_time)
              ::ActiveRecord::Base.logger.level = previous_level
              value
            end
          end
        end
      end
    end
  end
end

[HungYuHei]

It works, thank you @dsgh

[srpouyet]

Cheers @dsgh, you rock! 👍

[willkoehler]

Thanks @dsgh great solution. I'm just wondering why these log messages didn't appear before - I don't see them in v3.0.5 for example. Didn't delayed_jobs_active_record always use ActiveRecord to poll the job queue? I looked through the history and couldn't find a definitive commit that would have changed the logging behavior.

[melriffe]

My only contribution to @dsgh's solution:

if %w(development staging).include? Rails.env

[xHire]

DJ can have its own logger for AR too, no need for the hassle in the patch above. I just added the following line to config/initializers/delayed_job_config.rb:

Delayed::Backend::ActiveRecord::Job.logger = Logger.new(Rails.root.join('log', 'delayed_job_ar.log'))

[wpsamurai]

@xHire I'm afraid that your change will send all ActiveRecord logs to delayed_job_ar.log file, not only those from DelayedJobs gem.

[xHire]

@wpsamurai Ah, I didn’t notice it, but when I do run grep -v delayed_jobs I see that you are right. I’ll have yet to find out a way to restrict the initializer to affect only the DJ daemon then. Thank you for pointing this out! 👍

[aiomaster]

Based on the monkey patch of @dsgh I want to offer a more "clean" monkey patch like this:

if Rails.env.development?
  Delayed::Backend::ActiveRecord::Job.singleton_class.prepend(
    Module.new do
      def reserve(*)
        previous_level = ::ActiveRecord::Base.logger.level
        ::ActiveRecord::Base.logger.level = Logger::WARN if previous_level < Logger::WARN
        value = super
        ::ActiveRecord::Base.logger.level = previous_level
        value
      end
    end
  )
end

[pebneter]

This worked well for years, but after upgrading to Rails 6.0 / 6.1 I get

NameError: undefined method 'reserve' for class `#<Class:Delayed::Backend::ActiveRecord::Job>'

Any idea how to fix this again? It looks like at the time the patch is invoked, the original class is not yet defined.

[pebneter]

I can answer my own question and contribute to the solution. Based on your work, I found this approach to be working for me in Rails 6.1.3:

1. Create a new file for the patch in /lib/patches/delayed_job (or wherever you like to keep your monkey patches)

# /lib/patches/delayed_job/delayed_job_silencer.rb

module ::Delayed::Backend::ActiveRecord
  class Job < ::ActiveRecord::Base
  end
  Job.singleton_class.prepend(
    Module.new do
      def reserve(*)
        previous_level = ::ActiveRecord::Base.logger.level
        ::ActiveRecord::Base.logger.level = Logger::WARN if previous_level < Logger::WARN
        value = super
        ::ActiveRecord::Base.logger.level = previous_level
        value
      end
    end
  )
end

2. Make sure the patch is loaded. I did it by creating a new initializer for all custom patches

# /initializers/patches.rb

Dir.glob(Rails.root.join('lib/patches/**/*.rb')).sort.each do |filename|
  require filename
end

[xHire]

Nowadays, I use the following patch, which effectively separates DJ-related AR logging without affecting the rest of my application:

--- a/bin/delayed_job	2017-05-02 11:08:24.809361621 +0200
+++ b/bin/delayed_job	2020-03-19 17:23:27.338214244 +0100
@@ -2,4 +2,5 @@
 
 require File.expand_path(File.join(File.dirname(__FILE__), '..', 'config', 'environment'))
 require 'delayed/command'
+Delayed::Backend::ActiveRecord::Job.logger = ActiveSupport::Logger.new(Rails.root.join('log', 'dj_ar.log'))
 Delayed::Command.new(ARGV).daemonize

Might be helpful for folks who don’t want to disable the logs altogether (or can log into /dev/null without monkey patching log levels). Tested with Rails 6.0.