Intermittent failure on test environment about missing constants

[sobrinho]

Hello guys,

We have 3 complete different applications which are raising strange exceptions on the test environment.

I'm assuming it's a race condition but I'm not sure, still trying to figure out what's happening.

On a rails 4.0.4 application we are randomly seeing this exception:

An error occurred in an after hook
  ActionController::RoutingError: Object is not missing constant PeopleController!
  occurred at ..../activesupport-4.0.4/lib/active_support/dependencies.rb:449:in `load_missing_constant'

Using ActiveSupport::Dependencies.log_activity = true, as @rafaelfranca suggested, we see this on the test.log:

Started POST "/people" for 127.0.0.1 at 2014-05-13 09:37:32 -0300
Started POST "/people" for 127.0.0.1 at 2014-05-13 09:37:32 -0300
Dependencies: called load_missing_constant(Object, :PeopleController)
Dependencies: called load_missing_constant(Object, :PeopleController)
Dependencies: called require_or_load("..../app/controllers/people_controller", "PeopleController")
Dependencies: called require_or_load("..../app/controllers/people_controller", "PeopleController")
Dependencies: requiring ..../app/controllers/people_controller
Dependencies: called require_or_load("people_helper", nil)
Dependencies: requiring people_helper
Processing by PeopleController#create as JSON

We are seeing similar failures on rails 4.1 applications (circular dependency exception appears from time to time and we don't have any circular dependency).

What I can tell is that when we make 2 requests at same endpoint, in this case, at people controller, something happens on active support and it mess with the autoloading.

We changed config.eager_load to true on the test environment and the exceptions seems to be gone, we are running the same build again over and over again to be sure it won't fail again.

I'm assuming that is something related to the capybara running the server in a different thread but since webrick responds only one request per time, it do not makes sense.

Is that excepted to happen when eager load is false on test environment?

What else can we do to isolate the exception and you guys have some info about it?

[rafaelfranca]

cc @fxn

[sobrinho]

We have disabled the eager load to get other random failures and now we get the circular dependency exception:

Started POST "/people" for 127.0.0.1 at 2014-05-13 10:23:39 -0300
Started POST "/people" for 127.0.0.1 at 2014-05-13 10:23:39 -0300
Dependencies: called load_missing_constant(Object, :PeopleController)
Dependencies: called require_or_load(".../app/controllers/people_controller", "PeopleController")
Dependencies: requiring .../app/controllers/people_controller
Dependencies: called load_missing_constant(Object, :PeopleController)
Dependencies: called require_or_load("people_helper", nil)

An error occurred in an after hook
  RuntimeError: Circular dependency detected while autoloading constant PeopleController
  occurred at .../activesupport-4.0.4/lib/active_support/dependencies.rb:461:in `load_missing_constant'

[thedarkone]

Started POST "/people" for 127.0.0.1 at 2014-05-13 09:37:32 -0300
Started POST "/people" for 127.0.0.1 at 2014-05-13 09:37:32 -0300

Are you running 2 concurrent requests in the same Ruby process? ActiveSupport::Dependencies const-auto-reloading (development mode, config.eager_load = false) is not thread-safe.

[sobrinho]

But since we are using webrick, thread-safety must not be a problem.

[thedarkone]

@sobrinho I'm sorry, you can't have auto-loaded and auto-unloaded constants in a multi-threaded environment, it is not supported by Rails :(. Your choice of server has no bearing on this...

What happens is that multiple threads start loading/evaling .rb files concurrently (without regard for each-other) and all matter of things goes wrong.

@rafaelfranca this can be closed.

[matthewd]

@sobrinho as you said, capybara uses two threads: one to drive, and one to handle the web requests.

But... unless you're doing something quite odd, only the latter would normally have occasion to load a controller. And it certainly doesn't explain how you're ending up with two simultaneous requests, which I wouldn't normally expect capybara to make without rather explicit encouragement.

Can you please reduce this to a minimal test case? Mostly, I'd like to see a test method that causes this. (Is Webrick even getting involved? Or is capybara just using Rack::Test?)

@thedarkone note that cache_classes is presumably still on... there's no unloading/reloading involved, just loading. Which is still not threadsafe, but should be hard_er_ to make blow up. And eager_load = false is the default in the test environment: if changing it is the right answer, I think we need to understand exactly why it needs to be true in this case, so our general advice (and possibly the comment in test.rb) can be suitably informative.

[sobrinho]

@matthewd I will try to isolate it today and post some news.

[thedarkone]

@matthewd there is no need to change the default eager_load to true in test env., however if multiple concurrent app-accessing threads are at any point involved, then eager_load must be set to true.

I have no idea how capybara works, but if the "driver" thread is "sequential" to "web-app" thread (whereby "sequential" I mean the "driver" thread is never running concurrently with a "web-app", ie "driver" always blocks when calling "web-app", as in: it does app.call and then waits for a response) then development mode const-loading should work just fine.

[rails-bot]

This issue has been automatically marked as stale because it has not been commented on for at least
three months.

The resources of the Rails team are limited, and so we are asking for your help.

If you can still reproduce this error on the 4-1-stable, 4-0-stable branches or on master,
please reply with all of the information you have about it in order to keep the issue open.

Thank you for all your contributions.

[divineforest]

I have the same issue with capybara and wrong circular dependency exception.

eager_load=true helps.

Should we change the default value for it?

[fxn]

@divineforest constant autoloading works fine if constants are loaded in a sequential way. I have never seen a problem with constant autoloading that didn't uncover something wrong in the application code.

If there was something fundamental in Capybara that prevented it from being safe for constant autoloading, then we could study the situation and see what can be done, but we cannot change the default without that understanding.

[divineforest]

@fxn everything is fine with capybara. It just uses threads :). And rails are not thread-safe at constant autoloading. Please look at railsadminteam/rails_admin#2029 (comment) . It check loaded variable that was defined here https://github.com/rails/rails/blob/master/activesupport/lib/active_support/dependencies.rb#L30 . I believe that mattr_accessor is not thread-safe and Set as well.

