【问题标题】：Why are some of my background jobs failing?为什么我的一些后台作业失败了？
【发布时间】：2014-10-24 00:30:27
【问题描述】：

简要说明：

Heroku 上的 Rails 4.0 应用
通过延迟作业的后台作业
worker dyno 通过 Workless 旋转起来
大多数作业成功，有些失败（带有以下异常跟踪）
作业失败仅在生产中（我无法在本地重现此问题）
作业在被延迟作业接收后约 6 秒内失败（请参阅跟踪的前三行）
工作程序/应用程序初始化期间作业失败（我的代码甚至没有机会执行）
我认为问题出在 Devise 或其模块之一，在后台作业的上下文中

Gemfile（一些相关行）：

gem 'devise', '~> 3.2.4'
gem 'delayed_job_active_record', '4.0.1'
gem 'workless', '~> 1.2.3'
gem 'daemons', '~> 1.1.9'

异常跟踪：

16.566936 heroku[worker.2]: Starting process with command `bundle exec rake jobs:work`
17.201669 heroku[worker.2]: State changed from starting to up
23.375876 heroku[worker.2]: State changed from up to down
25.734990 heroku[worker.2]: Stopping all processes with SIGTERM
26.315290 app[worker.2]: rake aborted!
26.315342 app[worker.2]: SignalException: SIGTERM
26.333413 app[worker.2]: /app/vendor/bundle/ruby/2.0.0/gems/activesupport-4.0.5/lib/active_support/dependencies.rb:229:in `require'
26.333417 app[worker.2]: /app/vendor/bundle/ruby/2.0.0/gems/activesupport-4.0.5/lib/active_support/dependencies.rb:229:in `block in require'
26.333419 app[worker.2]: /app/vendor/bundle/ruby/2.0.0/gems/activesupport-4.0.5/lib/active_support/dependencies.rb:214:in `load_dependency'
26.333421 app[worker.2]: /app/vendor/bundle/ruby/2.0.0/gems/activesupport-4.0.5/lib/active_support/dependencies.rb:229:in `require'
26.333422 app[worker.2]: /app/vendor/bundle/ruby/2.0.0/gems/bcrypt-3.1.7/lib/bcrypt.rb:16:in `rescue in <top (required)>'
26.333424 app[worker.2]: /app/vendor/bundle/ruby/2.0.0/gems/bcrypt-3.1.7/lib/bcrypt.rb:12:in `<top (required)>'
26.333440 app[worker.2]: /app/vendor/bundle/ruby/2.0.0/gems/activesupport-4.0.5/lib/active_support/dependencies.rb:229:in `require'
26.333442 app[worker.2]: /app/vendor/bundle/ruby/2.0.0/gems/activesupport-4.0.5/lib/active_support/dependencies.rb:229:in `block in require'
26.333444 app[worker.2]: /app/vendor/bundle/ruby/2.0.0/gems/activesupport-4.0.5/lib/active_support/dependencies.rb:214:in `load_dependency'
26.333445 app[worker.2]: /app/vendor/bundle/ruby/2.0.0/gems/activesupport-4.0.5/lib/active_support/dependencies.rb:229:in `require'
26.333447 app[worker.2]: /app/vendor/bundle/ruby/2.0.0/gems/devise-3.2.4/lib/devise/models/database_authenticatable.rb:2:in `<top (required)>'
26.333448 app[worker.2]: /app/vendor/bundle/ruby/2.0.0/gems/devise-3.2.4/lib/devise/models.rb:88:in `const_get'
26.333450 app[worker.2]: /app/vendor/bundle/ruby/2.0.0/gems/devise-3.2.4/lib/devise/models.rb:88:in `block (2 levels) in devise'
26.333451 app[worker.2]: /app/vendor/bundle/ruby/2.0.0/gems/devise-3.2.4/lib/devise/models.rb:87:in `each'
26.333453 app[worker.2]: /app/vendor/bundle/ruby/2.0.0/gems/devise-3.2.4/lib/devise/models.rb:87:in `block in devise'
26.333454 app[worker.2]: /app/vendor/bundle/ruby/2.0.0/gems/devise-3.2.4/lib/devise/models.rb:114:in `devise_modules_hook!'
26.333456 app[worker.2]: /app/vendor/bundle/ruby/2.0.0/gems/devise-3.2.4/lib/devise/models.rb:84:in `devise'
26.333458 app[worker.2]: /app/app/models/user.rb:6:in `<class:User>'
26.333459 app[worker.2]: /app/app/models/user.rb:1:in `<top (required)>'
26.333461 app[worker.2]: /app/vendor/bundle/ruby/2.0.0/gems/activesupport-4.0.5/lib/active_support/dependencies.rb:229:in `require'
26.333462 app[worker.2]: /app/vendor/bundle/ruby/2.0.0/gems/activesupport-4.0.5/lib/active_support/dependencies.rb:229:in `block in require'
26.333464 app[worker.2]: /app/vendor/bundle/ruby/2.0.0/gems/activesupport-4.0.5/lib/active_support/dependencies.rb:214:in `load_dependency'
26.333465 app[worker.2]: /app/vendor/bundle/ruby/2.0.0/gems/activesupport-4.0.5/lib/active_support/dependencies.rb:229:in `require'
26.333466 app[worker.2]: /app/vendor/bundle/ruby/2.0.0/gems/activesupport-4.0.5/lib/active_support/dependencies.rb:330:in `require_or_load'
26.333468 app[worker.2]: /app/vendor/bundle/ruby/2.0.0/gems/activesupport-4.0.5/lib/active_support/dependencies.rb:463:in `load_missing_constant'
26.333469 app[worker.2]: /app/vendor/bundle/ruby/2.0.0/gems/activesupport-4.0.5/lib/active_support/dependencies.rb:184:in `const_missing'
26.333470 app[worker.2]: /app/vendor/bundle/ruby/2.0.0/gems/activesupport-4.0.5/lib/active_support/inflector/methods.rb:226:in `const_get'
26.333472 app[worker.2]: /app/vendor/bundle/ruby/2.0.0/gems/activesupport-4.0.5/lib/active_support/inflector/methods.rb:226:in `block in constantize'
26.333473 app[worker.2]: /app/vendor/bundle/ruby/2.0.0/gems/activesupport-4.0.5/lib/active_support/inflector/methods.rb:224:in `each'
26.333474 app[worker.2]: /app/vendor/bundle/ruby/2.0.0/gems/activesupport-4.0.5/lib/active_support/inflector/methods.rb:224:in `inject'
26.333476 app[worker.2]: /app/vendor/bundle/ruby/2.0.0/gems/activesupport-4.0.5/lib/active_support/inflector/methods.rb:224:in `constantize'
26.333477 app[worker.2]: /app/vendor/bundle/ruby/2.0.0/gems/activesupport-4.0.5/lib/active_support/dependencies.rb:535:in `get'
26.333478 app[worker.2]: /app/vendor/bundle/ruby/2.0.0/gems/activesupport-4.0.5/lib/active_support/dependencies.rb:566:in `constantize'
26.333480 app[worker.2]: /app/vendor/bundle/ruby/2.0.0/gems/devise-3.2.4/lib/devise.rb:297:in `get'
26.333481 app[worker.2]: /app/vendor/bundle/ruby/2.0.0/gems/devise-3.2.4/lib/devise/mapping.rb:77:in `to'
26.333483 app[worker.2]: /app/vendor/bundle/ruby/2.0.0/gems/devise-3.2.4/lib/devise/mapping.rb:72:in `modules'
26.333484 app[worker.2]: /app/vendor/bundle/ruby/2.0.0/gems/devise-3.2.4/lib/devise/mapping.rb:89:in `routes'
26.333508 app[worker.2]: /app/vendor/bundle/ruby/2.0.0/gems/devise-3.2.4/lib/devise/mapping.rb:156:in `default_used_route'
26.333509 app[worker.2]: /app/vendor/bundle/ruby/2.0.0/gems/devise-3.2.4/lib/devise/mapping.rb:66:in `initialize'
26.333510 app[worker.2]: /app/vendor/bundle/ruby/2.0.0/gems/devise-3.2.4/lib/devise.rb:331:in `new'
26.333512 app[worker.2]: /app/vendor/bundle/ruby/2.0.0/gems/devise-3.2.4/lib/devise.rb:331:in `add_mapping'
26.333519 app[worker.2]: /app/vendor/bundle/ruby/2.0.0/gems/devise-3.2.4/lib/devise/rails/routes.rb:221:in `block in devise_for'
26.333520 app[worker.2]: /app/vendor/bundle/ruby/2.0.0/gems/devise-3.2.4/lib/devise/rails/routes.rb:220:in `each'
26.333522 app[worker.2]: /app/vendor/bundle/ruby/2.0.0/gems/devise-3.2.4/lib/devise/rails/routes.rb:220:in `devise_for'
26.333523 app[worker.2]: /app/config/routes.rb:31:in `block in <top (required)>'
26.333524 app[worker.2]: /app/vendor/bundle/ruby/2.0.0/gems/actionpack-4.0.5/lib/action_dispatch/routing/route_set.rb:335:in `instance_exec' 
26.333526 app[worker.2]: /app/vendor/bundle/ruby/2.0.0/gems/actionpack-4.0.5/lib/action_dispatch/routing/route_set.rb:335:in `eval_block'
26.333527 app[worker.2]: /app/vendor/bundle/ruby/2.0.0/gems/actionpack-4.0.5/lib/action_dispatch/routing/route_set.rb:313:in `draw'
26.333528 app[worker.2]: /app/config/routes.rb:1:in `<top (required)>'
26.333530 app[worker.2]: /app/vendor/bundle/ruby/2.0.0/gems/activesupport-4.0.5/lib/active_support/dependencies.rb:223:in `load'
26.333531 app[worker.2]: /app/vendor/bundle/ruby/2.0.0/gems/activesupport-4.0.5/lib/active_support/dependencies.rb:223:in `block in load'
26.333542 app[worker.2]: /app/vendor/bundle/ruby/2.0.0/gems/activesupport-4.0.5/lib/active_support/dependencies.rb:214:in `load_dependency'
26.333543 app[worker.2]: /app/vendor/bundle/ruby/2.0.0/gems/activesupport-4.0.5/lib/active_support/dependencies.rb:223:in `load'
26.333545 app[worker.2]: /app/vendor/bundle/ruby/2.0.0/gems/railties-4.0.5/lib/rails/application/routes_reloader.rb:40:in `block in load_paths'
26.333546 app[worker.2]: /app/vendor/bundle/ruby/2.0.0/gems/railties-4.0.5/lib/rails/application/routes_reloader.rb:40:in `each'
26.333548 app[worker.2]: /app/vendor/bundle/ruby/2.0.0/gems/railties-4.0.5/lib/rails/application/routes_reloader.rb:40:in `load_paths'
26.333549 app[worker.2]: /app/vendor/bundle/ruby/2.0.0/gems/railties-4.0.5/lib/rails/application/routes_reloader.rb:16:in `reload!'
26.333551 app[worker.2]: /app/vendor/bundle/ruby/2.0.0/gems/railties-4.0.5/lib/rails/application/routes_reloader.rb:26:in `block in updater'
26.333552 app[worker.2]: /app/vendor/bundle/ruby/2.0.0/gems/activesupport-4.0.5/lib/active_support/file_update_checker.rb:75:in `call'
26.333553 app[worker.2]: /app/vendor/bundle/ruby/2.0.0/gems/activesupport-4.0.5/lib/active_support/file_update_checker.rb:75:in `execute'
26.333555 app[worker.2]: /app/vendor/bundle/ruby/2.0.0/gems/railties-4.0.5/lib/rails/application/routes_reloader.rb:27:in `updater'
26.333556 app[worker.2]: /app/vendor/bundle/ruby/2.0.0/gems/railties-4.0.5/lib/rails/application/routes_reloader.rb:6:in `execute_if_updated'
26.333557 app[worker.2]: /app/vendor/bundle/ruby/2.0.0/gems/railties-4.0.5/lib/rails/application/finisher.rb:69:in `block in <module:Finisher>'
26.333559 app[worker.2]: /app/vendor/bundle/ruby/2.0.0/gems/railties-4.0.5/lib/rails/initializable.rb:30:in `instance_exec'
26.333560 app[worker.2]: /app/vendor/bundle/ruby/2.0.0/gems/railties-4.0.5/lib/rails/initializable.rb:30:in `run'
26.333562 app[worker.2]: /app/vendor/bundle/ruby/2.0.0/gems/railties-4.0.5/lib/rails/initializable.rb:55:in `block in run_initializers'
26.333563 app[worker.2]: /app/vendor/bundle/ruby/2.0.0/gems/railties-4.0.5/lib/rails/initializable.rb:54:in `run_initializers'
26.333577 app[worker.2]: /app/vendor/bundle/ruby/2.0.0/gems/railties-4.0.5/lib/rails/application.rb:215:in `initialize!'
26.333579 app[worker.2]: /app/vendor/bundle/ruby/2.0.0/gems/railties-4.0.5/lib/rails/railtie/configurable.rb:30:in `method_missing'
26.333580 app[worker.2]: /app/config/environment.rb:9:in `<top (required)>'
26.333581 app[worker.2]: /app/vendor/bundle/ruby/2.0.0/gems/activesupport-4.0.5/lib/active_support/dependencies.rb:229:in `require'
26.333583 app[worker.2]: /app/vendor/bundle/ruby/2.0.0/gems/activesupport-4.0.5/lib/active_support/dependencies.rb:229:in `block in require'
26.333584 app[worker.2]: /app/vendor/bundle/ruby/2.0.0/gems/activesupport-4.0.5/lib/active_support/dependencies.rb:214:in `load_dependency'
26.333585 app[worker.2]: /app/vendor/bundle/ruby/2.0.0/gems/activesupport-4.0.5/lib/active_support/dependencies.rb:229:in `require'
26.333587 app[worker.2]: /app/vendor/bundle/ruby/2.0.0/gems/railties-4.0.5/lib/rails/application.rb:189:in `require_environment!'
26.333588 app[worker.2]: /app/vendor/bundle/ruby/2.0.0/gems/railties-4.0.5/lib/rails/application.rb:250:in `block in run_tasks_blocks'
26.333589 app[worker.2]: Tasks: TOP => jobs:work => jobs:environment_options => environment
26.333591 app[worker.2]: (See full trace by running task with --trace)
28.113879 heroku[worker.2]: Process exited with status 1

