RuntimeError: can't add a new key into hash during iteration in middleware

[YushengLi]

Describe the bug

After upgrade from sentry-raven to sentry-ruby, we noticed the random exception RuntimeError: can't add a new key into hash during iteration in middleware reported within middlewares

We never got the exception while using sentry-raven, it only starts happening after the upgrade, and we are still trying to rule out the root cause

Here's the list of all middlewares we have so far

$ rails middleware

use Slowpoke::Middleware # `slowpole`
use Sentry::Rails::CaptureExceptions
use Rack::Cors # `rack-cors`
use Rack::Rewrite
use Rack::Sendfile
use ActionDispatch::Static
use ActionDispatch::Executor
use ActiveSupport::Cache::Strategy::LocalCache::Middleware
use Rack::Runtime
use Rack::MethodOverride
use ActionDispatch::RequestId
use RequestStore::Middleware
use ActionDispatch::RemoteIp
use Sprockets::Rails::QuietAssets # `sprockets-redirect`
use Rails::Rack::Logger
use ActionDispatch::ShowExceptions
use ActionDispatch::DebugExceptions
use Rack::Timeout
use ScoutApm::ErrorService::Middleware # `scout_apm`
use ActionDispatch::Callbacks
use ActionDispatch::Cookies
use ActionDispatch::Session::CookieStore
use ActionDispatch::Flash
use ActionDispatch::ContentSecurityPolicy::Middleware
use Rack::Head
use Rack::ConditionalGet
use Rack::ETag
use Rack::TempfileReaper
use Warden::Manager
use ScoutApm::Middleware # `scout_apm`
use Sentry::Rails::RescuedExceptionInterceptor
use HttpAcceptLanguage::Middleware # `http_accept_language`
use OmniAuth::Strategies::Facebook
run Application.routes

Backtrace of the exception

