ActiveJob::DeserializationError thrown in sidekiq when registering new users
Right after a new user is submitted into Rails an ActiveJob::DeserializationError
exception was thrown in sidekiq, before the POST request even finishes. After the POST request finishes, sidekiq retries the task and it got successfully executed.
15:57:12 rails-background-jobs.1 | 2016-04-11T07:57:12.073Z 13630 TID-ox44yxmxs ActionMailer::DeliveryJob JID-c1685c96f57a64fa999b2d0d INFO: start
15:57:12 rails-background-jobs.1 | 2016-04-11T07:57:12.113Z 13630 TID-ox44yxmxs ActionMailer::DeliveryJob JID-c1685c96f57a64fa999b2d0d INFO: fail: 0.04 sec
15:57:12 rails-background-jobs.1 | 2016-04-11T07:57:12.113Z 13630 TID-ox44yxmxs WARN: {"class"=>"ActiveJob::QueueAdapters::SidekiqAdapter::JobWrapper", "wrapped"=>"ActionMailer::DeliveryJob", "queue"=>"mailers", "args"=>[{"job_class"=>"ActionMailer::DeliveryJob", "job_id"=>"daa05105-2c4d-4502-8676-fb76f7d5b87c", "queue_name"=>"mailers", "arguments"=>["DeviseMailer", "confirmation_instructions", "deliver_now", {"_aj_globalid"=>"gid://gitlab/User/4"}, "6DxBz-WWuig_B4xeDphK", {"_aj_symbol_keys"=>[]}], "locale"=>"en"}], "retry"=>true, "jid"=>"c1685c96f57a64fa999b2d0d", "created_at"=>1460361432.06764, "enqueued_at"=>1460361432.067986, "error_message"=>"Error while trying to deserialize arguments: Couldn't find User with 'id'=4", "error_class"=>"ActiveJob::DeserializationError", "failed_at"=>1460361432.112812, "retry_count"=>0}
15:57:12 rails-background-jobs.1 | 2016-04-11T07:57:12.113Z 13630 TID-ox44yxmxs WARN: ActiveJob::DeserializationError: Error while trying to deserialize arguments: Couldn't find User with 'id'=4
15:57:12 rails-background-jobs.1 | 2016-04-11T07:57:12.113Z 13630 TID-ox44yxmxs WARN: /Users/pmq20/.rvm/gems/ruby-2.1.8/gems/activerecord-4.2.6/lib/active_record/relation/finder_methods.rb:324:in `raise_record_not_found_exception!'
15:57:12 rails-background-jobs.1 | /Users/pmq20/.rvm/gems/ruby-2.1.8/gems/activerecord-4.2.6/lib/active_record/relation/finder_methods.rb:444:in `find_one'
15:57:12 rails-background-jobs.1 | /Users/pmq20/.rvm/gems/ruby-2.1.8/gems/activerecord-4.2.6/lib/active_record/relation/finder_methods.rb:423:in `find_with_ids'
15:57:12 rails-background-jobs.1 | /Users/pmq20/.rvm/gems/ruby-2.1.8/gems/activerecord-4.2.6/lib/active_record/relation/finder_methods.rb:71:in `find'
15:57:12 rails-background-jobs.1 | /Users/pmq20/.rvm/gems/ruby-2.1.8/gems/activerecord-4.2.6/lib/active_record/querying.rb:3:in `find'
15:57:12 rails-background-jobs.1 | /Users/pmq20/.rvm/gems/ruby-2.1.8/gems/activerecord-4.2.6/lib/active_record/core.rb:131:in `find'
15:57:12 rails-background-jobs.1 | /Users/pmq20/.rvm/gems/ruby-2.1.8/gems/globalid-0.3.6/lib/global_id/locator.rb:132:in `locate'
15:57:12 rails-background-jobs.1 | /Users/pmq20/.rvm/gems/ruby-2.1.8/gems/globalid-0.3.6/lib/global_id/locator.rb:158:in `block in locate'
15:57:12 rails-background-jobs.1 | /Users/pmq20/.rvm/gems/ruby-2.1.8/gems/activerecord-4.2.6/lib/active_record/scoping/default.rb:33:in `block in unscoped'
15:57:12 rails-background-jobs.1 | /Users/pmq20/.rvm/gems/ruby-2.1.8/gems/activerecord-4.2.6/lib/active_record/relation.rb:302:in `scoping'
15:57:12 rails-background-jobs.1 | /Users/pmq20/.rvm/gems/ruby-2.1.8/gems/activerecord-4.2.6/lib/active_record/scoping/default.rb:33:in `unscoped'
15:57:12 rails-background-jobs.1 | /Users/pmq20/.rvm/gems/ruby-2.1.8/gems/globalid-0.3.6/lib/global_id/locator.rb:158:in `locate'
15:57:12 rails-background-jobs.1 | /Users/pmq20/.rvm/gems/ruby-2.1.8/gems/globalid-0.3.6/lib/global_id/locator.rb:17:in `locate'
15:57:12 rails-background-jobs.1 | /Users/pmq20/.rvm/gems/ruby-2.1.8/gems/activejob-4.2.6/lib/active_job/arguments.rb:97:in `deserialize_global_id'
15:57:12 rails-background-jobs.1 | /Users/pmq20/.rvm/gems/ruby-2.1.8/gems/activejob-4.2.6/lib/active_job/arguments.rb:83:in `deserialize_argument'
15:57:12 rails-background-jobs.1 | /Users/pmq20/.rvm/gems/ruby-2.1.8/gems/activejob-4.2.6/lib/active_job/arguments.rb:40:in `block in deserialize'
15:57:12 rails-background-jobs.1 | /Users/pmq20/.rvm/gems/ruby-2.1.8/gems/activejob-4.2.6/lib/active_job/arguments.rb:40:in `map'
15:57:12 rails-background-jobs.1 | /Users/pmq20/.rvm/gems/ruby-2.1.8/gems/activejob-4.2.6/lib/active_job/arguments.rb:40:in `deserialize'
15:57:12 rails-background-jobs.1 | /Users/pmq20/.rvm/gems/ruby-2.1.8/gems/activejob-4.2.6/lib/active_job/core.rb:90:in `deserialize_arguments'
15:57:12 rails-background-jobs.1 | /Users/pmq20/.rvm/gems/ruby-2.1.8/gems/activejob-4.2.6/lib/active_job/core.rb:80:in `deserialize_arguments_if_needed'
15:57:12 rails-background-jobs.1 | /Users/pmq20/.rvm/gems/ruby-2.1.8/gems/activejob-4.2.6/lib/active_job/execution.rb:30:in `perform_now'
15:57:12 rails-background-jobs.1 | /Users/pmq20/.rvm/gems/ruby-2.1.8/gems/activejob-4.2.6/lib/active_job/execution.rb:21:in `execute'
15:57:12 rails-background-jobs.1 | /Users/pmq20/.rvm/gems/ruby-2.1.8/gems/activejob-4.2.6/lib/active_job/queue_adapters/sidekiq_adapter.rb:42:in `perform'
15:57:12 rails-background-jobs.1 | /Users/pmq20/.rvm/gems/ruby-2.1.8/gems/sidekiq-4.0.1/lib/sidekiq/processor.rb:150:in `execute_job'
15:57:12 rails-background-jobs.1 | /Users/pmq20/.rvm/gems/ruby-2.1.8/gems/sidekiq-4.0.1/lib/sidekiq/processor.rb:132:in `block (2 levels) in process'
15:57:12 rails-background-jobs.1 | /Users/pmq20/.rvm/gems/ruby-2.1.8/gems/sidekiq-4.0.1/lib/sidekiq/middleware/chain.rb:127:in `block in invoke'
15:57:12 rails-background-jobs.1 | /Users/pmq20/.rvm/gems/ruby-2.1.8/gems/sidekiq-4.0.1/lib/sidekiq/middleware/server/active_record.rb:6:in `call'
15:57:12 rails-background-jobs.1 | /Users/pmq20/.rvm/gems/ruby-2.1.8/gems/sidekiq-4.0.1/lib/sidekiq/middleware/chain.rb:129:in `block in invoke'
15:57:12 rails-background-jobs.1 | /Users/pmq20/.rvm/gems/ruby-2.1.8/gems/sidekiq-4.0.1/lib/sidekiq/middleware/server/retry_jobs.rb:74:in `call'
15:57:12 rails-background-jobs.1 | /Users/pmq20/.rvm/gems/ruby-2.1.8/gems/sidekiq-4.0.1/lib/sidekiq/middleware/chain.rb:129:in `block in invoke'
15:57:12 rails-background-jobs.1 | /Users/pmq20/.rvm/gems/ruby-2.1.8/gems/sidekiq-4.0.1/lib/sidekiq/middleware/server/logging.rb:11:in `block in call'
15:57:12 rails-background-jobs.1 | /Users/pmq20/.rvm/gems/ruby-2.1.8/gems/sidekiq-4.0.1/lib/sidekiq/logging.rb:30:in `with_context'
15:57:12 rails-background-jobs.1 | /Users/pmq20/.rvm/gems/ruby-2.1.8/gems/sidekiq-4.0.1/lib/sidekiq/middleware/server/logging.rb:7:in `call'
15:57:12 rails-background-jobs.1 | /Users/pmq20/.rvm/gems/ruby-2.1.8/gems/sidekiq-4.0.1/lib/sidekiq/middleware/chain.rb:129:in `block in invoke'
15:57:12 rails-background-jobs.1 | /Users/pmq20/.rvm/gems/ruby-2.1.8/gems/sidekiq-4.0.1/lib/sidekiq/middleware/chain.rb:132:in `call'
15:57:12 rails-background-jobs.1 | /Users/pmq20/.rvm/gems/ruby-2.1.8/gems/sidekiq-4.0.1/lib/sidekiq/middleware/chain.rb:132:in `invoke'
15:57:12 rails-background-jobs.1 | /Users/pmq20/.rvm/gems/ruby-2.1.8/gems/sidekiq-4.0.1/lib/sidekiq/processor.rb:127:in `block in process'
15:57:12 rails-background-jobs.1 | /Users/pmq20/.rvm/gems/ruby-2.1.8/gems/sidekiq-4.0.1/lib/sidekiq/processor.rb:166:in `stats'
15:57:12 rails-background-jobs.1 | /Users/pmq20/.rvm/gems/ruby-2.1.8/gems/sidekiq-4.0.1/lib/sidekiq/processor.rb:126:in `process'
15:57:12 rails-background-jobs.1 | /Users/pmq20/.rvm/gems/ruby-2.1.8/gems/sidekiq-4.0.1/lib/sidekiq/processor.rb:79:in `process_one'
15:57:12 rails-background-jobs.1 | /Users/pmq20/.rvm/gems/ruby-2.1.8/gems/sidekiq-4.0.1/lib/sidekiq/processor.rb:67:in `run'
15:57:12 rails-background-jobs.1 | /Users/pmq20/.rvm/gems/ruby-2.1.8/gems/sidekiq-4.0.1/lib/sidekiq/util.rb:16:in `watchdog'
15:57:12 rails-background-jobs.1 | /Users/pmq20/.rvm/gems/ruby-2.1.8/gems/sidekiq-4.0.1/lib/sidekiq/util.rb:24:in `block in safe_thread'
15:57:12 gitlab-workhorse.1 | localhost 127.0.0.1:58274 - - [2016-04-11 15:57:11.204168653 +0800 CST] "POST /users HTTP/1.1" 302 96 "http://localhost/users/sign_in" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_11_3) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/51.0.2695.0 Safari/537.36" 0.965981