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 https://github.com/ruby-concurrency/concurrent-ruby/issues/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?

[kaukas]

Please try this repository. It reproduces the problem on my Mac quite reliably.

Please also note the (lack of) speed of asset compilation. Even though the number of files is large Sprockets takes ages to compile. Way too slow in my opinion. It is not uncommon to have even more dependencies in large projects if you include CSS, font and image assets. The sprockets_bug repo could also be used to research the issue #84.

Thank you!

[kaukas]

Has anyone had any luck reproducing the issue with the demo repository? Is there some other way I could help?

[schneems]

I won't be able to dig in until after RailsConf

[arktisklada]

I see the linked issue has been resolved and folded into the Rails 5.0.0 release, but it's not working for me in 4.2. Any ideas here?

[kaukas]

If I understand it correctly, the bug in #24627 has been fixed by upgrading to the latest ConcurrentRuby. I upgraded the demo repository too but the problem still occurs.

[schneems]

This is different than the concurrent-ruby example linked.

[arktisklada]

Anyone have any insights on this yet? Or at least an idea of a starting point; happy to dig deeper myself!

[schneems]

We know exactly what is happening, it's just that to solve it would cause performance problems in production which we don't want. Maybe try using some other cache backends and see if that helps? You can try memcache, filestore, memory store.

The issue is that the same object is being mutated in several threads since you're using a multithreaded webserver in development.

One hacky work around could be to turn down your threads to 1 in development and instead use multiple processes (i.e. multiple puma workers). That should prevent this problem from showing up locally until (if) a sane fix can be applied.

[masterkain]

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

1 File "/app/.rvm/rubies/ruby-2.3.0/lib/ruby/2.3.0/set.rb" line 153 in replace
2 File "/app/.rvm/rubies/ruby-2.3.0/lib/ruby/2.3.0/set.rb" line 153 in replace
3 File "/app/.rvm/rubies/ruby-2.3.0/lib/ruby/2.3.0/set.rb" line 360 in collect!
4 File "/app/shared/bundle/ruby/2.3.0/gems/sprockets-3.6.0/lib/sprockets/loader.rb" line 85 in asset_from_cache
5 File "/app/shared/bundle/ruby/2.3.0/gems/sprockets-3.6.0/lib/sprockets/loader.rb" line 35 in load
6 File "/app/shared/bundle/ruby/2.3.0/gems/sprockets-3.6.0/lib/sprockets/cached_environment.rb" line 20 in block in initialize
7 File "/app/shared/bundle/ruby/2.3.0/gems/sprockets-3.6.0/lib/sprockets/cached_environment.rb" line 47 in load
8 File "/app/shared/bundle/ruby/2.3.0/gems/sprockets-3.6.0/lib/sprockets/legacy.rb" line 195 in block in to_a
9 File "/app/shared/bundle/ruby/2.3.0/gems/sprockets-3.6.0/lib/sprockets/legacy.rb" line 195 in map
10 File "/app/shared/bundle/ruby/2.3.0/gems/sprockets-3.6.0/lib/sprockets/legacy.rb" line 195 in to_a
11 File "/app/shared/bundle/ruby/2.3.0/gems/sprockets-3.6.0/lib/sprockets/legacy.rb" line 207 in dependencies
12 File "/app/shared/bundle/ruby/2.3.0/bundler/gems/opal-c92d78b3b443/lib/opal/sprockets.rb" line 40 in load_asset
13 File "/app/shared/bundle/ruby/2.3.0/bundler/gems/opal-rails-ddc65773ea16/app/helpers/opal_helper.rb" line 19 in block in javascript_include_tag
14 File "/app/shared/bundle/ruby/2.3.0/bundler/gems/opal-rails-ddc65773ea16/app/helpers/opal_helper.rb" line 18 in each
15 File "/app/shared/bundle/ruby/2.3.0/bundler/gems/opal-rails-ddc65773ea16/app/helpers/opal_helper.rb" line 18 in javascript_include_ta 

