RuntimeError - can't add a new key into hash during iteration

[bronson]

Got this backtrace in development mode while using my app... The page crashed instead of rendering. Haven't managed to reproduce it though. Tried a few times, both with and without clearing the cache first.

RuntimeError - can't add a new key into hash during iteration:
  /Users/bronson/.rubies/ruby-2.2.2/lib/ruby/2.2.0/set.rb:151:in `replace'
  /Users/bronson/.rubies/ruby-2.2.2/lib/ruby/2.2.0/set.rb:347:in `collect!'
  sprockets (3.5.2) lib/sprockets/loader.rb:85:in `asset_from_cache'
  sprockets (3.5.2) lib/sprockets/loader.rb:57:in `block in load'
  sprockets (3.5.2) lib/sprockets/loader.rb:312:in `block in fetch_asset_from_dependency_cache'
  sprockets (3.5.2) lib/sprockets/loader.rb:308:in `fetch_asset_from_dependency_cache'
  sprockets (3.5.2) lib/sprockets/loader.rb:44:in `load'
  sprockets (3.5.2) lib/sprockets/cached_environment.rb:20:in `block in initialize'
  sprockets (3.5.2) lib/sprockets/cached_environment.rb:47:in `load'
  sprockets (3.5.2) lib/sprockets/base.rb:66:in `find_asset'
  sprockets (3.5.2) lib/sprockets/base.rb:92:in `[]'
  sprockets-rails (3.0.1) lib/sprockets/rails/helper.rb:342:in `find_asset'
  sprockets-rails (3.0.1) lib/sprockets/rails/helper.rb:323:in `digest_path'
  sprockets-rails (3.0.1) lib/sprockets/rails/helper.rb:312:in `asset_path'
  sprockets-rails (3.0.1) lib/sprockets/rails/helper.rb:90:in `block in resolve_asset_path'
  sprockets-rails (3.0.1) lib/sprockets/rails/helper.rb:230:in `block in resolve_asset'
  sprockets-rails (3.0.1) lib/sprockets/rails/helper.rb:229:in `resolve_asset'
  sprockets-rails (3.0.1) lib/sprockets/rails/helper.rb:89:in `resolve_asset_path'
  sprockets-rails (3.0.1) lib/sprockets/rails/helper.rb:79:in `compute_asset_path'
  actionview (5.0.0.beta2) lib/action_view/helpers/asset_url_helper.rb:144:in `asset_path'
  actionview (5.0.0.beta2) lib/action_view/helpers/asset_url_helper.rb:281:in `stylesheet_path'
  sprockets-rails (3.0.1) lib/sprockets/rails/helper.rb:161:in `block (2 levels) in stylesheet_link_tag'
  sprockets-rails (3.0.1) lib/sprockets/rails/helper.rb:160:in `block in stylesheet_link_tag'
  sprockets-rails (3.0.1) lib/sprockets/rails/helper.rb:157:in `stylesheet_link_tag'
  app/views/layouts/print.html.haml:9:in `_app_views_layouts_print_html_haml__1453697812607104007_70324318851660'
  actionview (5.0.0.beta2) lib/action_view/template.rb:159:in `block in render'
  activesupport (5.0.0.beta2) lib/active_support/notifications.rb:166:in `instrument'
  actionview (5.0.0.beta2) lib/action_view/template.rb:353:in `instrument'
  actionview (5.0.0.beta2) lib/action_view/template.rb:157:in `render'
  actionview (5.0.0.beta2) lib/action_view/renderer/template_renderer.rb:66:in `render_with_layout'
  actionview (5.0.0.beta2) lib/action_view/renderer/template_renderer.rb:52:in `render_template'
  actionview (5.0.0.beta2) lib/action_view/renderer/template_renderer.rb:14:in `render'
  actionview (5.0.0.beta2) lib/action_view/renderer/renderer.rb:42:in `render_template'
  actionview (5.0.0.beta2) lib/action_view/renderer/renderer.rb:23:in `render'
  actionview (5.0.0.beta2) lib/action_view/rendering.rb:103:in `_render_template'
  actionpack (5.0.0.beta2) lib/action_controller/metal/streaming.rb:217:in `_render_template'
  actionview (5.0.0.beta2) lib/action_view/rendering.rb:83:in `render_to_body'
  actionpack (5.0.0.beta2) lib/action_controller/metal/rendering.rb:52:in `render_to_body'
  actionpack (5.0.0.beta2) lib/action_controller/metal/renderers.rb:144:in `render_to_body'
  actionpack (5.0.0.beta2) lib/abstract_controller/rendering.rb:25:in `render'
  actionpack (5.0.0.beta2) lib/action_controller/metal/rendering.rb:36:in `render'
  actionpack (5.0.0.beta2) lib/action_controller/metal/instrumentation.rb:43:in `block (2 levels) in render'
  activesupport (5.0.0.beta2) lib/active_support/core_ext/benchmark.rb:12:in `block in ms'
  /Users/bronson/.rubies/ruby-2.2.2/lib/ruby/2.2.0/benchmark.rb:303:in `realtime'
  activesupport (5.0.0.beta2) lib/active_support/core_ext/benchmark.rb:12:in `ms'
  actionpack (5.0.0.beta2) lib/action_controller/metal/instrumentation.rb:43:in `block in render'
  actionpack (5.0.0.beta2) lib/action_controller/metal/instrumentation.rb:86:in `cleanup_view_runtime'
  activerecord (5.0.0.beta2) lib/active_record/railties/controller_runtime.rb:25:in `cleanup_view_runtime'
  actionpack (5.0.0.beta2) lib/action_controller/metal/instrumentation.rb:42:in `render'
  app/controllers/comparisons_controller.rb:13:in `print'
  actionpack (5.0.0.beta2) lib/action_controller/metal/basic_implicit_render.rb:4:in `send_action'
  actionpack (5.0.0.beta2) lib/abstract_controller/base.rb:183:in `process_action'
  actionpack (5.0.0.beta2) lib/action_controller/metal/rendering.rb:30:in `process_action'
  actionpack (5.0.0.beta2) lib/abstract_controller/callbacks.rb:20:in `block in process_action'
  activesupport (5.0.0.beta2) lib/active_support/callbacks.rb:126:in `call'
  activesupport (5.0.0.beta2) lib/active_support/callbacks.rb:506:in `block (2 levels) in compile'
  activesupport (5.0.0.beta2) lib/active_support/callbacks.rb:455:in `call'
  activesupport (5.0.0.beta2) lib/active_support/callbacks.rb:101:in `__run_callbacks__'
  activesupport (5.0.0.beta2) lib/active_support/callbacks.rb:750:in `_run_process_action_callbacks'
  activesupport (5.0.0.beta2) lib/active_support/callbacks.rb:90:in `run_callbacks'
  actionpack (5.0.0.beta2) lib/abstract_controller/callbacks.rb:19:in `process_action'
  actionpack (5.0.0.beta2) lib/action_controller/metal/rescue.rb:27:in `process_action'
  actionpack (5.0.0.beta2) lib/action_controller/metal/instrumentation.rb:31:in `block in process_action'
  activesupport (5.0.0.beta2) lib/active_support/notifications.rb:164:in `block in instrument'
  activesupport (5.0.0.beta2) lib/active_support/notifications/instrumenter.rb:21:in `instrument'
  activesupport (5.0.0.beta2) lib/active_support/notifications.rb:164:in `instrument'
  actionpack (5.0.0.beta2) lib/action_controller/metal/instrumentation.rb:29:in `process_action'
  actionpack (5.0.0.beta2) lib/action_controller/metal/params_wrapper.rb:248:in `process_action'
  activerecord (5.0.0.beta2) lib/active_record/railties/controller_runtime.rb:18:in `process_action'
  actionpack (5.0.0.beta2) lib/abstract_controller/base.rb:128:in `process'
  actionview (5.0.0.beta2) lib/action_view/rendering.rb:30:in `process'
  actionpack (5.0.0.beta2) lib/action_controller/metal.rb:193:in `dispatch'
  actionpack (5.0.0.beta2) lib/action_controller/metal.rb:265:in `dispatch'
  actionpack (5.0.0.beta2) lib/action_dispatch/routing/route_set.rb:50:in `dispatch'
  actionpack (5.0.0.beta2) lib/action_dispatch/routing/route_set.rb:32:in `serve'
  actionpack (5.0.0.beta2) lib/action_dispatch/journey/router.rb:42:in `block in serve'
  actionpack (5.0.0.beta2) lib/action_dispatch/journey/router.rb:29:in `serve'
  actionpack (5.0.0.beta2) lib/action_dispatch/routing/route_set.rb:724:in `call'
  actionview (5.0.0.beta2) lib/action_view/digestor.rb:14:in `call'
  rack (2.0.0.alpha) lib/rack/etag.rb:25:in `call'
  rack (2.0.0.alpha) lib/rack/conditional_get.rb:25:in `call'
  rack (2.0.0.alpha) lib/rack/head.rb:12:in `call'
  actionpack (5.0.0.beta2) lib/action_dispatch/middleware/cookies.rb:608:in `call'
  activerecord (5.0.0.beta2) lib/active_record/query_cache.rb:36:in `call'
  activerecord (5.0.0.beta2) lib/active_record/connection_adapters/abstract/connection_pool.rb:963:in `call'
  activerecord (5.0.0.beta2) lib/active_record/migration.rb:558:in `call'
  actionpack (5.0.0.beta2) lib/action_dispatch/middleware/callbacks.rb:29:in `block in call'
  activesupport (5.0.0.beta2) lib/active_support/callbacks.rb:97:in `__run_callbacks__'
  activesupport (5.0.0.beta2) lib/active_support/callbacks.rb:750:in `_run_call_callbacks'
  activesupport (5.0.0.beta2) lib/active_support/callbacks.rb:90:in `run_callbacks'
  actionpack (5.0.0.beta2) lib/action_dispatch/middleware/callbacks.rb:27:in `call'
  actionpack (5.0.0.beta2) lib/action_dispatch/middleware/reloader.rb:71:in `call'
  actionpack (5.0.0.beta2) lib/action_dispatch/middleware/remote_ip.rb:79:in `call'
  better_errors (2.1.1) lib/better_errors/middleware.rb:84:in `protected_app_call'
  better_errors (2.1.1) lib/better_errors/middleware.rb:79:in `better_errors_call'
  better_errors (2.1.1) lib/better_errors/middleware.rb:57:in `call'
  actionpack (5.0.0.beta2) lib/action_dispatch/middleware/debug_exceptions.rb:49:in `call'
  actionpack (5.0.0.beta2) lib/action_dispatch/middleware/show_exceptions.rb:31:in `call'
  railties (5.0.0.beta2) lib/rails/rack/logger.rb:36:in `call_app'
  railties (5.0.0.beta2) lib/rails/rack/logger.rb:24:in `block in call'
  activesupport (5.0.0.beta2) lib/active_support/tagged_logging.rb:70:in `block in tagged'
  activesupport (5.0.0.beta2) lib/active_support/tagged_logging.rb:26:in `tagged'
  activesupport (5.0.0.beta2) lib/active_support/tagged_logging.rb:70:in `tagged'
  railties (5.0.0.beta2) lib/rails/rack/logger.rb:24:in `call'
  actionpack (5.0.0.beta2) lib/action_dispatch/middleware/request_id.rb:24:in `call'
  rack (2.0.0.alpha) lib/rack/method_override.rb:22:in `call'
  rack (2.0.0.alpha) lib/rack/runtime.rb:22:in `call'
  activesupport (5.0.0.beta2) lib/active_support/cache/strategy/local_cache_middleware.rb:28:in `call'
  actionpack (5.0.0.beta2) lib/action_dispatch/middleware/load_interlock.rb:13:in `call'
  actionpack (5.0.0.beta2) lib/action_dispatch/middleware/static.rb:136:in `call'
  rack (2.0.0.alpha) lib/rack/sendfile.rb:111:in `call'
  railties (5.0.0.beta2) lib/rails/engine.rb:522:in `call'
  rack (2.0.0.alpha) lib/rack/handler/webrick.rb:86:in `service'
  /Users/bronson/.rubies/ruby-2.2.2/lib/ruby/2.2.0/webrick/httpserver.rb:138:in `service'
  /Users/bronson/.rubies/ruby-2.2.2/lib/ruby/2.2.0/webrick/httpserver.rb:94:in `run'
  /Users/bronson/.rubies/ruby-2.2.2/lib/ruby/2.2.0/webrick/server.rb:294:in `block in start_thread'

