NoMethodError on Sidekiq jobs on Rails 6.0.3.2

[hmatic]

trafficstars

We have been trying to upgrade to Rails 6.0.3.2 and there's issue with scout apm while executing jobs. We're getting following error on every job: NoMethodError: undefined method downcase' for {}:Hash`

Rails version: 6.0.3.2 Scout_apm version: 2.6.8 Sidekiq version: 5.0.0

Issue seems to be on this line: https://github.com/scoutapp/scout_apm_ruby/blob/master/lib/scout_apm/job_record.rb#L67

Im not that familiar with inside implementation of scout apm gem, but layer should have string in its "name" variable, but it has Hash instead.

[cschneid]

Could you try downgrading to scout apm 2.6.7 temporarily. I fixed another issue with Sidekiq, and I wonder if this is an unintended side effect.

[cschneid]

@hmatic Are you using ActiveJob, or "run-later" functionality in sidekiq? Trying to narrow down the situation you're seeing.

Are you seeing this issue newly on an upgraded Rails? Which version are you coming from?

[hmatic]

Could you try downgrading to scout apm 2.6.7 temporarily. I fixed another issue with Sidekiq, and I wonder if this is an unintended side effect.

I initially tried it on 2.6.0 and it was happening there aswell.

@hmatic Are you using ActiveJob, or "run-later" functionality in sidekiq? Trying to narrow down the situation you're seeing.

Are you seeing this issue newly on an upgraded Rails? Which version are you coming from?

Yes, we're using activejob. We are currently running rails 6.0.0 and issue doesn't exist there. We tried upgrading to 6.0.3.2 and that's when it started happening (on staging environment ofc).

[cschneid]

Thank you for the report - something must have changed in the ActiveJob payload between the ... patch releases... of Rails. I'll take a look.

[cschneid]

@hmatic I am not able to reproduce this locally. I have a new Rails 6.0.3.2, with ActiveJob set to sidekiq, and Sidekiq 5.0.0.

We capture the job name from Sidekiq's middleware API at https://github.com/scoutapp/scout_apm_ruby/blob/master/lib/scout_apm/background_job_integrations/sidekiq.rb#L88

When I put a debug line to dump msg, I get:

{"class"=>"ActiveJob::QueueAdapters::SidekiqAdapter::JobWrapper"
 "wrapped"=>"FooJob"
 "queue"=>"default"
 "args"=>[{"job_class"=>"FooJob"
 "job_id"=>"724ae354-f5e6-418b-97e6-e3ce3deb0318"
 "provider_job_id"=>nil
 "queue_name"=>"default"
 "priority"=>nil
 "arguments"=>[1]
 "executions"=>0
 "exception_executions"=>{}
 "locale"=>"en"
 "timezone"=>"UTC"
 "enqueued_at"=>"2020-06-29T18:27:20Z"}]
 "retry"=>true
 "jid"=>"cadfab0940b5106b5a6cb08f"
 "created_at"=>1593455240.1413648
 "enqueued_at"=>1593455240.1414034}

Where msg["wrapped"] is the expected FooJob class in my test.

Next Steps

:one: Do you have any other sidekiq or activejob plugins that may be changing this payload? :two: Are you calling .perform_later to enqueue, or some other approach? :three: Would you be willing to run a quick branch with some more debugging around how the name is being captured?

[hmatic]

Hey @cschneid , sorry for late answer.

1. I don't think we do
2. Yes, we're enqueuing all jobs with perform_later
3. Yes, we can run any branch you provide

[hmatic]

Hey @cschneid , any updates here?

[hmatic]

Any updates here?

[cschneid]

Hi @hmatic, sorry this got lost in the shuffle.

Could you add a middleware to sidekiq that simply logs the parameters passed into it? There's something weird going on with the shape of the data we expect, and the data that's actually coming through.

lib/sidekiq_dump_payload.rb

