rails/rails — Issue #3817: can't add a new key into hash during iteration
Author: xaviershay
Created: 2011-11-30 19:15:17+00:00
State: open

We are seeing the following exception fairly reliably during our acceptance tests when they are run together. I don't have a reproducible case I can share yet, but I will add to this ticket as I discover more.

```
can't add a new key into hash during iteration

/rails-77dcf76f142b/activesupport/lib/active_support/dependencies.rb:528:in `[]='
/rails-77dcf76f142b/activesupport/lib/active_support/dependencies.rb:528:in `block in initialize'
/rails-77dcf76f142b/activesupport/lib/active_support/dependencies.rb:550:in `yield'
/rails-77dcf76f142b/activesupport/lib/active_support/dependencies.rb:550:in `default'
/rails-77dcf76f142b/activesupport/lib/active_support/dependencies.rb:550:in `[]'
/rails-77dcf76f142b/actionpack/lib/action_dispatch/routing/route_set.rb:61:in `controller_reference'
/rails-77dcf76f142b/actionpack/lib/action_dispatch/routing/route_set.rb:46:in `controller'
/rails-77dcf76f142b/actionpack/lib/action_dispatch/routing/route_set.rb:25:in `call'
rack-mount (0.8.3) lib/rack/mount/route_set.rb:152:in `block in call'
rack-mount (0.8.3) lib/rack/mount/code_generation.rb:96:in `block in recognize'
rack-mount (0.8.3) lib/rack/mount/code_generation.rb:75:in `optimized_each'
rack-mount (0.8.3) lib/rack/mount/code_generation.rb:95:in `recognize'
rack-mount (0.8.3) lib/rack/mount/route_set.rb:141:in `call'
/rails-77dcf76f142b/actionpack/lib/action_dispatch/routing/route_set.rb:532:in `call'
square-hoptoad_notifier (2.4.8) lib/hoptoad_notifier/rack.rb:27:in `call'
/rails-77dcf76f142b/actionpack/lib/action_dispatch/middleware/best_standards_support.rb:17:in `call'
rack (1.3.5) lib/rack/etag.rb:23:in `call'
rack (1.3.5) lib/rack/conditionalget.rb:35:in `call'
/rails-77dcf76f142b/actionpack/lib/action_dispatch/middleware/head.rb:14:in `call'
/rails-77dcf76f142b/actionpack/lib/action_dispatch/middleware/params_parser.rb:21:in `call'
/rails-77dcf76f142b/actionpack/lib/action_dispatch/middleware/flash.rb:247:in `call'
rack (1.3.5) lib/rack/session/abstract/id.rb:195:in `context'
rack (1.3.5) lib/rack/session/abstract/id.rb:190:in `call'
/rails-77dcf76f142b/actionpack/lib/action_dispatch/middleware/cookies.rb:331:in `call'
/rails-77dcf76f142b/activerecord/lib/active_record/query_cache.rb:64:in `call'
/rails-77dcf76f142b/activerecord/lib/active_record/connection_adapters/abstract/connection_pool.rb:477:in `call'
/rails-77dcf76f142b/actionpack/lib/action_dispatch/middleware/callbacks.rb:29:in `block in call'
/rails-77dcf76f142b/activesupport/lib/active_support/callbacks.rb:392:in `_run_call_callbacks'
/rails-77dcf76f142b/activesupport/lib/active_support/callbacks.rb:81:in `run_callbacks'
/rails-77dcf76f142b/actionpack/lib/action_dispatch/middleware/callbacks.rb:28:in `call'
rack (1.3.5) lib/rack/sendfile.rb:101:in `call'
/rails-77dcf76f142b/actionpack/lib/action_dispatch/middleware/remote_ip.rb:48:in `call'
/rails-77dcf76f142b/actionpack/lib/action_dispatch/middleware/show_exceptions.rb:47:in `call'
/rails-77dcf76f142b/railties/lib/rails/rack/logger.rb:13:in `call'
rack (1.3.5) lib/rack/methodoverride.rb:24:in `call'
rack (1.3.5) lib/rack/runtime.rb:17:in `call'
/rails-77dcf76f142b/activesupport/lib/active_support/cache/strategy/local_cache.rb:72:in `call'
/rails-77dcf76f142b/actionpack/lib/action_dispatch/middleware/static.rb:53:in `call'
square-hoptoad_notifier (2.4.8) lib/hoptoad_notifier/user_informer.rb:12:in `call'
/rails-77dcf76f142b/railties/lib/rails/engine.rb:456:in `call'
rack (1.3.5) lib/rack/urlmap.rb:52:in `block in call'
rack (1.3.5) lib/rack/urlmap.rb:46:in `each'
rack (1.3.5) lib/rack/urlmap.rb:46:in `call'
capybara (1.1.1) lib/capybara/server.rb:17:in `call'
rack (1.3.5) lib/rack/handler/webrick.rb:59:in `service'
/Users/taylor/.rvm/rubies/ruby-1.9.3-rc1/lib/ruby/1.9.1/webrick/httpserver.rb:138:in `service'
/Users/taylor/.rvm/rubies/ruby-1.9.3-rc1/lib/ruby/1.9.1/webrick/httpserver.rb:94:in `run'
/Users/taylor/.rvm/rubies/ruby-1.9.3-rc1/lib/ruby/1.9.1/webrick/server.rb:191:in `block in start_thread'
```

