Rails + Heroku:Excon 预期([200、201、202、204、206、304])<=> 实际(422 无法处理的实体)

Rails + Heroku: Excon Expected([200, 201, 202, 204, 206, 304]) <=> Actual(422 Unprocessable Entity)

我的 Rails 应用程序部署在 Heroku 中,使用了一些我定义并计划每天执行一次的 rake 任务。非常简单的任务,他们唯一做的就是向 DelajedJobs 添加一些工作 table,以便工作人员起床并执行它们。

几天前,所有 rake 作业都开始失败。其中之一的一些示例:

# Rakefile
desc 'Update balances of all organizations'
task recalculate_balances: :environment do
  Organization.all.each do |organization|
    RecalculateBalancesJob.perform_later(organization)
  end
end

我在我的 Rollbar 帐户中看到了这个异常:

Excon::Error::UnprocessableEntity: Expected([200, 201, 202, 204, 206, 304]) <=> Actual(422 Unprocessable Entity)
+ 61 non-project frames
62
File "/app/Rakefile", line 22 in block (2 levels) in <top (required)>
+ 2 non-project frames
65
File "/app/Rakefile", line 21 in block in <top (required)>
+ 32 non-project frames
98
File "/app/bin/bundle", line 3 in load
99
File "/app/bin/bundle", line 3 in <main>

所以我所做的是用 begin rescue end 块覆盖,以避免丢失那里的工作,但我一直看到同样的错误。没有什么能给我关于可能发生的事情的线索。这是完整的堆栈跟踪:

Expected([200, 201, 202, 204, 206, 304]) <=> Actual(422 Unprocessable Entity)
/app/vendor/bundle/ruby/2.4.0/gems/excon-0.57.1/lib/excon/middlewares/expects.rb:7:in `response_call'
/app/vendor/bundle/ruby/2.4.0/gems/excon-0.57.1/lib/excon/middlewares/response_parser.rb:9:in `response_call'
/app/vendor/bundle/ruby/2.4.0/gems/excon-0.57.1/lib/excon/connection.rb:388:in `response'
/app/vendor/bundle/ruby/2.4.0/gems/excon-0.57.1/lib/excon/connection.rb:252:in `request'
/app/vendor/bundle/ruby/2.4.0/gems/heroics-0.0.23/lib/heroics/link.rb:111:in `request_with_cache'
/app/vendor/bundle/ruby/2.4.0/gems/heroics-0.0.23/lib/heroics/link.rb:66:in `run'
/app/vendor/bundle/ruby/2.4.0/gems/heroics-0.0.23/lib/heroics/resource.rb:28:in `method_missing'
/app/vendor/bundle/ruby/2.4.0/gems/platform-api-2.1.0/lib/platform-api/client.rb:1455:in `update'
/app/vendor/bundle/ruby/2.4.0/gems/workless_revived-2.1.0.2/lib/workless/scalers/heroku.rb:14:in `up'
/app/vendor/bundle/ruby/2.4.0/gems/workless_revived-2.1.0.2/lib/workless/scaler.rb:21:in `block (2 levels) in included'
/app/vendor/bundle/ruby/2.4.0/gems/activesupport-5.0.1/lib/active_support/callbacks.rb:396:in `instance_exec'
/app/vendor/bundle/ruby/2.4.0/gems/activesupport-5.0.1/lib/active_support/callbacks.rb:396:in `block in make_lambda'
/app/vendor/bundle/ruby/2.4.0/gems/activesupport-5.0.1/lib/active_support/callbacks.rb:232:in `block in conditional'
/app/vendor/bundle/ruby/2.4.0/gems/activesupport-5.0.1/lib/active_support/callbacks.rb:456:in `block in call'
/app/vendor/bundle/ruby/2.4.0/gems/activesupport-5.0.1/lib/active_support/callbacks.rb:456:in `each'
/app/vendor/bundle/ruby/2.4.0/gems/activesupport-5.0.1/lib/active_support/callbacks.rb:456:in `call'
/app/vendor/bundle/ruby/2.4.0/gems/activesupport-5.0.1/lib/active_support/callbacks.rb:101:in `__run_callbacks__'
/app/vendor/bundle/ruby/2.4.0/gems/activesupport-5.0.1/lib/active_support/callbacks.rb:750:in `_run_commit_callbacks'
/app/vendor/bundle/ruby/2.4.0/gems/activerecord-5.0.1/lib/active_record/transactions.rb:354:in `committed!'
/app/vendor/bundle/ruby/2.4.0/gems/activerecord-5.0.1/lib/active_record/connection_adapters/abstract/transaction.rb:87:in `commit_records'
/app/vendor/bundle/ruby/2.4.0/gems/activerecord-5.0.1/lib/active_record/connection_adapters/abstract/transaction.rb:178:in `commit_transaction'
/app/vendor/bundle/ruby/2.4.0/gems/activerecord-5.0.1/lib/active_record/connection_adapters/abstract/transaction.rb:202:in `within_new_transaction'
/app/vendor/bundle/ruby/2.4.0/gems/activerecord-5.0.1/lib/active_record/connection_adapters/abstract/database_statements.rb:232:in `transaction'
/app/vendor/bundle/ruby/2.4.0/gems/activerecord-5.0.1/lib/active_record/transactions.rb:211:in `transaction'
/app/vendor/bundle/ruby/2.4.0/gems/activerecord-5.0.1/lib/active_record/transactions.rb:392:in `with_transaction_returning_status'
/app/vendor/bundle/ruby/2.4.0/gems/activerecord-5.0.1/lib/active_record/transactions.rb:319:in `block in save'
/app/vendor/bundle/ruby/2.4.0/gems/activerecord-5.0.1/lib/active_record/transactions.rb:334:in `rollback_active_record_state!'
/app/vendor/bundle/ruby/2.4.0/gems/activerecord-5.0.1/lib/active_record/transactions.rb:318:in `save'
/app/vendor/bundle/ruby/2.4.0/gems/activerecord-5.0.1/lib/active_record/suppressor.rb:41:in `save'
/app/vendor/bundle/ruby/2.4.0/gems/delayed_job-4.1.2/lib/delayed/backend/base.rb:19:in `block (2 levels) in enqueue_job'
/app/vendor/bundle/ruby/2.4.0/gems/delayed_job-4.1.2/lib/delayed/lifecycle.rb:61:in `block in initialize'
/app/vendor/bundle/ruby/2.4.0/gems/delayed_job-4.1.2/lib/delayed/lifecycle.rb:66:in `execute'
/app/vendor/bundle/ruby/2.4.0/gems/delayed_job-4.1.2/lib/delayed/lifecycle.rb:40:in `run_callbacks'
/app/vendor/bundle/ruby/2.4.0/gems/delayed_job-4.1.2/lib/delayed/backend/base.rb:17:in `block in enqueue_job'
/app/vendor/bundle/ruby/2.4.0/gems/delayed_job-4.1.2/lib/delayed/backend/base.rb:16:in `tap'
/app/vendor/bundle/ruby/2.4.0/gems/delayed_job-4.1.2/lib/delayed/backend/base.rb:16:in `enqueue_job'
/app/vendor/bundle/ruby/2.4.0/gems/delayed_job-4.1.2/lib/delayed/backend/base.rb:12:in `enqueue'
/app/vendor/bundle/ruby/2.4.0/gems/activejob-5.0.1/lib/active_job/queue_adapters/delayed_job_adapter.rb:17:in `enqueue'
/app/vendor/bundle/ruby/2.4.0/gems/activejob-5.0.1/lib/active_job/enqueuing.rb:76:in `block in enqueue'
/app/vendor/bundle/ruby/2.4.0/gems/activesupport-5.0.1/lib/active_support/callbacks.rb:126:in `call'
/app/vendor/bundle/ruby/2.4.0/gems/activesupport-5.0.1/lib/active_support/callbacks.rb:506:in `block (2 levels) in compile'
/app/vendor/bundle/ruby/2.4.0/gems/activesupport-5.0.1/lib/active_support/callbacks.rb:455:in `call'
/app/vendor/bundle/ruby/2.4.0/gems/activesupport-5.0.1/lib/active_support/callbacks.rb:448:in `block (2 levels) in around'
/app/vendor/bundle/ruby/2.4.0/gems/activesupport-5.0.1/lib/active_support/callbacks.rb:286:in `block (2 levels) in halting'
/app/vendor/bundle/ruby/2.4.0/gems/activejob-5.0.1/lib/active_job/logging.rb:15:in `block (3 levels) in <module:Logging>'
/app/vendor/bundle/ruby/2.4.0/gems/activejob-5.0.1/lib/active_job/logging.rb:44:in `block in tag_logger'
/app/vendor/bundle/ruby/2.4.0/gems/activesupport-5.0.1/lib/active_support/tagged_logging.rb:69:in `block in tagged'
/app/vendor/bundle/ruby/2.4.0/gems/activesupport-5.0.1/lib/active_support/tagged_logging.rb:26:in `tagged'
/app/vendor/bundle/ruby/2.4.0/gems/activesupport-5.0.1/lib/active_support/tagged_logging.rb:69:in `tagged'
/app/vendor/bundle/ruby/2.4.0/gems/activejob-5.0.1/lib/active_job/logging.rb:44:in `tag_logger'
/app/vendor/bundle/ruby/2.4.0/gems/activejob-5.0.1/lib/active_job/logging.rb:14:in `block (2 levels) in <module:Logging>'
/app/vendor/bundle/ruby/2.4.0/gems/activesupport-5.0.1/lib/active_support/callbacks.rb:391:in `instance_exec'
/app/vendor/bundle/ruby/2.4.0/gems/activesupport-5.0.1/lib/active_support/callbacks.rb:391:in `block in make_lambda'
/app/vendor/bundle/ruby/2.4.0/gems/activesupport-5.0.1/lib/active_support/callbacks.rb:285:in `block in halting'
/app/vendor/bundle/ruby/2.4.0/gems/activesupport-5.0.1/lib/active_support/callbacks.rb:447:in `block in around'
/app/vendor/bundle/ruby/2.4.0/gems/activesupport-5.0.1/lib/active_support/callbacks.rb:455:in `call'
/app/vendor/bundle/ruby/2.4.0/gems/activesupport-5.0.1/lib/active_support/callbacks.rb:101:in `__run_callbacks__'
/app/vendor/bundle/ruby/2.4.0/gems/activesupport-5.0.1/lib/active_support/callbacks.rb:750:in `_run_enqueue_callbacks'
/app/vendor/bundle/ruby/2.4.0/gems/activesupport-5.0.1/lib/active_support/callbacks.rb:90:in `run_callbacks'
/app/vendor/bundle/ruby/2.4.0/gems/activejob-5.0.1/lib/active_job/enqueuing.rb:72:in `enqueue'
/app/vendor/bundle/ruby/2.4.0/gems/activejob-5.0.1/lib/active_job/enqueuing.rb:18:in `perform_later'
/app/Rakefile:30:in `block (2 levels) in <top (required)>'
/app/vendor/bundle/ruby/2.4.0/gems/activerecord-5.0.1/lib/active_record/relation/delegation.rb:38:in `each'
/app/vendor/bundle/ruby/2.4.0/gems/activerecord-5.0.1/lib/active_record/relation/delegation.rb:38:in `each'
/app/Rakefile:27:in `block in <top (required)>'
/app/vendor/bundle/ruby/2.4.0/gems/rake-11.3.0/lib/rake/task.rb:248:in `block in execute'
/app/vendor/bundle/ruby/2.4.0/gems/rake-11.3.0/lib/rake/task.rb:243:in `each'
/app/vendor/bundle/ruby/2.4.0/gems/rake-11.3.0/lib/rake/task.rb:243:in `execute'
/app/vendor/bundle/ruby/2.4.0/gems/rake-11.3.0/lib/rake/task.rb:187:in `block in invoke_with_call_chain'
/app/vendor/ruby-2.4.0/lib/ruby/2.4.0/monitor.rb:214:in `mon_synchronize'
/app/vendor/bundle/ruby/2.4.0/gems/rake-11.3.0/lib/rake/task.rb:180:in `invoke_with_call_chain'
/app/vendor/bundle/ruby/2.4.0/gems/rake-11.3.0/lib/rake/task.rb:173:in `invoke'
/app/vendor/bundle/ruby/2.4.0/gems/rake-11.3.0/lib/rake/application.rb:152:in `invoke_task'
/app/vendor/bundle/ruby/2.4.0/gems/rake-11.3.0/lib/rake/application.rb:108:in `block (2 levels) in top_level'
/app/vendor/bundle/ruby/2.4.0/gems/rake-11.3.0/lib/rake/application.rb:108:in `each'
/app/vendor/bundle/ruby/2.4.0/gems/rake-11.3.0/lib/rake/application.rb:108:in `block in top_level'
/app/vendor/bundle/ruby/2.4.0/gems/rake-11.3.0/lib/rake/application.rb:117:in `run_with_threads'
/app/vendor/bundle/ruby/2.4.0/gems/rake-11.3.0/lib/rake/application.rb:102:in `top_level'
/app/vendor/bundle/ruby/2.4.0/gems/rake-11.3.0/lib/rake/application.rb:80:in `block in run'
/app/vendor/bundle/ruby/2.4.0/gems/rake-11.3.0/lib/rake/application.rb:178:in `standard_exception_handling'
/app/vendor/bundle/ruby/2.4.0/gems/rake-11.3.0/lib/rake/application.rb:77:in `run'
/app/bin/rake:9:in `<main>'