class SidekiqDumpPayload
    def call(worker, msg, queue)
      Rails.logger.info("SidekiqDumpPayload: \n#{worker.inspect},\nMessage: #{msg.inspect},\nQueue: #{queue.inspect}"
      yield
    end
end

config/initializers/sidekiq.rb

Sidekiq.configure_server do |config|
  config.server_middleware do |chain|
    chain.add SidekiqDumpPayload
  end
end

Feel free to adjust to dump to a file or another log, we just need to see what data is coming through.

Let me know what comes out, particularly in the msg.inspect section.

Post here (redacting whatever is needed), or email us at [email protected].

[hmatic]

Here's output of msg:

Message: {
  "retry"=>true,
  "queue"=>"critical",
  "class"=>"ActiveJob::QueueAdapters::SidekiqAdapter::JobWrapper",
  "wrapped"=>{},
  "args"=>[
    {
      "job_class"=>"MailerServiceJob",
      "job_id"=>"d8b2a739-54a7-498f-b4e0-508d5ddb3763",
      "provider_job_id"=>nil,
      "queue_name"=>"critical",
      "priority"=>nil,
      "arguments"=>[
        "/weekly_summaries",
        {
          "api_token"=>"redacted",
          "account_id"=>1,
          "_aj_symbol_keys"=>[
            "api_token",
            "account_id"
          ]
        }
      ],
      "executions"=>0,
      "exception_executions"=>{},
      "locale"=>"en",
      "timezone"=>"Zagreb",
      "enqueued_at"=>"2020-11-08T23:39:43Z"
    }
  ],
  "jid"=>"c919f33072e9d754a594f588",
  "created_at"=>1604878783.3325152,
  "acts_as_tenant"=>{
    "class"=>"Account",
    "id"=>1
  },
  "enqueued_at"=>1604878855.3264155,
  "error_message"=>"undefined method `downcase' for {}:Hash",
  "error_class"=>"NoMethodError",
  "failed_at"=>1604878785.3309312,
  "retry_count"=>1,
  "retried_at"=>1604878824.8162913
}

[rcugut]

I'm running into the exact same issue! Followed the steps recommended above, I get similar results.

My app is deployed to Heroku, using Scout as addon.

Ruby 2.7.0, Rails 6.0.3.4 Sidekiq 6.1.2 via ActiveJob scout_apm 2.6.10

No errors before having scout_apm. Getting errors after adding the scout_apm gem.

my solution => remove scout_apm :-) I have no choice right now

[rcugut]

A new observation I made lately:

@cschneid It seems that the scout_apm is actually just masking an underlying error from ActiveJob (backed by Sidekiq).

It's easy to reproduce with ActionMailer:

First, intentionally raise an error in one of the mailer methods: i.e. just add a first line in the method body like raise "fake error".

Then the 2 scenarios:

scout_apm disabled

Comment out scout_apm from the Gemfile and deploy. Trigger the mailer method with deliver_later. => in the sidekiq web console (or your logs) you'll see the clear error fake error triggered during sidekiq job run.

scout_apm enabled

Add scout_apm back in the Gemfile and deploy. Trigger the mailer method with deliver_later. => you won't see the "fake error" message anymore, but instead it will be masked by the error message reported in this issue: NoMethodError: undefined method `downcase' for {}:Hash and the entire underlying error's stacktrace is "replaced" with the error triggered by scout_apm:

/app/vendor/bundle/ruby/2.7.0/gems/scout_apm-2.6.10/lib/scout_apm/job_record.rb:67:in `hash'
/app/vendor/bundle/ruby/2.7.0/gems/scout_apm-2.6.10/lib/scout_apm/store.rb:270:in `block in merge_jobs!'
/app/vendor/bundle/ruby/2.7.0/gems/scout_apm-2.6.10/lib/scout_apm/store.rb:266:in `each'
/app/vendor/bundle/ruby/2.7.0/gems/scout_apm-2.6.10/lib/scout_apm/store.rb:266:in `merge_jobs!'
/app/vendor/bundle/ruby/2.7.0/gems/scout_apm-2.6.10/lib/scout_apm/store.rb:73:in `block in track_job!'
/app/vendor/bundle/ruby/2.7.0/gems/scout_apm-2.6.10/lib/scout_apm/store.rb:72:in `synchronize'
/app/vendor/bundle/ruby/2.7.0/gems/scout_apm-2.6.10/lib/scout_apm/store.rb:72:in `track_job!'
/app/vendor/bundle/ruby/2.7.0/gems/scout_apm-2.6.10/lib/scout_apm/layer_converters/job_converter.rb:57:in `record!'
/app/vendor/bundle/ruby/2.7.0/gems/scout_apm-2.6.10/lib/scout_apm/tracked_request.rb:337:in `block in record!'
/app/vendor/bundle/ruby/2.7.0/gems/scout_apm-2.6.10/lib/scout_apm/tracked_request.rb:336:in `each'
/app/vendor/bundle/ruby/2.7.0/gems/scout_apm-2.6.10/lib/scout_apm/tracked_request.rb:336:in `inject'
/app/vendor/bundle/ruby/2.7.0/gems/scout_apm-2.6.10/lib/scout_apm/tracked_request.rb:336:in `record!'
/app/vendor/bundle/ruby/2.7.0/gems/scout_apm-2.6.10/lib/scout_apm/synchronous_recorder.rb:27:in `record!'
/app/vendor/bundle/ruby/2.7.0/gems/scout_apm-2.6.10/lib/scout_apm/tracked_request.rb:241:in `stop_request'
/app/vendor/bundle/ruby/2.7.0/gems/scout_apm-2.6.10/lib/scout_apm/tracked_request.rb:131:in `stop_layer'
/app/vendor/bundle/ruby/2.7.0/gems/scout_apm-2.6.10/lib/scout_apm/background_job_integrations/sidekiq.rb:74:in `ensure in call'
/app/vendor/bundle/ruby/2.7.0/gems/scout_apm-2.6.10/lib/scout_apm/background_job_integrations/sidekiq.rb:74:in `call'
/app/vendor/bundle/ruby/2.7.0/gems/sidekiq-6.1.2/lib/sidekiq/middleware/chain.rb:140:in `block in invoke'
/app/vendor/bundle/ruby/2.7.0/gems/sentry-raven-2.13.0/lib/raven/integrations/sidekiq.rb:9:in `call'
/app/vendor/bundle/ruby/2.7.0/gems/sidekiq-6.1.2/lib/sidekiq/middleware/chain.rb:140:in `block in invoke'

[rcugut]

@cschneid and @hmatic I found the underlying root cause of this issue: JSON serialization.

There was a change in the Rails ActiveJob Sidekiq adapter which, by removing the to_s, breaks serialization for JSON of the class when using gems like yajl-ruby (and possibly others!?).

With a gem like yajl-ruby, when the ActiveJob is enqueued to be sent to Sidekiq adapter which then pushes it serialized as JSON to redis, the wrapped field ends up being serialized as a {} instead of the string name of the ruby class.

It affects the stack to deep for scout_apm to do much about it, although there may be workarounds (like getting the job_class and name from the args parameter instead of wrapped). But IMO this is much better to be addressed by either the Sidekiq creator (author of the Rails change mentioned above), or the yajl library team? :-)

For my project, the fix was to just remove the yajl-ruby gem from the Gemfile and to default back to the native Ruby JSON, and now everything works. However, I was using yajl for its increased performance, so I guess it will have to wait until there's a fix in any the two libs. Good news is I'm re-enabling scout_apm for our project now 🎉

[hmatic]

@rcugut good catch, problem is that yajl-ruby is not something that we enabled, but it came with money-historical-bank gem, so not quite sure that I can just get rid of it.

Not quite sure how to continue, seems like everyone is passing ball to others :)