[divineforest]

@fxn I can try to fix autoloading and circular dependency checking. But still looks like ruby's require method is not thread safe.

[fxn]

@divineforest it uses threads, but there are comments in this thread that suggest that maybe it uses threads in a way that should not affect constant autoloading. I don't know Capybara internals, we need confirmation of whether it is a problem or not.

I can say I have never had issues with Capybara and constants, but that still doesn't prove anything, maybe I was lucky, maybe there's no issue. We need to know.

[divineforest]

@fxn the issue occurs when there are a lot of parallel ajax requests to the same action

[fxn]

@divineforest are those parallel requests served by different threads?

[divineforest]

@fxn yes

[fxn]

@divineforest why?

[divineforest]

@fxn I print Thread.current.object_id and see 3 different ids

[divineforest]

Looks like other people also have these issues https://gist.github.com/josevalim/470808

/cc @ka8725

[fxn]

Well, that thread seems unrelated to constants. It says that there are threads and thus different connections.

But we need to know rather than guess that Capybara uses threads in a way that makes constant autoloading non-safe. If that is the case, then we will study the best thing to do knowing what we have to address.

I may personally study how Capybara works when I find the time (in some imaginary dimension!), it is something that interests me anyway.

[sobrinho]

Just to be clear, we are using database rewinder and not the shared connection ;)

[rafaelfranca]

#16828 and linked issue is related to this one too.

[divineforest]

@fxn thanks for you attention. I feel that now I need to dig more info and then continue discussion :)

[divineforest]

@fxn that thread itself is not relevant, only the comment

But now I have one more problem: the tests fail sometimes saying that there is no connection to DB and sometimes with a circular dependency in ActiveRecord associations... Now I don't know what to do: may be this is because of race conditions from Poltergeist's parallel requests to

[thedarkone]

@divineforest:

@fxn the issue occurs when there are a lot of parallel ajax requests to the same action

@fxn:

@divineforest are those parallel requests served by different threads?

@divineforest:

@fxn yes

Back to my comment from a couple of months ago:

Are you running 2 concurrent requests in the same Ruby process? ActiveSupport::Dependencies const-auto-reloading (development mode, config.eager_load = false) is not thread-safe.

I think this is solved and the issue can be closed then.

this @matthewd comment's:

@sobrinho as you said, capybara uses two threads: one to drive, and one to handle the web requests.

doesn't apply because @divineforest clearly uses more than one thread "to handle" web requests.

[twalpole]

@divineforest Do you happen to be creating multiple Capybara::Session objects, and if so - are they all created with the same application instance? Capybara will start one server thread for each application instance, each listening on its own port. You can look at Capybara::Server.ports to see how many server threads capybara is running (one port per thread)

[divineforest]

@twalpole

Capybara::Server.ports =>
{70100771329120=>62578}

[divineforest]

@fxn oh, thanks :)

[fxn]

@divineforest before the Rack days every server had their own interface and the adapter for WEBrick was responsible for the synchronization. Nowadays a middleware is injected when you run rails server, see https://github.com/rails/rails/blob/master/railties/lib/rails/commands/server.rb#L87-L103.

I guess we are onto something.

[twalpole]