app/models/user.rb:6

devise :database_authenticatable, :registerable, :confirmable, :omniauthable, :recoverable, :rememberable, :trackable, :validatable

config/routes.rb:31

devise_for :users, controllers: {omniauth_callbacks: 'omniauth_callbacks'}

第二次尝试

我在user.rb 中注释掉了omniauthable：

devise :database_authenticatable, :registerable, :confirmable, #:omniauthable,
       :recoverable, :rememberable, :trackable, :validatable

和omniauth_callbacks 在routes.rb：

devise_for :users#, controllers: {omniauth_callbacks: 'omniauth_callbacks'}

我运行了大约 20 个工作，最后一个崩溃了。这次的异常跟踪有点不同：

异常跟踪：

24.233695 app[worker.2]: rake aborted!
24.233841 app[worker.2]: SignalException: SIGTERM
24.234293 app[worker.2]: /app/vendor/bundle/ruby/2.0.0/gems/activesupport-4.0.5/lib/active_support/dependencies.rb:229:in `block in require'
24.234297 app[worker.2]: /app/vendor/bundle/ruby/2.0.0/gems/activesupport-4.0.5/lib/active_support/dependencies.rb:214:in `load_dependency'
24.234300 app[worker.2]: /app/vendor/bundle/ruby/2.0.0/gems/activesupport-4.0.5/lib/active_support/dependencies.rb:229:in `require'
24.234302 app[worker.2]: /app/vendor/bundle/ruby/2.0.0/gems/newrelic_rpm-3.9.0.229/lib/new_relic/agent/transaction_sampler.rb:11:in `<top (required)>'
24.234303 app[worker.2]: /app/vendor/bundle/ruby/2.0.0/gems/activesupport-4.0.5/lib/active_support/dependencies.rb:229:in `require'
24.234305 app[worker.2]: /app/vendor/bundle/ruby/2.0.0/gems/activesupport-4.0.5/lib/active_support/dependencies.rb:229:in `block in require'
24.234307 app[worker.2]: /app/vendor/bundle/ruby/2.0.0/gems/activesupport-4.0.5/lib/active_support/dependencies.rb:214:in `load_dependency'
24.234309 app[worker.2]: /app/vendor/bundle/ruby/2.0.0/gems/activesupport-4.0.5/lib/active_support/dependencies.rb:229:in `require'
24.234311 app[worker.2]: /app/vendor/bundle/ruby/2.0.0/gems /newrelic_rpm-3.9.0.229/lib/new_relic/agent.rb:94:in `<module:Agent>'
24.234313 app[worker.2]: /app/vendor/bundle/ruby/2.0.0/gems/newrelic_rpm-3.9.0.229/lib/new_relic/agent.rb:69:in `<module:NewRelic>'
24.234315 app[worker.2]: /app/vendor/bundle/ruby/2.0.0/gems/newrelic_rpm-3.9.0.229/lib/new_relic/agent.rb:40:in `<top (required)>'
24.234317 app[worker.2]: /app/vendor/bundle/ruby/2.0.0/gems/activesupport-4.0.5/lib/active_support/dependencies.rb:229:in `require'
24.234319 app[worker.2]: /app/vendor/bundle/ruby/2.0.0/gems/activesupport-4.0.5/lib/active_support/dependencies.rb:229:in `block in require'
24.234321 app[worker.2]: /app/vendor/bundle/ruby/2.0.0/gems/activesupport-4.0.5/lib/active_support/dependencies.rb:214:in `load_dependency'
24.234323 app[worker.2]: /app/vendor/bundle/ruby/2.0.0/gems/activesupport-4.0.5/lib/active_support/dependencies.rb:229:in `require'
24.234325 app[worker.2]: /app/vendor/bundle/ruby/2.0.0/gems/newrelic_rpm-3.9.0.229/lib/new_relic/control.rb:24:in `<top (required)>'
24.234327 app[worker.2]: /app/vendor/bundle/ruby/2.0.0/gems/activesupport-4.0.5/lib/active_support/dependencies.rb:229:in `require'
24.234329 app[worker.2]: /app/vendor/bundle/ruby/2.0.0/gems/activesupport-4.0.5/lib/active_support /dependencies.rb:229:in `block in require'
24.234332 app[worker.2]: /app/vendor/bundle/ruby/2.0.0/gems/activesupport-4.0.5/lib/active_support/dependencies.rb:214:in `load_dependency'
24.234334 app[worker.2]: /app/vendor/bundle/ruby/2.0.0/gems/activesupport-4.0.5/lib/active_support/dependencies.rb:229:in `require'
24.234336 app[worker.2]: /app/vendor/bundle/ruby/2.0.0/gems/newrelic_rpm-3.9.0.229/lib/newrelic_rpm.rb:25:in `<top (required)>'
24.234338 app[worker.2]: /app/vendor/bundle/ruby/2.0.0/gems/bundler-1.6.3/lib/bundler/runtime.rb:76:in `require'
24.234340 app[worker.2]: /app/vendor/bundle/ruby/2.0.0/gems/bundler-1.6.3/lib/bundler/runtime.rb:76:in `block (2 levels) in require'
24.234343 app[worker.2]: /app/vendor/bundle/ruby/2.0.0/gems/bundler-1.6.3/lib/bundler/runtime.rb:72:in `each'
24.234345 app[worker.2]: /app/vendor/bundle/ruby/2.0.0/gems/bundler-1.6.3/lib/bundler/runtime.rb:72:in `block in require'
24.234346 app[worker.2]: /app/vendor/bundle/ruby/2.0.0/gems/bundler-1.6.3/lib/bundler/runtime.rb:61:in `each'
24.234349 app[worker.2]: /app/vendor/bundle/ruby/2.0.0/gems/bundler-1.6.3/lib/bundler/runtime.rb:61:in `require'
24.234351 app[worker.2]: /app/vendor/bundle/ruby/2.0.0/gems/bundler-1.6.3/lib/bundler.rb:132:in `require'
24.234354 app[worker.2]: /app/config/application.rb:12:in `<top (required)>'
24.234356 app[worker.2]: /app/Rakefile:4:in `require'
24.234358 app[worker.2]: /app/Rakefile:4:in `<top (required)>'
24.234365 app[worker.2]: (See full trace by running task with --trace)
23.305036 heroku[worker.2]: Stopping all processes with SIGTERM
25.200583 heroku[worker.2]: Process exited with status 1

Rakefile:4

require File.expand_path('../config/application', __FILE__)

config/application.rb:12

Bundler.require(:default, Rails.env)

【问题讨论】：

标签： ruby-on-rails heroku devise omniauth delayed-job

【解决方案1】：

如果您没有调用SIGTERM，Heroku 至少每天通过发送SIGTERM 重新启动每个测功机一次。 Sidekiq 会自动处理这个问题，但有时 Heroku 会提前关闭它，并导致问题 - 这意味着最好将超时时间从 8 更改为 5 秒。 Delayed Jobs 和 Resque 要求您在 5 左右处理信号。

请求说明 https://devcenter.heroku.com/articles/queuing-ruby-resque#job-termination

延迟作业 Long running delayed_job jobs stay locked after a restart on Heroku

【讨论】：

谢谢，但我认为这无关。我的工作似乎在初始化期间被杀死了。它们在~6 秒内从up 变为down。我认为这是 Devise 或其模块之一的问题。
只是一个观察，但时间是一致的~6秒的机会是它的heroku强制超时，或者sidekiq可能超时github.com/mperham/sidekiq/wiki/…
另一点尝试创建一个不调用设计的作业，而只是调用一个简单的数据库调用，看看是否再次发生同样的事情。如果是这样，您的问题在于数据库连接而不是设计。
谢谢。这些都是不错的想法。请注意，此时我使用的是延迟作业（不是 Sidekiq）。

【解决方案2】：

您的测功机将收到SIGTERM 命令。然后，您的进程有 10 秒的时间关闭，然后将 SIGKILL 发送到您的进程。如果必须强制终止进程，则抛出R12 error。除此之外，我们 (Heroku) 不会强制执行任何超时。

如果您对此还有任何疑问，请告诉我。或者，非常欢迎您打开support request 以获取更多信息。

来源：Dynos and the Dyno Manager：Graceful shutdown with SIGTERM

【讨论】：

但是为什么 Heroku 将SIGTERM 发送给一个新旋转的测功机？这是一个测功机，可能与 2 到 10 个其他人一起旋转，以处理用户添加的图像。我旋转与添加的图像一样多的测功机，因为我宁愿并行处理它们而不是串行处理它们。我使用workless gem 来启动它们，并将WORKLESS_WORKERS_RATIO 设置为1（即，我为每个进入队列的工作启动一个测功机）。想法？