我可以看出这可能是相关的:https://github.com/heroku/platform-api/issues/74

PS:我很确定 Rails 作业没有任何问题,因为我手动通过 rails c 执行了其中一个作业,一切顺利。

➜  git:(master) ✗ heroku run bash --remote=production
Running bash on ⬢ my-app-name... up, run.7883 (Hobby)
~ $ rails c
... some libs loading I removed ...
Loading production environment (Rails 5.0.1)
irb(main):001:0> o = Organization.find SOME_ID
D, [2018-02-28T04:39:43.711584 #5] DEBUG -- :   Organization Load (0.7ms)  SELECT  ...
irb(main):002:0> CountStudentsJob.perform_later o
D, [2018-02-28T04:40:02.466393 #5] DEBUG -- : [ActiveJob]    (0.7ms)  BEGIN ...
... here all goes good ...
I, [2018-02-28T04:40:02.916888 #5]  INFO -- : [ActiveJob] Enqueued CountStudentsJob (Job ID: cbba5507-44e5-417d-97e0-11539049784a) to DelayedJob(default) with arguments: #<GlobalID:0x000000070fdaf0 @uri=#<URI::GID gid:some-gid-id>>
irb(main):003:0>exit
~ $ rake recalculate_balances
... some libs loading I removed ...
... lots of organizations loads ...
... until it comes to the same SOME_ID from up ...
Scheduling :recalculate_balances for Organization SOME_ID
D, [2018-02-28T04:40:38.957868 #20] DEBUG -- : [ActiveJob]    (0.5ms)  BEGIN
D, [2018-02-28T04:40:38.960324 #20] DEBUG -- : [ActiveJob]   SQL (0.6ms)  INSERT INTO "delayed_jobs" ("handler", "run_at", "queue", "created_at", "updated_at") VALUES (, , , , ) RETURNING "id"  [["handler", "--- !ruby/object:ActiveJob::QueueAdapters::DelayedJobAdapter::JobWrapper\njob_data:\n  job_class: RecalculateBalancesJob\n  job_id: b41052b9-f964-4325-8736-36014bdf62c6\n  queue_name: default\n  priority: \n  arguments:\n  - _aj_globalid: gid:some-gid\n  locale: es\n"], ["run_at", 2018-02-28 04:40:38 UTC], ["queue", "default"], ["created_at", 2018-02-28 04:40:38 UTC], ["updated_at", 2018-02-28 04:40:38 UTC]]
D, [2018-02-28T04:40:38.962464 #20] DEBUG -- : [ActiveJob]    (1.6ms)  COMMIT
D, [2018-02-28T04:40:38.963943 #20] DEBUG -- : [ActiveJob]    (0.6ms)  SELECT COUNT(*) FROM "delayed_jobs" WHERE "delayed_jobs"."failed_at" IS NULL
D, [2018-02-28T04:40:39.045392 #20] DEBUG -- : [ActiveJob]    (1.0ms)  SELECT COUNT(*) FROM "delayed_jobs" WHERE "delayed_jobs"."failed_at" IS NULL
D, [2018-02-28T04:40:39.046998 #20] DEBUG -- : [ActiveJob]    (0.6ms)  SELECT COUNT(*) FROM "delayed_jobs" WHERE "delayed_jobs"."failed_at" IS NULL
Expected([200, 201, 202, 204, 206, 304]) <=> Actual(422 Unprocessable Entity)
... and the traceback ...

问题要么是 rake、DelayedJob、Workless(gem 对于 heroku workers management),要么是 Excon。

附加信息

我已将解决方案添加到答案中,并将此问题转换为问答,以防对其他人有用。

我在这里找到了打印消息的方法:https://github.com/heroku/platform-api/issues/50

消息是:

Excon error 
{
  "id": "cannot_update_above_limit",
  "limit": 1,
  "message": "Cannot update to more than 1 Hobby size dynos per process type.",
  "size": "Hobby",
  "url": "https://devcenter.heroku.com/articles/dyno-size#default-scaling-limits"
}

所以我联系了 Heroku 支持,因为我有一个 Hobby(首付计划,$7/dyno)帐户,他们回复:

Hi there,

The issues here is that for "hobby" dynos you cannot have more than one process type running at the same time. Dynos started using the scheduler add-on are all one-off dynos with a process type of "scheduler". If any of those scheduled tasks overlap then both them cannot run at the same time.

You can have one-off dynos started with the heroku run CLI command and the scheduler at the same time because heroku run one-off dynos have a process type of run.

我的调度程序作业没有重叠,我确信这一点是因为我的日志。所以我得出的结论是:

Because of using workless-gem, the workless attempts to start processing the jobs are going to fail until the scheduler finish its job of "scheduling" the jobs for the worker to execute.

(现在,再读一遍,背景音乐非常快)

同时,begin-rescue-end 将自己捕获并打印错误。

更新

感谢@geemus 的洞察力,我也将无用的 ENV 变量修改为 WORKLESS_MAX_WORKERS: '1',错误不再出现。这是因为 爱好 计划。