RuntimeError: can't add a new key into hash during iteration
  from rack/request.rb:79:in `set_header'
  from action_dispatch/http/request.rb:299:in `request_id='
  from action_dispatch/middleware/request_id.rb:26:in `call'
  from rack/method_override.rb:24:in `call'
  from rack/runtime.rb:22:in `call'
  from active_support/cache/strategy/local_cache_middleware.rb:29:in `call'
  from action_dispatch/middleware/executor.rb:14:in `call'
  from action_dispatch/middleware/static.rb:127:in `call'
  from rack/sendfile.rb:110:in `call'
  from action_dispatch/middleware/ssl.rb:74:in `call'
  from rack/rewrite.rb:24:in `call'
  from rack/cors.rb:100:in `call'
  from sentry/rack/capture_exceptions.rb:23:in `block in call'
  from sentry/hub.rb:50:in `with_scope'
  from sentry-ruby.rb:114:in `with_scope'
  from sentry/rack/capture_exceptions.rb:14:in `call'
  from slowpoke/middleware.rb:8:in `call'
  from scout_apm/instruments/middleware_summary.rb:58:in `call'
  from rails/engine.rb:524:in `call'
  from puma/configuration.rb:246:in `call'
  from puma/request.rb:76:in `block in handle_request'
  from puma/thread_pool.rb:337:in `with_force_shutdown'
  from puma/request.rb:75:in `handle_request'
  from puma/server.rb:431:in `process_client'
  from puma/thread_pool.rb:145:in `block in spawn_thread'

To Reproduce

Here's the tricky part, the exception happens randomly, I haven't figured out a way to reproduce the exception 100%.

Expected behavior

Actual behavior

Environment

• Ruby Version: 2.7.2
• SDK Version: 4.1.2 (sentry-ruby, sentry-rails, sentry-sidekiq enabled)
• Integration Versions (if any):
  • Rails: 5.2.4.4
  • Sidekiq 6.1.2

Sentry Config

This is not necessary but could be helpful.

Sentry.init do |config|
  config.dsn = ENV['SENTRY_DSN']
  config.enabled_environments = %w[staging production]
  config.release = ENV['GIT_COMMIT']
  config.excluded_exceptions += %w[
    Rack::Timeout::RequestTimeoutError
    ActionController::UnknownFormat
    Faraday::TimeoutError
    Pundit::NotAuthorizedError
    Async::Container::Terminate
    Interrupt
    Koala::Facebook::ServerError
  ]
  config.breadcrumbs_logger = [:active_support_logger]
  config.send_default_pii = true
  config.traces_sample_rate = 0.8
end

[st0012]

thanks for the detailed report 👍

this looks like a concurrency issue to me, which is that when Rails' ActionDispatch::RequestId middleware was assigning the request id to the headers, something else also had a copy of the request env and was iterating it. and I think I know what's causing it. here are some contexts:

• Sentry holds a copy of the request env and iterates it when preparing an event.
• Sentry now sends events asynchronously. which means the request will continue when the SDK is preparing the event.

so it's possible that when a request triggered an event (whether it's an exception or message event),

• the request happened to go through ActionDispatch::RequestId (add a new key into hash)
• while the SDK was processing the headers for preparing the event (performing the iteration)

to confirm my hypothesis, can you add this to your config?

Sentry.init do |config|
  config.background_worker_threads = 0
  # other configs
end

this will make the SDK send events synchronously again (just like sentry-raven). and if this stops the issue, then I think my guess is correct.

Possible Fix

assume my diagnose is correct, the fix would probably be like:

module Sentry
  class Scope
    def apply_to_event(event, hint = nil)
      event.tags = tags.merge(event.tags)
      event.user = user.merge(event.user)
      event.extra = extra.merge(event.extra)
      event.contexts = contexts.merge(event.contexts)

      if span
        event.contexts[:trace] = span.get_trace_context
      end

      event.fingerprint = fingerprint
      event.level = level
      event.transaction = transaction_names.last
      event.breadcrumbs = breadcrumbs
      # used to be event.rack_env = rack_env if rack_env
      event.rack_env = rack_env.dup if rack_env

      unless @event_processors.empty?
        @event_processors.each do |processor_block|
          event = processor_block.call(event, hint)
        end
      end

      event
    end
  end
end

---

Update: the above assumption seems to be incorrect.

The Scope#apply_to_event is called synchronously during the request, whether before/after the ActionDispatch::RequestId is ran. So it's not likely that the header processing could happen while the request id is assigned.

[st0012]

Here are some (possibly) related issues I found online:

• RuntimeError: can't add a new key into hash during iteration rack/rack#589
• https://stackoverflow.com/questions/47768547/runtimeerror-cant-add-a-new-key-into-hash-during-iteration-in-rack

What they and this issue have in common are:

1. The error happens when setting new values to the env hash.
2. The root cause is likely the middleware of a monitoring SDK the user uses: airbrake vs new_relic vs sentry-ruby.

Although there isn't a stable way to reproduce such issues yet, avoid sharing the env data should be a solid solution. So I have added #1186 to give it a try.

[st0012]

@YushengLi I can't confirm if the PR fixes the issue as I can't reproduce it myself. So please reopen it if you still encounter the same problem after the 4.1.3 release.

[YushengLi]

Sorry for the slow reply, finally got time to upgrade Sentry Ruby to 4.1.3

After the upgrade, the error still gets reported but less frequently compared with 4.1.2

Also, I would like to ask if Sentry Rails tracing is production-ready. I can only saw operation rails.request, yet sql. active_record , process_action. action_controller and other action_view related events are not being recorded.

[sl0thentr0py]

@st0012 imo the json serialization/deserialization/rescue is kinda hacky, maybe we should come up with more explicit logic to decide what goes into the breadcrumb hash?

[st0012]

I went through ActiveSupport Notification's doc, and it looks like the only remaining values that may be problematic to us would be connection and perhaps binds, which of both are from the sql.active_record event. So if we add them to the IGNORED_DATA_TYPES list, we should avoid most of the problems from Rails itself.

And on top of that, we can also filter out non-primitive objects, which should also avoid the span from datadog and reduce the chance of similar issues to pretty low.

[st0012]

Actually, after checking the edge Rails guide, the data that will NOT be caught by the above approach will grow quite a bit, such as:

• render_template.action_view's locals
• enqueue_all.active_job's jobs
• process.action_mailbox's mailbox
• And probably a couple more

So I agree that we should probably update our approach on this. I imagine the solution will be pretty similar to a hash like:

{
  "sql.active_record" => {
    allowed_data: [:sql, :name]
  },
  "start_processing.action_controller" => {
    allowed_data: [:controller, :action, :method, :path, :format]
  },
  # ... 
}

And we only subscribe to those events and include those data.

[github-actions]

This issue has gone three weeks without activity. In another week, I will close it.

But! If you comment or otherwise update it, I will reset the clock, and if you label it Status: Backlog or Status: In Progress, I will leave it alone ... forever!

---

"A weed is but an unloved flower." ― Ella Wheeler Wilcox 🥀

[colszowka]

This isn't stale, based on previous comments