brandonhilkert / sucker_punch

Sucker Punch is a Ruby asynchronous processing library using concurrent-ruby, heavily influenced by Sidekiq and girl_friday.
MIT License
2.65k stars 114 forks source link

Unicorn async jobs do not seem to work #72

Closed j1n6 closed 10 years ago

j1n6 commented 10 years ago

Hi,

I'm running unicorn with Rails 4 in production. The async.perform doesn't seem to work, because it still seems to execute tasks in sync style. I tried both 1.1 and 1.0.5 release.

Are there anyway I can debug the issue? May be it's just something is missing in documentation?

Thanks

brandonhilkert commented 10 years ago

code?

j1n6 commented 10 years ago

The code is simple:

class AuditMailerJob
  include SuckerPunch::Job
  workers 4
   # all parameters are string
  def perform(performer, title, diffs = nil)
   # this is standard Rails mailer
    AuditMailer.audit(performer, title, diffs).deliver
  end  
end

Local rails s async seems to work, but it has no effect on production with Unicorn. Thanks.

brandonhilkert commented 10 years ago

Can you describe your production ENV?

j1n6 commented 10 years ago

Production runs MRI Ruby 2.0.0. Here's my unicorn setting, in case it might be something wrong?

app_path = '/home/....'
listen '/tmp/app.sock'

# Spawn unicorn master worker for user mdashboard
user 'deployer', 'deployer'

# Fill path to your app
working_directory app_path

# Should be 'production' by default, otherwise use other env 
rails_env = ENV['RAILS_ENV'] || 'production'

# Log everything to one file
stderr_path "#{app_path}/log/unicorn.stderr.log"
stdout_path "#{app_path}/log/unicorn.log"

# Set master PID location
pid "#{app_path}/tmp/pids/unicorn.pid"

worker_processes Integer(ENV["WEB_CONCURRENCY"] || 4)
timeout 15
preload_app true

before_fork do |server, worker|
  Signal.trap 'TERM' do
    puts 'Unicorn master intercepting TERM and sending myself QUIT instead'
    Process.kill 'QUIT', Process.pid
  end

  defined?(ActiveRecord::Base) and
    ActiveRecord::Base.connection.disconnect!
end

after_fork do |server, worker|
  Signal.trap 'TERM' do
    puts 'Unicorn worker intercepting TERM and doing nothing. Wait for master to send QUIT'
  end

  defined?(ActiveRecord::Base) and
    ActiveRecord::Base.establish_connection
end
j1n6 commented 10 years ago

The setup is Nginx + Unicorn with Rails 4.0.5.

brandonhilkert commented 10 years ago

Everything looks normal to me there. What is it that shows it's not working in production?

j1n6 commented 10 years ago

The odd thing is that there's no crashes. When I call AuditMailerJob.new.async.perform('a', 'b', 'c') in production, it still makes sync call (blocking mailing). Same code in local development runs async. I will debug see if there are anything suspicious.

Thanks for your fast response. I will close this issue if it's problem on my side.

brandonhilkert commented 10 years ago

Are you calling it from a console? How do you know it's blocking? because of output?

j1n6 commented 10 years ago

I read the request time and method call from server logs.

On 20 Aug 2014, at 21:59, Brandon Hilkert notifications@github.com wrote:

Are you calling it from a console? How do you know it's blocking? because of output?

— Reply to this email directly or view it on GitHub.

j1n6 commented 10 years ago

Here's striped log:

Local development shows response 200 OK before sending emails, this is the production log:

I, [2014-08-20T22:37:59.932301 #16726]  INFO -- :   Rendered audit_mailer/audit.html.erb (1029.9ms)
I, [2014-08-20T22:38:01.975440 #16726]  INFO -- :
Sent mail to test@example.com (1987.3ms)
I, [2014-08-20T22:38:26.052294 #16726]  INFO -- :   Rendered users/update.json.jbuilder (1.5ms)
I, [2014-08-20T22:38:26.053943 #16726]  INFO -- : Completed 200 OK in 29863ms (Views: 59.9ms | ActiveRecord: 87.0ms)
brandonhilkert commented 10 years ago

Hmmm...that is curious. I wouldn't count on the order of the logs. If the job is enqueued prior, it's possible the worker picks it up before it's finished. It's hard to tell here because something is missing given the time doesn't total the 29 sec.

j1n6 commented 10 years ago

It's unlikely to be the issue with this gem. Thank you for helping me tracing it.