[elia]

@schneems to add context to the stacktrace above we're seeing this in production, the server in our case is Rainbows! with ThreadPool strategy which is indeed multithreaded.

This is a reduced example of what happens:

require 'set'
set = Set.new (1..5).to_a
p set

loop = -> {
  set.map! do |v|
    sleep 0.1
    v+1
  end
}

t1 = Thread.new {
  sleep 0.2
  loop.call
}

t2 = Thread.new {
  sleep 0.1
  loop.call
}

t1.join
t2.join

I think it could make sense to add an in-memory cache for assets with expanded keys, something on the lines of this:

def asset_from_cache(key)
  asset = cache.get(key, true)
  return unless asset

  @expanded_assets ||= {} # this should be initialized elsewhere
  @expanded_assets[key] ||= begin
    asset[:uri]       = expand_from_root(asset[:uri])
    asset[:load_path] = expand_from_root(asset[:load_path])
    asset[:filename]  = expand_from_root(asset[:filename])
    asset[:metadata][:included]     = asset[:metadata][:included].map      { |uri| expand_from_root(uri) } if asset[:metadata][:included]
    asset[:metadata][:links]        = asset[:metadata][:links].map         { |uri| expand_from_root(uri) } if asset[:metadata][:links]
    asset[:metadata][:stubbed]      = asset[:metadata][:stubbed].map       { |uri| expand_from_root(uri) } if asset[:metadata][:stubbed]
    asset[:metadata][:required]     = asset[:metadata][:required].map      { |uri| expand_from_root(uri) } if asset[:metadata][:required]
    asset[:metadata][:dependencies] = asset[:metadata][:dependencies].map  { |uri| uri.start_with?("file-digest://") ? expand_from_root(uri) : uri } if asset[:metadata][:dependencies]

    asset[:metadata].each_key do |k|
      next unless k =~ /_dependencies\z/
      asset[:metadata][k] = asset[:metadata][k].map { |uri| expand_from_root(uri) }
    end
    asset
  end
end

It's clearly draft code but should eliminate both performance and root-expansion problems at the cost of some memory that would stay resident instead of being GC'ed and rebuilt each time.

PS: in the meanwhile I'll try this patch

[schneems]

I agree that PR would solve the problem, however in production we want to mutate the original arrays as there is a performance penalty for allocating additional objects.

Maybe if someone has some time and can set up some benchmarks with a large-ish project (lots of assets) and can show that this change has very little impact we could move forwards with it.

[elia]

Not a super big set, but foo.js has 132 dependecies, so I think it's a fair benchmark

p setup_env[Sprockets::CachedEnvironment].find_asset('foo').metadata[:dependencies].size # => 132

(the control benchmark is there just to ensure a slower impl is detected)

gem 'opal', '0.10.0.beta5'
gem 'benchmark-ips'
gem 'sprockets', '3.6.0'

require 'opal'
require 'benchmark/ips'

class PatchedEnvironment < Sprockets::CachedEnvironment
  def initialize(*)
    super
    @expanded_assets_cache = {}
  end

  def asset_from_cache(key)
    return @expanded_assets_cache[key] if @expanded_assets_cache.has_key?(key)

    asset = cache.get(key, true)

    if asset
      asset[:uri]       = expand_from_root(asset[:uri])
      asset[:load_path] = expand_from_root(asset[:load_path])
      asset[:filename]  = expand_from_root(asset[:filename])
      asset[:metadata][:included]     = asset[:metadata][:included].map      { |uri| expand_from_root(uri) } if asset[:metadata][:included]
      asset[:metadata][:links]        = asset[:metadata][:links].map         { |uri| expand_from_root(uri) } if asset[:metadata][:links]
      asset[:metadata][:stubbed]      = asset[:metadata][:stubbed].map       { |uri| expand_from_root(uri) } if asset[:metadata][:stubbed]
      asset[:metadata][:required]     = asset[:metadata][:required].map      { |uri| expand_from_root(uri) } if asset[:metadata][:required]
      asset[:metadata][:dependencies] = asset[:metadata][:dependencies].map  { |uri| uri.start_with?("file-digest://") ? expand_from_root(uri) : uri } if asset[:metadata][:dependencies]

      asset[:metadata].each_key do |k|
        next unless k =~ /_dependencies\z/
        asset[:metadata][k] = asset[:metadata][k].map { |uri| expand_from_root(uri) }
      end
      asset
    end

    @expanded_assets_cache[key] = asset
  end
