View Resque log output in Rails server logs

Question

I've got a Rails 4 app on a Puma server with Resque/Resque-Scheduler running background jobs. What I'd like to know is how I merge the log output of my two Resque workers into my server log, or, of that is not possible, how I can view the log output of my Resque workers. Currently I have not been able to figure out how to view the log output for the workers, so I have no idea what's happening under the hood. I found this blogpost, which suggests adding the following likes to my resque.rake file:

task "resque:setup" => :environment do
  Resque.before_fork = Proc.new { 
    ActiveRecord::Base.establish_connection

    # Open the new separate log file
    logfile = File.open(File.join(Rails.root, 'log', 'resque.log'), 'a')

    # Activate file synchronization
    logfile.sync = true

    # Create a new buffered logger
    Resque.logger = ActiveSupport::BufferedLogger.new(logfile)
    Resque.logger.level = Logger::INFO
    Resque.logger.info "Resque Logger Initialized!"
  }
end

That didn't work. I also tried the suggestion in the comments, which was to replace Resque.logger = ActiveSupport::BufferedLogger.new(logfile) with Resque.logger = ActiveSupport::Logger.new(logfile), however that didn't work either. With the second option, I still get a NoMethodError: undefined method 'logger=' for Resque:Module error when I try to boot up a worker.

Here is my current resque.rake file:

require 'resque/tasks'
require 'resque_scheduler/tasks'

namespace :resque do
    puts "Loading Rails environment for Resque"
    task :setup => :environment do
        require 'resque'
        require 'resque_scheduler'
        require 'resque/scheduler'
        require 'postman'
    end
end

I've looked at the Resque docs on logging, but am not sure how to use what's there as I admittedly don't know very much about logging in Rails. I haven't had any luck finding other useful resources on the subject.

Answer 1

How I fix it, it is not perfect but just works.

my environment: rails 5.0.1, resque: 1.26.0

at the first time, I set the Resque.logger and Resque.logger.level in config/initializers/resque.rb as most docs suggest:

# config/initializers/resque.rb
Resque.logger = Logger.new("#{Rails.root}/log/resque.log")
Resque.logger.level = Logger::DEBUG

then in the job, I output log by Resque.logger.info:

# update_xxx_job.rb
class UpdateXxxJob
  def self.perform
    Resque.logger.info 'Job starts'
    ...
  end
end

it doesn't work, I can see nothing in log/resque.log.

then someone said should set the logfile sync always, no buffer, so I update the config/initializers/resque.rb according a question from stackoverflow:

# config/initializers/resque.rb
logfile = File.open(File.join(Rails.root, 'log', 'resque.log'), 'a')
logfile.sync = true
Resque.logger = ActiveSupport::Logger.new(logfile)
Resque.logger.level = Logger::INFO

still doesn't work.

I also tried config resque logger in lib/tasks/resque.rake:

# lib/tasks/resque.rake
require 'resque'
require 'resque/tasks'
require 'resque/scheduler/tasks'
require 'resque-scheduler'
require 'resque/scheduler/server'

namespace :resque do
  task setup: :environment do
    Resque.schedule = YAML.load_file(Rails.root + "config/resque_scheduler_#{Rails.env}.yml")

    Resque.redis.namespace = "xxx_#{Rails.env}"

    Resque.logger = Logger.new("#{Rails.root}/log/resque.log")
    Resque.logger.level = Logger::INFO
  end
end

doesn't work.

finally, I decide to move the logger configuration from initializer to the job, so the job now looks like:

# update_xxx_job.rb
class UpdateXxxJob
  def self.perform
    Resque.logger = Logger.new("#{Rails.root}/log/resque.log")
    Resque.logger.level = Logger::DEBUG   

    Resque.logger.info 'Job starts'
    ...
  end
end

then I can get what I want in the log/resque.log.

you can try it.

Answer 2

I faced the same issue so that I check the source of resque and finally I needed to do the followings at initialization process:

1. define log formatter.
2. then define logger with log-file path.
3. set any log level.

Here the example is at my config/initializers/resque.rb in rails case:

...
Resque.logger           = Logger.new("#{Rails.root}/log/resque.log")
Resque.logger.level     = Logger::DEBUG
Resque.logger.formatter = ::Logger::Formatter.new   # This is important

Resque default logger formatter is set here and its definitions is here. That apparently just ignores the output...

Answer 3

I've had the same problem while setting up mine. Here's what I did:

Resque.before_fork do
  # Your code here
end

It seems before_fork accepts a block as an argument rather than assigning a block to it.