My Rails application, deployed in Heroku, uses some rake tasks I have defined and scheduled to be executed once a day. Very simple tasks that the only thing they do, is add some jobs to the DelajedJobs table, so a worker gets up and execute them.
Some days ago, all rake jobs started failing. Some example of one of those:
# Rakefile
desc 'Update balances of all organizations'
task recalculate_balances: :environment do
Organization.all.each do |organization|
RecalculateBalancesJob.perform_later(organization)
end
end
And I saw this exception in my Rollbar account:
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>
So what I did was covering with a begin rescue end block, to avoid losing the work there, but I keep seeing same error. There's nothing that gives me a clue about what could be happening. Here's the complete stack trace:
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>'
I can see this could be related: https://github.com/heroku/platform-api/issues/74
PS: I'm pretty sure there's nothing wrong with the Rails Jobs, because I went manually via rails c, executed one of them, and it all went good.
➜ 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 ($1, $2, $3, $4, $5) 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 ...
Issue is either with rake, DelayedJob, Workless (gem for heroku workers management), or Excon.
I have added the resolution in an answer and converted this question to a Q&A in case is useful for somebody else.
I have found the way to print the message here: https://github.com/heroku/platform-api/issues/50
And the message was:
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"
}
So I have contacted with Heroku Support, because I have a Hobby (first paid plan, $7/dyno) account, and they responded:
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.
My scheduler jobs does not overlap, I am sure of that because of my logs. So I have came to the conclusion that:
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.
(Now, read it again really fast with a rap track in the background).
Meanwhile, a begin-rescue-end will work to catch and print the errors by myself.
Thanks to @geemus insight, I have also modified the workless ENV variable to WORKLESS_MAX_WORKERS: '1', and error stopped appearing. This because of the Hobby plan.