end

class ControlEnvironment < Sprockets::CachedEnvironment
  def asset_from_cache(key)
    sleep 0.01
    super
  end
end

dirs = Opal.paths
files = Dir["{#{dirs.join(',')}}/*.rb"]
names = files.map { |path| File.basename(path, '.rb') }
File.write "#{__dir__}/foo.js", names.map {|n| "//= depend_on #{n}.js\n"}.join
names << 'foo'

env = Sprockets::Environment.new(__dir__)
env.cache = Sprockets::Cache::FileStore.new('cache')
(dirs + [__dir__]).each { |path| env.append_path path }

setup_env = -> klass { klass.new(env) }

Benchmark.ips do |x|
  x.report("vanilla") { setup_env[Sprockets::CachedEnvironment].find_asset('foo.js') }
  x.report("patched") { setup_env[PatchedEnvironment].find_asset('foo.js') }
  x.report("control") { setup_env[ControlEnvironment].find_asset('foo.js') }
  x.compare!
end

Warming up --------------------------------------
             vanilla    20.000  i/100ms
             patched    16.000  i/100ms
             control     5.000  i/100ms
Calculating -------------------------------------
             vanilla    211.511  (±13.7%) i/s -      1.040k
             patched    211.118  (±17.5%) i/s -      1.024k
             control     50.642  (± 5.9%) i/s -    255.000 

Comparison:
             vanilla:      211.5 i/s
             patched:      211.1 i/s - same-ish: difference falls within error
             control:       50.6 i/s - 4.18x slower

[schneems]

Can you put it somewhere I can reproduce your benchmarks?

[elia]

It's all self contained, you can save the script to something like /tmp/bench.rb and just run it. :)

[samandmoore]

We're seeing this issue in production running on jruby 1.7.24 (1.9.3p551) with puma 2.15.x. We're actually encountering it when we use the image_tag helper and it dives down into sprockets to locate an asset (yes, we have the sprockets runtime enabled in production at the moment).

when you said:

Maybe try using some other cache backends and see if that helps? You can try memcache, filestore, memory store.

Do you mean that we should consider configuring rails to use a different cache backend? e.g. config.cache_store = :memory_store? Or is there a sprockets-specific cache backend? I don't understand exactly where the cache backend fits into this (sorry for my ignorance, I'm still trying to grok the internals of sprockets).

I'd love to throw together an example app for you, but it's been surprisingly hard to reproduce. I will see what I can do though.

[schneems]

I'm fine with this fix. Can you send me a PR and i'll merge it?

[CyborgMaster]

I've been struggling with what appears to be the same the same bug. I see it when trying to run javascript tests using konacha with the rake konacha:run command. I only see it when using Puma as my webserver (probably because it's a multithreaded webserver). I don't seem to see it during development, only when running javascript tests. I tried changing the sprockets cache backend like this:

config.assets.configure do |env|
  env.cache = ActiveSupport::Cache.lookup_store(:memory_store,
                                                { size: 32.megabytes })
end