@divineforest - As you pointed out Rails will normally insert Rack::Lock into the middleware to prevent Webrick from handling multiple requests simultaneously - This may not be being included when run with Capybara, or you may to be removing it from the middleware in your app? I will hopefully have time to check later today whether Capybara is missing that for rails apps.

[thedarkone]

Geeze guys! Reading this issue is an exercise in frustration...

I assume Capybara's "driver" thread works like this: request url, wait response, read response, parse html, send another request, wait response, parse html, send request, etc. If it is so, and there is only one such "driver" thread, then it doesn't matter how many threads webrick is running/spawning or whether Rack::Lock is used -> webrick serves 1 request at a time, no parallelism everything is fine.

If this is not so, and there are multiple "driver" threads or a "driver" might issue multiple requests simultaneously then there is a problem.

[twalpole]

@thedarkone Capybara in this case is being used to test an app through a browser - So capybara has two threads - one that runs a server (Webrick) and one that interacts with a browser. So it goes
tell browser to request some uri -> tell browser to edit some elemnts -> tell browser to click some elements -> etc -> wait for some condition in browser to change ... it appears that If during the edit some elements, click some elements, etc the app in the browser happens to issue multiple requests to the running webrick and Rack::Lock is not in the middleware then webrick (as a multithreaded web server) will actually handle more than 1 request at a time and there is parallelism - This has nothing to do with the "driver" issuing multiple requests

[fxn]

I have not been able to look at the code and I am writing this from my phone.

The hypothesis is that the application is issuing severall Ajax call in the context of one single Capybara request. Those ones would spawn threads in WEBrick if there's no locking manually configured.

[twalpole]

So looking through the code, Rails adds Rack::Lock to the middleware for the app unless allow_concurrency? is true - allow concurrency is defined as

def allow_concurrency?
    config.allow_concurrency.nil? ? config.cache_classes : config.allow_concurrency
end

Since config.cache_classes is true by default in the test environment while config.eager_load is false, This sets up a default of allowing concurrency in webrick while not eager loading the code - which I believe is causing these errors. Is this the intended behavior in rails?

[fxn]

@twalpole that's going to be it, that predicate should not return true if eager_load is false. I think we have it thanks a lot for your insight on Capybara's internals :).

[fxn]

I have confirmed this is the case. Wrote a test app that issues 10 Ajax calls in the layout to a dummy action that sleeps for one second. When running it trough Capybara there are as many threads in parallel, and if we disable concurrency they are served linearly.

So this is definitely wrong, going to fix it.

[thedarkone]

@twalpole thanks, finally things are starting to make sense!

Capybara uses a browser and an app (that is being tested) has AJAX requests that are not user triggered or a user action might trigger multiple AJAX requests, that then end up hitting multithreaded rails app in development mode.

The solution is simple, the Rails enviroment used by Capybara must either:

• not be in dev. mode or
• have (config.allow_concurrency = false) or (config.allow_concurrency = nil (as is not be setup with user provided value) and config.cache_classes = false)

[fxn]

No, no, the predicate should return false if eager_load is false. I am writing a patch.

[fxn]

@thedarkone the app is running in test mode BTW.

[twalpole]

@thedarkone - slight clarification there -- the app is being run in test mode not dev. Dev mode in rails by default sets cache_classes to false which effectively disables concurrency by adding Rack::Lock to the middleware

[twalpole]

and as @fxn stated the proper solution is for allow_concurrency? to be false if eager_load is false. This issue goes back to at least Rails 4.

[sobrinho]

Well done guys 💃

[fxn]

@sobrinho for apps before 4.2, you can throw

config.allow_concurrency = false

in config/environments/test.rb.

In principle that configuration option is going to go away some day, that's why the patch is based on the logic related to eager loading and multi-threading. But for pre-4.2 that old-school flag is going to be less costly than enabling eager loading.

[divineforest]

@fxn @twalpole thank you :) ❤️ That was a great investigation!

[sobrinho]

Thanks @fxn and @twalpole, nice job!

[monkbroc]

I have been trying to root cause this issue in my app for 2 months! I'm so glad this has been fixed. Thanks everyone for the excellent detective work and thanks @fxn and @twalpole for the fix!

[Intrepidd]

Thanks ! Nice investigation. This bug has driven me nuts.

[jrochkind]

I believe the config/environments/test.rb generated still says:

# Do not eager load code on boot. This avoids loading your whole application
# just for the purpose of running a single test. If you are using a tool that
# preloads Rails for running tests, you may have to set it to true.
config.eager_load = false

Should this advice, that you may have to set config.eager_load to true (essentially for Capybara with javascript driver tests) be changed? Now it's expected there's no reason to do that, what you really needed was config.allow_concurrency = false, and you don't even need that in 4.2+ ?

[fxn]

/cc @matthewd