When shunting dj logs to their own file, the active record lines remain in the dev.log

[DaveSanders]

We're trying to get all logging for delayed_job into its own delayed_job.log. We've done the config line from the readme

Delayed::Worker.logger = Logger.new(Rails.root.join('log/delayed_job.log'))

But are still seeing messages with this signature in our development.log:

Delayed::Backend::ActiveRecord::Job Load (0.7ms)�[0m  �[1m�[37mUPDATE "delayed_jobs" SET locked_at = '2023-06-13 15:42:36.559114'....

Is there another config to move these, or some other strategy to quiet these out of the dev.log? Or is this a bug and needs to be resolved so that these messages move to the other log as well? We are also using delayed_job

• delayed_job 4.1.11
• delayed_job_active_record 4.1.7
• delayed_job_worker_pool 1.0.0
• ruby 3.2.1
• Rails 7.0.4.3

[speckins]

Delayed::Worker.logger isn't logging SQL queries; ActiveRecord::Base.logger is.

Most of the Rails components have their own logger accessor (ActiveRecord::Base.logger, ActiveJob::Base.logger, etc). During the Rails initialization process Rails.logger is initialized based on your configuration (under config/), then each of those loggers are set to Rails.logger.

You either need to put something in your config (either config/application.rb or config/environments/*.rb) to set up an alternate logger early in the process or change the logger(s) late in the process.

If you're using the rake task (rake jobs:work) to run jobs, you could add a task dependency to switch the logger.

# lib/rake/jobs.rake:
namespace :jobs do
  task :prepare_logger do
    logfile = File.open 'log/delayed_job.log', 'a'
    logfile.sync = true

    Rails.logger.reopen(logfile)
    Rails.logger.level = :info

    # https://github.com/collectiveidea/delayed_job/issues/1112
    ENV['QUIET'] = '1'
  end

  task :environment_options => :prepare_logger
end

Another option, if you're running the workers with something like systemd might be to log to STDOUT (using RAILS_LOG_TO_STDOUT; see the default config/environments/production.rb) and capture it to a file.

[th317erd]

I have tried every single "hack" or configuration setting I have found online, including everything found here: #886

ABSOLUTELY NOTHING will stop DJ from outputting debug messages in my real log file in production:

D, [2024-02-19T12:00:36.037525 #17718] DEBUG -- :   Delayed::Backend::ActiveRecord::Job Count (1.0ms)  SELECT COUNT(*) FROM `delayed_jobs` WHERE (failed_at is not NULL)
D, [2024-02-19T12:00:36.038717 #17718] DEBUG -- :   Delayed::Backend::ActiveRecord::Job Count (0.7ms)  SELECT COUNT(*) FROM `delayed_jobs` WHERE (locked_by is not NULL)
D, [2024-02-19T12:00:36.040563 #17718] DEBUG -- :   Delayed::Backend::ActiveRecord::Job Count (0.9ms)  SELECT COUNT(*) AS `count_all`, `delayed_jobs`.`queue` AS `delayed_jobs_queue` FROM `delayed_jobs` WHERE (run_at <= '2024-02-19 19:00:36.039172' and failed_at is NULL) GROUP BY `delayed_jobs`.`queue`
D, [2024-02-19T12:00:36.041947 #17718] DEBUG -- :   Delayed::Backend::ActiveRecord::Job Count (0.8ms)  SELECT COUNT(*) AS `count_all`, `delayed_jobs`.`priority` AS `delayed_jobs_priority` FROM `delayed_jobs` WHERE (run_at <= '2024-02-19 19:00:36.040694' and failed_at is NULL) GROUP BY `delayed_jobs`.`priority`
D, [2024-02-19T12:00:39.597628 #17718] DEBUG -- :   Delayed::Backend::ActiveRecord::Job Update All (1.4ms)  UPDATE `delayed_jobs` SET `delayed_jobs`.`locked_at` = '2024-02-19 19:00:39', `delayed_jobs`.`locked_by` = 'delayed_job host:ip-172-31-35-218 pid:17718' WHERE (((run_at <= '2024-02-19 19:00:39.595108' AND (locked_at IS NULL OR locked_at < '2024-02-19 15:00:39.595130')) OR locked_by = 'delayed_job host:ip-172-31-35-218 pid:17718') AND failed_at IS NULL) ORDER BY priority ASC, run_at ASC LIMIT 1
D, [2024-02-19T12:00:44.605479 #17718] DEBUG -- :   Delayed::Backend::ActiveRecord::Job Update All (1.3ms)  UPDATE `delayed_jobs` SET `delayed_jobs`.`locked_at` = '2024-02-19 19:00:44', `delayed_jobs`.`locked_by` = 'delayed_job host:ip-172-31-35-218 pid:17718' WHERE (((run_at <= '2024-02-19 19:00:44.603051' AND (locked_at IS NULL OR locked_at < '2024-02-19 15:00:44.603072')) OR locked_by = 'delayed_job host:ip-172-31-35-218 pid:17718') AND failed_at IS NULL) ORDER BY priority ASC, run_at ASC LIMIT 1
D, [2024-02-19T12:00:49.613364 #17718] DEBUG -- :   Delayed::Backend::ActiveRecord::Job Update All (1.3ms)  UPDATE `delayed_jobs` SET `delayed_jobs`.`locked_at` = '2024-02-19 19:00:49', `delayed_jobs`.`locked_by` = 'delayed_job host:ip-172-31-35-218 pid:17718' WHERE (((run_at <= '2024-02-19 19:00:49.610944' AND (locked_at IS NULL OR locked_at < '2024-02-19 15:00:49.610966')) OR locked_by = 'delayed_job host:ip-172-31-35-218 pid:17718') AND failed_at IS NULL) ORDER BY priority ASC, run_at ASC LIMIT 1

In my config/environments/production.rb I have:

config.log_level = :info
Rails.logger.level = :info

And in config/initializers/delayed_job_config.rb:

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

Can someone please help me make this stop?!

EDIT:
I realized I was being dumb for two reasons:

1. I was creating a NEW logger instance in the delayed_job_config.rb, which obviously has its own level
2. I restarted Rails on the server after making config changes, but I forgot that DJ has its own worker process that I had to restart as well

Here is my updated config/initializers/delayed_job_config.rb that actually works:

dj_logger = Logger.new(File.join(Rails.root, 'log', 'delayed_job.log'))
dj_logger.level = Rails.logger.level

Delayed::Backend::ActiveRecord::Job.logger = Delayed::Worker.logger = dj_logger