but it didn't seem to help. Applying @elia's patch seems to fix it. I of course had to remove his unless Rails.env.development? check because I do want it in my development environment (and only in my development environment.

[CyborgMaster]

Sometimes, while using @elia's patch, I'll get this error. I think it's related.

ActionView::Template::Error: no implicit conversion of Set into Array
    /Users/jeremy/.rvm/gems/ruby-2.3.1@allynova/gems/sprockets-3.6.3/lib/sprockets/bundle.rb:59:in `+'
    /Users/jeremy/.rvm/gems/ruby-2.3.1@allynova/gems/sprockets-3.6.3/lib/sprockets/bundle.rb:59:in `block (2 levels) in process_bundle_reducers'
    /Users/jeremy/.rvm/gems/ruby-2.3.1@allynova/gems/sprockets-3.6.3/lib/sprockets/bundle.rb:55:in `each'
    /Users/jeremy/.rvm/gems/ruby-2.3.1@allynova/gems/sprockets-3.6.3/lib/sprockets/bundle.rb:55:in `block in process_bundle_reducers'
    /Users/jeremy/.rvm/gems/ruby-2.3.1@allynova/gems/sprockets-3.6.3/lib/sprockets/bundle.rb:54:in `each'
    /Users/jeremy/.rvm/gems/ruby-2.3.1@allynova/gems/sprockets-3.6.3/lib/sprockets/bundle.rb:54:in `reduce'
    /Users/jeremy/.rvm/gems/ruby-2.3.1@allynova/gems/sprockets-3.6.3/lib/sprockets/bundle.rb:54:in `process_bundle_reducers'
    /Users/jeremy/.rvm/gems/ruby-2.3.1@allynova/gems/sprockets-3.6.3/lib/sprockets/bundle.rb:34:in `call'
    /Users/jeremy/.rvm/gems/ruby-2.3.1@allynova/gems/sprockets-3.6.3/lib/sprockets/processor_utils.rb:75:in `call_processor'
    /Users/jeremy/.rvm/gems/ruby-2.3.1@allynova/gems/sprockets-3.6.3/lib/sprockets/processor_utils.rb:57:in `block in call_processors'
    /Users/jeremy/.rvm/gems/ruby-2.3.1@allynova/gems/sprockets-3.6.3/lib/sprockets/processor_utils.rb:56:in `reverse_each'
    /Users/jeremy/.rvm/gems/ruby-2.3.1@allynova/gems/sprockets-3.6.3/lib/sprockets/processor_utils.rb:56:in `call_processors'
    /Users/jeremy/.rvm/gems/ruby-2.3.1@allynova/gems/sprockets-3.6.3/lib/sprockets/loader.rb:134:in `load_from_unloaded'
    /Users/jeremy/.rvm/gems/ruby-2.3.1@allynova/gems/sprockets-3.6.3/lib/sprockets/loader.rb:60:in `block in load'
    /Users/jeremy/.rvm/gems/ruby-2.3.1@allynova/gems/sprockets-3.6.3/lib/sprockets/loader.rb:317:in `fetch_asset_from_dependency_cache'
    /Users/jeremy/.rvm/gems/ruby-2.3.1@allynova/gems/sprockets-3.6.3/lib/sprockets/loader.rb:44:in `load'
    /Users/jeremy/.rvm/gems/ruby-2.3.1@allynova/gems/sprockets-3.6.3/lib/sprockets/cached_environment.rb:20:in `block in initialize'
    /Users/jeremy/.rvm/gems/ruby-2.3.1@allynova/gems/sprockets-3.6.3/lib/sprockets/cached_environment.rb:47:in `load'
    /Users/jeremy/.rvm/gems/ruby-2.3.1@allynova/gems/sprockets-3.6.3/lib/sprockets/base.rb:66:in `find_asset'
    /Users/jeremy/.rvm/gems/ruby-2.3.1@allynova/gems/sprockets-3.6.3/lib/sprockets/base.rb:92:in `[]'
    /Users/jeremy/.rvm/gems/ruby-2.3.1@allynova/gems/sprockets-rails-3.1.1/lib/sprockets/rails/helper.rb:338:in `find_asset'
    /Users/jeremy/.rvm/gems/ruby-2.3.1@allynova/gems/sprockets-rails-3.1.1/lib/sprockets/rails/helper.rb:312:in `asset_path'
    /Users/jeremy/.rvm/gems/ruby-2.3.1@allynova/gems/sprockets-rails-3.1.1/lib/sprockets/rails/helper.rb:85:in `block in resolve_asset_path'
    /Users/jeremy/.rvm/gems/ruby-2.3.1@allynova/gems/sprockets-rails-3.1.1/lib/sprockets/rails/helper.rb:225:in `block in resolve_asset'
    /Users/jeremy/.rvm/gems/ruby-2.3.1@allynova/gems/sprockets-rails-3.1.1/lib/sprockets/rails/helper.rb:224:in `each'
    /Users/jeremy/.rvm/gems/ruby-2.3.1@allynova/gems/sprockets-rails-3.1.1/lib/sprockets/rails/helper.rb:224:in `detect'
    /Users/jeremy/.rvm/gems/ruby-2.3.1@allynova/gems/sprockets-rails-3.1.1/lib/sprockets/rails/helper.rb:224:in `resolve_asset'
    /Users/jeremy/.rvm/gems/ruby-2.3.1@allynova/gems/sprockets-rails-3.1.1/lib/sprockets/rails/helper.rb:84:in `resolve_asset_path'
    /Users/jeremy/.rvm/gems/ruby-2.3.1@allynova/gems/sprockets-rails-3.1.1/lib/sprockets/rails/helper.rb:74:in `compute_asset_path'
    /Users/jeremy/.rvm/gems/ruby-2.3.1@allynova/gems/actionview-4.2.7/lib/action_view/helpers/asset_url_helper.rb:135:in `asset_path'
    /Users/jeremy/.rvm/gems/ruby-2.3.1@allynova/gems/actionview-4.2.7/lib/action_view/helpers/asset_url_helper.rb:245:in `javascript_path'
    /Users/jeremy/.rvm/gems/ruby-2.3.1@allynova/gems/actionview-4.2.7/lib/action_view/helpers/asset_tag_helper.rb:61:in `block in javascript_include_tag'
    /Users/jeremy/.rvm/gems/ruby-2.3.1@allynova/gems/actionview-4.2.7/lib/action_view/helpers/asset_tag_helper.rb:59:in `map'
    /Users/jeremy/.rvm/gems/ruby-2.3.1@allynova/gems/actionview-4.2.7/lib/action_view/helpers/asset_tag_helper.rb:59:in `javascript_include_tag'
    /Users/jeremy/.rvm/gems/ruby-2.3.1@allynova/gems/sprockets-rails-3.1.1/lib/sprockets/rails/helper.rb:139:in `block in javascript_include_tag'
    /Users/jeremy/.rvm/gems/ruby-2.3.1@allynova/gems/sprockets-rails-3.1.1/lib/sprockets/rails/helper.rb:137:in `map'
    /Users/jeremy/.rvm/gems/ruby-2.3.1@allynova/gems/sprockets-rails-3.1.1/lib/sprockets/rails/helper.rb:137:in `javascript_include_tag'
...

[CyborgMaster]

I've been working on the no implicit conversion of Set into Array crash and I'm not getting anywhere. Anyone have any thoughts?

[CyborgMaster]

I tried the following patch instead of the one provided by @elia, and it seems to solve both the can't add a new key into hash during iteration and the no implicit conversion of Set into Array bugs.

  module SprocketsSynchronizedLoader
    def self.prepended(klass)
      klass.class_eval do
        class << self
          attr_reader :mutex
        end
        @mutex = Mutex.new
      end
    end

    def asset_from_cache(key)
      self.class.mutex.synchronize do
        super
      end
    end

    Sprockets::CachedEnvironment.prepend self
  end

[CyborgMaster]

Another note about my above patch. It seems to work great at preventing the errors, but sometimes seems to get stuck for some reason and I have to kill the process.

[solipet]

Seeing the same in Rails 5.0.0.1, sprockets 3.7.0, ruby 2.3.1, puma 3.6.0. Dropping puma to 1 thread did fix it.

Of course, now that I try to recreate the error, it's playing nice so I lost the stack trace, but it was in set.rb, line 153. I'll post if it reoccurs.

[dennyluan]

Also seeing this with sprockets 3.7.0, rails 4.2.6

ActionView::Template::Error: can't add a new key into hash during iteration
    /Users/denny/.rbenv/versions/2.3.1/lib/ruby/2.3.0/set.rb:153:in `replace'
    /Users/denny/.rbenv/versions/2.3.1/lib/ruby/2.3.0/set.rb:153:in `replace'
    /Users/denny/.rbenv/versions/2.3.1/lib/ruby/2.3.0/set.rb:360:in `collect!'
    /Users/denny/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/sprockets-3.7.0/lib/sprockets/loader.rb:85:in `asset_from_cache'
    /Users/denny/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/sprockets-3.7.0/lib/sprockets/loader.rb:57:in `block in load'

[merqlove]

Same here, Rails 5.0.1, Ruby 2.3.3, Sprockets master, i'm saw this one many times. What i can say. Here is no dependency on single or multiple threads. I'm see this error on both server types, webrick, puma, puma single thread. Also my current project is just Rails dummy app with lots of frontend stuff. So yes, Sprockets need time to update cache on changes.

[frederikspang]

+1 for Rails 5.1.2, Ruby 2.4.1, sprockets (3.7.1) and sprockets-rails (3.2.0).

[webdev1014]

+1 for rails 5.0.3, Ruby 2.3.1p112, sprockets (3.7.1) I've just got same error.

[mgwidmann]

+1 I've got this and our app is running Rails 5.1.2 on Ruby 2.4.1 w/ sprockets 3.7.1 and concurrent-ruby 1.0.5. Was able to repro by duplicating a tab a bunch of times, failure occurred on a stylesheet file in the layout file.

[japzi]

I got the same error. Rails 5.0.2 | Ruby 2.3.3p222 | sprockets 3.7.1 | concurrent-ruby 1.0.5

[cavoixanha]

I got the same error when update to sprockets 4.0.0.beta5, sprockets 3.7.1 is work

Config: Rails 4.2 Ruby 2.2 concurrent-ruby 1.0.5

[wycarol44]

same error

[schneems]

I have a PR to fix this issue. https://github.com/rails/sprockets/pull/518

I'm still a bit confused about how it happens. Anything that is being mutated is coming from a Marshal.load from the cache

def asset_from_cache(key)
  asset = cache.get(key, true)

AFAIK each marshal "loaded" object is unique

a = [1,2,3]
b = Marshal.load(Marshal.dump(a))
c = Marshal.load(Marshal.dump(a))

puts b == c
# => True

b << 4 #mutating `b` does not mutate `c`

puts b == c
# => False

Are you all still seeing the error sometimes, or did you stop using sprockets 4 beta?

[samandmoore]

Are you all still seeing the error sometimes, or did you stop using sprockets 4 beta?

My configuration has changed and I'm mostly not using JRuby anymore, so I'm not seeing this issue lately. I was seeing this issue on 3.x; I haven't tried the 4 beta.

[Karthik-Y]

I had the same errors.

My issue happened when the cached data was reiterated on browser load but the map object in the cache refused the new keys but instead of ignoring it throws error. Which in my opinion is correct behaviour since it should not treat it as hard refresh and of course once hard refreshed the cache gets resettled.

On double check it was the Turbolinks and sprockets on my case and I believe it is because when turbo links is not properly configured to reload like the following below you may likely see this error or notice it becoming frequent.

    = stylesheet_link_tag 'application', media: 'all', 'data-turbolinks-track': 'reload'
    = javascript_include_tag 'application', 'data-turbolinks-track': 'reload'

[acrolink]

@Karthik-Y

Have you found a solution, I am having the same problem?

[Karthik-Y]

@acrolink Yes, as I mentioned it was Turbolinks configuration on my case. *Please refer my comment above..I added the following

'data-turbolinks-track': 'reload'

to my views/layouts/application file.

[drusepth]

Commenting to subscribe to updates, as I'm also seeing this occasionally.