[kaukas]

I am experiencing this as well. It is not consistent but I can rarely compile all assets without getting it at least once.

Looks like some kind of a race condition to me. We have a lot of small files. Perhaps the more files you need to compile the more likely you are to get this error. The code in sprockets loader.rb file performs a lot of in-place modifications. Maybe some other thread is iterating over those same keys at the same time?

[martinpovolny]

Same for me:

[----] F, [2016-04-14T14:39:20.360658 #29342:196d060] FATAL -- : Error caught: [RuntimeError] can't add a new key into hash during iteration
/home/martin/.rvm/rubies/ruby-2.2.2/lib/ruby/2.2.0/set.rb:151:in `replace'
/home/martin/.rvm/rubies/ruby-2.2.2/lib/ruby/2.2.0/set.rb:151:in `replace'
/home/martin/.rvm/rubies/ruby-2.2.2/lib/ruby/2.2.0/set.rb:347:in `collect!'
/home/martin/.rvm/gems/ruby-2.2.2@cfme/gems/sprockets-3.6.0/lib/sprockets/loader.rb:85:in `asset_from_cache'
/home/martin/.rvm/gems/ruby-2.2.2@cfme/gems/sprockets-3.6.0/lib/sprockets/loader.rb:57:in `block in load'
/home/martin/.rvm/gems/ruby-2.2.2@cfme/gems/sprockets-3.6.0/lib/sprockets/loader.rb:311:in `block in fetch_asset_from_dependency_cache'
/home/martin/.rvm/gems/ruby-2.2.2@cfme/gems/sprockets-3.6.0/lib/sprockets/loader.rb:307:in `each'
/home/martin/.rvm/gems/ruby-2.2.2@cfme/gems/sprockets-3.6.0/lib/sprockets/loader.rb:307:in `each_with_index'
/home/martin/.rvm/gems/ruby-2.2.2@cfme/gems/sprockets-3.6.0/lib/sprockets/loader.rb:307:in `fetch_asset_from_dependency_cache'
/home/martin/.rvm/gems/ruby-2.2.2@cfme/gems/sprockets-3.6.0/lib/sprockets/loader.rb:44:in `load'
/home/martin/.rvm/gems/ruby-2.2.2@cfme/gems/sprockets-3.6.0/lib/sprockets/cached_environment.rb:20:in `block in initialize'
/home/martin/.rvm/gems/ruby-2.2.2@cfme/gems/sprockets-3.6.0/lib/sprockets/cached_environment.rb:47:in `yield'
/home/martin/.rvm/gems/ruby-2.2.2@cfme/gems/sprockets-3.6.0/lib/sprockets/cached_environment.rb:47:in `load'
/home/martin/.rvm/gems/ruby-2.2.2@cfme/gems/sprockets-3.6.0/lib/sprockets/base.rb:66:in `find_asset'
/home/martin/.rvm/gems/ruby-2.2.2@cfme/gems/sprockets-3.6.0/lib/sprockets/base.rb:92:in `[]'
/home/martin/.rvm/gems/ruby-2.2.2@cfme/gems/sprockets-rails-3.0.4/lib/sprockets/rails/helper.rb:341:in `find_asset'
/home/martin/.rvm/gems/ruby-2.2.2@cfme/gems/sprockets-rails-3.0.4/lib/sprockets/rails/helper.rb:322:in `digest_path'
/home/martin/.rvm/gems/ruby-2.2.2@cfme/gems/sprockets-rails-3.0.4/lib/sprockets/rails/helper.rb:311:in `asset_path'
/home/martin/.rvm/gems/ruby-2.2.2@cfme/gems/sprockets-rails-3.0.4/lib/sprockets/rails/helper.rb:89:in `block in resolve_asset_path'
/home/martin/.rvm/gems/ruby-2.2.2@cfme/gems/sprockets-rails-3.0.4/lib/sprockets/rails/helper.rb:229:in `block in resolve_asset'
/home/martin/.rvm/gems/ruby-2.2.2@cfme/gems/sprockets-rails-3.0.4/lib/sprockets/rails/helper.rb:228:in `each'
/home/martin/.rvm/gems/ruby-2.2.2@cfme/gems/sprockets-rails-3.0.4/lib/sprockets/rails/helper.rb:228:in `detect'
/home/martin/.rvm/gems/ruby-2.2.2@cfme/gems/sprockets-rails-3.0.4/lib/sprockets/rails/helper.rb:228:in `resolve_asset'
/home/martin/.rvm/gems/ruby-2.2.2@cfme/gems/sprockets-rails-3.0.4/lib/sprockets/rails/helper.rb:88:in `resolve_asset_path'
/home/martin/.rvm/gems/ruby-2.2.2@cfme/gems/sprockets-rails-3.0.4/lib/sprockets/rails/helper.rb:78:in `compute_asset_path'
/home/martin/.rvm/gems/ruby-2.2.2@cfme/bundler/gems/rails-53ab1ee5652e/actionview/lib/action_view/helpers/asset_url_helper.rb:144:in `asset_path'
/home/martin/.rvm/gems/ruby-2.2.2@cfme/bundler/gems/rails-53ab1ee5652e/actionview/lib/action_view/helpers/asset_url_helper.rb:281:in `stylesheet_path'
/home/martin/.rvm/gems/ruby-2.2.2@cfme/gems/sprockets-rails-3.0.4/lib/sprockets/rails/helper.rb:160:in `block (2 levels) in stylesheet_link_tag'
/home/martin/.rvm/gems/ruby-2.2.2@cfme/gems/sprockets-rails-3.0.4/lib/sprockets/rails/helper.rb:159:in `map'
/home/martin/.rvm/gems/ruby-2.2.2@cfme/gems/sprockets-rails-3.0.4/lib/sprockets/rails/helper.rb:159:in `block in stylesheet_link_tag'
/home/martin/.rvm/gems/ruby-2.2.2@cfme/gems/sprockets-rails-3.0.4/lib/sprockets/rails/helper.rb:156:in `map'
/home/martin/.rvm/gems/ruby-2.2.2@cfme/gems/sprockets-rails-3.0.4/lib/sprockets/rails/helper.rb:156:in `stylesheet_link_tag'
/home/martin/Projects/manageiq-2/app/views/layouts/application.html.haml:26:in `_app_views_layouts_application_html_haml__2777982366737568467_70121407000000'
/home/martin/.rvm/gems/ruby-2.2.2@cfme/bundler/gems/rails-53ab1ee5652e/actionview/lib/action_view/template.rb:158:in `block in render'
/home/martin/.rvm/gems/ruby-2.2.2@cfme/bundler/gems/rails-53ab1ee5652e/activesupport/lib/active_support/notifications.rb:166:in `instrument'
/home/martin/.rvm/gems/ruby-2.2.2@cfme/bundler/gems/rails-53ab1ee5652e/actionview/lib/action_view/template.rb:348:in `instrument'
/home/martin/.rvm/gems/ruby-2.2.2@cfme/bundler/gems/rails-53ab1ee5652e/actionview/lib/action_view/template.rb:156:in `render'
/home/martin/.rvm/gems/ruby-2.2.2@cfme/bundler/gems/rails-53ab1ee5652e/actionview/lib/action_view/renderer/template_renderer.rb:66:in `render_with_layout'

[mwenger1]

👍

[schneems]

Looks like this is a bug in concurrent-ruby see rails/rails#24627

[schneems]

Which is being tracked in ruby-concurrency/concurrent-ruby#528

[schneems]

Not sure why that would happen here though. I don't think that we load assets concurrently. The error is coming from

 asset = cache.get(key, true)
if asset
  asset[:metadata][:dependencies].map!      { |uri| uri.start_with?("file-digest://") ? expand_from_root(uri) : uri } if asset[:metadata][:dependencies]

basically.

We are mutating the values of a hash as we're iterating through it, but I would think that would either work all the time or never. It's weird that it's the same line for both of you since there are other arrays that we're mutating before. I guess maybe that asset only has dependencies?

Both of you are using Ruby 2.2.2 can you try 2.2.4 or 2.3.0?

Could one of you share a project that demonstrates this problem, even if only sometimes?

The best way to reproduce something that happens intermittently is to do it a lot. If this fails on rake assets:precompile you can loop through that, waiting for it to fail.

$ while bundle exec rake assets:precompile; do : ; done

[kaukas]

I am sorry but I can not share the code of the project I am working on. My only observation is that the more files Sprockets needs to compile the more likely the error.

I am currently using Ruby 2.2.4 and hitting the same error.

[schneems]

I am sorry but I can not share the code of the project I am working on.

Sorry didn't specify, I really don't want your code. I want a small project that reproduces the problem. Like may be if the error always happens on the same asset, pull that out into a new project and see if the error happens. If it does, replace the asset with something generic and sharable. If I can't reproduce the problem with an example app, I won't be able to fix it.

[kaukas]

Makes sense, thank you! I'll see what I can reproduce.

[schneems]

Tried to repro the behavior with a ruby only script and i'm not able to

require 'set'
require 'securerandom'

while true
  hash = {}
  hash[:nested] = {}
  hash[:nested][:set] = Set.new

  rand(0..5000).times.each do |i|
    puts i
    hash[:nested][:set] << SecureRandom.hex.upcase
  end

  marshaled = Marshal.dump(hash)
  new_hash = Marshal.load(marshaled)

  new_hash[:nested][:set].map! {|x| x.downcase }
end

[jeremy]

No concurrent access there, @schneems ?

[schneems]

@jeremy right now assets are loaded one at a time since they have dependencies that needed to be loaded in order. Theoretically we could parallelize it but it would need some love to get to that point.

The only other way that these could be accessed parallel that I can see is if they're being accessed by two different requests at the same time. The only way that would happen is if this was in development mode, or if config.assets.compile = true.

Got this backtrace in development mode while using my app

Ah, ha. So it may be related to concurrency.

[kaukas]

Sorry, I did not have time to make a test app.

@schneems, I am mostly seeing this problem when running browser tests in development with compilation. That involves loading the same .js files many times for each test. So it does look like multiple requests trigger concurrent access issues.

[schneems]

Not sure the best way to move forwards here. If the issue exists only in development we don't want to slow down prod to fix dev.

I'm still not 100% sure what is happening. It looks like maybe marshal is returning the exact same object for each request maybe?