NoMethodError on Sidekiq jobs on Rails 6.0.3.2 #342

hmatic · 2020-06-28T14:26:56Z

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.

The text was updated successfully, but these errors were encountered:

cschneid · 2020-06-29T16:07:28Z

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 · 2020-06-29T17:29:09Z

@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 · 2020-06-29T17:45:37Z

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 · 2020-06-29T17:48:37Z

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 · 2020-06-29T19:24:39Z

@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

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

hmatic · 2020-07-13T12:19:13Z

Hey @cschneid , sorry for late answer.

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

hmatic · 2020-08-16T17:40:16Z

Hey @cschneid , any updates here?

hmatic · 2020-10-15T09:04:59Z

Any updates here?

cschneid · 2020-10-21T16:47:41Z

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 · 2020-11-08T23:46:16Z

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 · 2020-11-13T19:28:57Z

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 · 2020-11-24T23:20:23Z

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 · 2020-11-28T01:02:56Z

@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 🎉

This is the wrapper that gets used when you use ad-hoc backgrounding with `MyClass.delay.myfunc(1,2,3)` We were just getting the name of the wrapper, and now we expand it out and read off the name of the actual function being called.

Currently `wrapped` is a String. Instead pass Class so that Sidekiq can get access to the ActiveJob and its configuration without having to constantize. I verified that `JobClass.to_s` == `"JobClass"` so serialization to JSON should not be affected. ```ruby > JSON.dump({"wrapped" => SomeJob}) => "{\"wrapped\":\"SomeJob\"}" ``` By having access to the ActiveJob class, Sidekiq can get access to any `sidekiq_options` which have been set on that ActiveJob type and serialize those options into Redis. https://github.com/mperham/sidekiq/blob/master/Changes.md#60

hmatic · 2020-12-07T05:25:25Z

@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 :)

rcugut mentioned this issue Nov 28, 2020

ensure wrapped is of type string, representing the AJ class name sidekiq/sidekiq#4751

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

NoMethodError on Sidekiq jobs on Rails 6.0.3.2 #342

NoMethodError on Sidekiq jobs on Rails 6.0.3.2 #342

hmatic commented Jun 28, 2020

cschneid commented Jun 29, 2020

cschneid commented Jun 29, 2020

hmatic commented Jun 29, 2020

cschneid commented Jun 29, 2020

cschneid commented Jun 29, 2020

hmatic commented Jul 13, 2020

hmatic commented Aug 16, 2020

hmatic commented Oct 15, 2020

cschneid commented Oct 21, 2020

hmatic commented Nov 8, 2020 •

edited

Loading

rcugut commented Nov 13, 2020 •

edited

Loading

rcugut commented Nov 24, 2020

rcugut commented Nov 28, 2020 •

edited

Loading

hmatic commented Dec 7, 2020

NoMethodError on Sidekiq jobs on Rails 6.0.3.2 #342

NoMethodError on Sidekiq jobs on Rails 6.0.3.2 #342

Comments

hmatic commented Jun 28, 2020

cschneid commented Jun 29, 2020

cschneid commented Jun 29, 2020

hmatic commented Jun 29, 2020

cschneid commented Jun 29, 2020

cschneid commented Jun 29, 2020

Next Steps

hmatic commented Jul 13, 2020

hmatic commented Aug 16, 2020

hmatic commented Oct 15, 2020

cschneid commented Oct 21, 2020

lib/sidekiq_dump_payload.rb

config/initializers/sidekiq.rb

hmatic commented Nov 8, 2020 • edited Loading

rcugut commented Nov 13, 2020 • edited Loading

rcugut commented Nov 24, 2020

scout_apm disabled

scout_apm enabled

rcugut commented Nov 28, 2020 • edited Loading

hmatic commented Dec 7, 2020

hmatic commented Nov 8, 2020 •

edited

Loading

rcugut commented Nov 13, 2020 •

edited

Loading

rcugut commented Nov 28, 2020 •

edited

Loading