The exception occurs with threadsafe mode on rails 3.1.1 and 3.1.3 under ruby 1.9.3. We are using girl_friday, and the action that triggers this exception is posting a job that makes an HTTP request. This plus the stack trace inside `ActiveSupport::Dependencies` leads me to believe this is a concurrency related loading bug.

The exception occurs in the default value block for `@store` in `ClassCache` in `active_support/dependencies.rb:528`. I tried replacing that class as follows, with logging and a mutex lock. There are many hash methods aside from the obvious that cause iteration, such as clear, merge, key, etc... (see `hash.c` in ruby source). My theory was one of these was being called (hence the `instance_eval`). Unfortunately, this did not prevent the exception, nor was any output created. This confuses me, since it doesn't look like the `@store` variable is not being leaked outside of this class, so I can't hypothesize what else would be causing this error.

``` Ruby
class ClassCache
def initialize
@mutex = Mutex.new
@store = Hash.new { |h, k|
raise "FAIL" unless @mutex.locked?
h[k] = Inflector.constantize(k)
}
(Hash.new.public_methods - Kernel.public_methods - [:[], :[]=, :default]).each do |meth|
@store.instance_eval <<-EOS
def #{meth}(*args)
puts
puts "--- #{meth}"
puts caller
super
end
EOS
end
end

def empty?
@mutex.synchronize { @store.empty? }
end

def key?(key)
@mutex.synchronize { @store.key?(key) }
end

def []=(key, value)
return unless key.respond_to?(:name)

raise(ArgumentError, 'anonymous classes cannot be cached') if key.name.blank?

@mutex.synchronize {
@store[key.name] = value
}
end

def [](key)
key = key.name if key.respond_to?(:name)

@mutex.synchronize {
@store[key]
}
end
alias :get :[]

class Getter # :nodoc:
def initialize(name)
@name = name
end

def get
Reference.get @name
end
deprecate :get
end

def new(name)
self[name] = name
Getter.new(name)
end
deprecate :new

def store(name)
self[name] = name
self
end

def clear!
@mutex.synchronize do
@store.clear
end
end
end
```

I also looked at surrounding code for potential issues incase the stack trace was misleading. The following code from `ActionDispatch` is not thread-safe (not an atomic compare and set - unless there is a lock higher in the stack?), but not sure how it could cause problems.

``` Ruby
# action_dispatch/routing/route_set.rb:54
def controller_reference(controller_param)
controller_name = "#{controller_param.camelize}Controller"

unless controller = @controllers[controller_param]
controller = @controllers[controller_param] =
ActiveSupport::Dependencies.reference(controller_name)
end
controller.get(controller_name)
end
```

I tried various ways of setting up multiple threads both writing to the same defaults to try and reproduce an error by force, but failed.

``` Ruby
hash = Hash.new {|h, k| sleep 0.01; h[rand] = "a" }

threads = [
Thread.new {
100.times { hash[1] }
puts "A DONE"
},
Thread.new {
100.times { hash[1] }
puts "B DONE"
}
]
threads.each(&:join)
```

Investigation continues...