Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Intermittent failure on test environment about missing constants #15089

Closed
sobrinho opened this issue May 13, 2014 · 59 comments
Closed

Intermittent failure on test environment about missing constants #15089

sobrinho opened this issue May 13, 2014 · 59 comments

Comments

@sobrinho
Copy link
Contributor

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
Copy link
Member

cc @fxn

@sobrinho
Copy link
Contributor Author

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
Copy link
Contributor

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
Copy link
Contributor Author

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

@thedarkone
Copy link
Contributor

@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
Copy link
Member

@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
Copy link
Contributor Author

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

@thedarkone
Copy link
Contributor

@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
Copy link

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
Copy link
Contributor

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
Copy link
Member

fxn commented Sep 9, 2014

@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
Copy link
Contributor

@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
Copy link
Contributor

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

@fxn
Copy link
Member

fxn commented Sep 10, 2014

@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
Copy link
Contributor

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

@fxn
Copy link
Member

fxn commented Sep 10, 2014

@divineforest are those parallel requests served by different threads?

@divineforest
Copy link
Contributor

@fxn yes

@fxn
Copy link
Member

fxn commented Sep 10, 2014

@divineforest why?

@divineforest
Copy link
Contributor

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

@divineforest
Copy link
Contributor

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

/cc @ka8725

@fxn
Copy link
Member

fxn commented Sep 10, 2014

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
Copy link
Contributor Author

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

@rafaelfranca
Copy link
Member

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

@divineforest
Copy link
Contributor

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

@divineforest
Copy link
Contributor

@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
Copy link
Contributor

@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
Copy link
Contributor

@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
Copy link
Contributor

@twalpole

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

@divineforest
Copy link
Contributor

@fxn oh, thanks :)

@fxn
Copy link
Member

fxn commented Sep 18, 2014

@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
Copy link
Contributor

@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
Copy link
Contributor

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
Copy link
Contributor

@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
Copy link
Member

fxn commented Sep 18, 2014

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
Copy link
Contributor

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
Copy link
Member

fxn commented Sep 18, 2014

@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
Copy link
Member

fxn commented Sep 18, 2014

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
Copy link
Contributor

@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
Copy link
Member

fxn commented Sep 18, 2014

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

@fxn
Copy link
Member

fxn commented Sep 18, 2014

@thedarkone the app is running in test mode BTW.

@twalpole
Copy link
Contributor

@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
Copy link
Contributor

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
Copy link
Contributor Author

Well done guys 💃

@fxn fxn closed this as completed in 112077c Sep 18, 2014
@fxn
Copy link
Member

fxn commented Sep 18, 2014

@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.

trungpham pushed a commit to trungpham/rails that referenced this issue Sep 19, 2014
If code is not eager loaded constants are loaded on demand. Constant
autoloading is not thread-safe, so if eager loading is not enabled
multi-threading should not be allowed.

This showed up in certain Capybara scenarios: Most Capybara drivers
other than Rack::Test need a web server. In particular, drivers for
JavaScript support. Capybara launches WEBrick in its own thread for
those but that per se is fine, because the spec thread and the server
thread are coordinated.

Problem comes if the page being served in the spec makes Ajax calls.
Those may hit WEBrick in parallel, and since WEBrick is multi-threaded
and allow_concurrency? returns true in the test environment before
this patch, threads are spawned to serve those parallel requests. On
the other hand, since eager_load is false by default in the test
environment, constants are not preloaded.

So the suite is autoloading constants in a multi-threaded set. That's
a receipt for paracetamol. The symptom is random obscure errors whose
messages point somehow to constant autoloading.

As a consequence of this fix for allow_concurrency? WEBrick in
Capybara scenarios no longer runs in multi-threaded mode.

Fixes rails#15089.
@divineforest
Copy link
Contributor

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

fxn added a commit that referenced this issue Sep 19, 2014
If code is not eager loaded constants are loaded on demand. Constant
autoloading is not thread-safe, so if eager loading is not enabled
multi-threading should not be allowed.

This showed up in certain Capybara scenarios: Most Capybara drivers
other than Rack::Test need a web server. In particular, drivers for
JavaScript support. Capybara launches WEBrick in its own thread for
those but that per se is fine, because the spec thread and the server
thread are coordinated.

Problem comes if the page being served in the spec makes Ajax calls.
Those may hit WEBrick in parallel, and since WEBrick is multi-threaded
and allow_concurrency? returns true in the test environment before
this patch, threads are spawned to serve those parallel requests. On
the other hand, since eager_load is false by default in the test
environment, constants are not preloaded.

So the suite is autoloading constants in a multi-threaded set. That's
a receipt for paracetamol. The symptom is random obscure errors whose
messages point somehow to constant autoloading.

As a consequence of this fix for allow_concurrency? WEBrick in
Capybara scenarios no longer runs in multi-threaded mode.

Fixes #15089.

Conflicts:
	railties/CHANGELOG.md
@sobrinho
Copy link
Contributor Author

Thanks @fxn and @twalpole, nice job!

@monkbroc
Copy link

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
Copy link
Contributor

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

@jrochkind
Copy link
Contributor

jrochkind commented Jan 22, 2016

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
Copy link
Member

fxn commented Jan 22, 2016

/cc @matthewd

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests