[Rails 3.1 edge] ActionDispatch::ClosedError: Cannot modify cookies because it was closed. This means it was already streamed back to the client or converted to HTTP headers. #1452

Closed
dreamr opened this Issue Jun 1, 2011 · 33 comments

Comments

Projects
None yet
10 participants

dreamr commented Jun 1, 2011

This is related to the new streaming.

Whenever I post to user_session (using authlogic) via request specs (or for that matter cucumber or controller specs rendering views) For now I have pended these things. I'm betting this is going to be similar to the flash issue.

I don't have time just now to look into this more then I have, maybe this weekend if no one gets to it.

Member

sikachu commented Jun 1, 2011

Do you have any middleware that accessing the cookie?

dreamr commented Jun 1, 2011

Nope, it straight authlogic with the following helpers: https://gist.github.com/1003373
my spec helper: https://gist.github.com/1003383
my request spec: https://gist.github.com/1003385
My user session model: https://gist.github.com/1003387
my factories: https://gist.github.com/1003388

It was working till I upgraded to 3.1 last week.

I have tried quite a few work arounds with no luck yet.

Member

sikachu commented Jun 1, 2011

Thank you. I'll dig around to see if I can reproduce.

Anyway, just to make sure, you're on the latest version of rspec-rails (2.6.1) right? I think all versions before 2.6.1 is broken on Rails 3.1.

dreamr commented Jun 2, 2011

yup.

On Wed, Jun 1, 2011 at 4:33 PM, sikachu <
reply@reply.github.com>wrote:

Thank you. I'll dig around to see if I can reproduce.

Anyway, just to make sure, you're on the latest version of rspec-rails
(2.6.1) right? I think all versions before 2.6.1 is broken on Rails 3.1.

Reply to this email directly or view it on GitHub:
#1452 (comment)

E. James OKelly

Chief Technologist
RubyistLabs, llc.

+1 760 851 1046
james@rubyloves.me

Owner

spastorino commented Jun 2, 2011

@dreamr can you gave us a github repo of a minimal app with the failing test?

aeden commented Jun 5, 2011

I'm seeing the same thing. I also use authlogic. I am seeing the issue with Cucumber features though.

Member

josevalim commented Jun 7, 2011

It seems to be an authlogic issue? It seems to be storing cookies somewhere and modifying them after they are sent back.

Owner

spastorino commented Jun 8, 2011

It would help if any of you guys can share an application that shows the error

aeden commented Jun 8, 2011

I'll try to set up an example.

aeden commented Jun 8, 2011

@dreamr are you also using Factory Girl? Looking at my failing Cucumber scenarios I see that they are actually failing when a User instance is being created with Factory(:user). So far in a test app I've created the same problem does not manifest with Cucumber and Authlogic alone. Still digging...

aeden commented Jun 8, 2011

FactoryGirl was a red herring. I've reproduced the error without it. I'll publish the repo momentarily.

aeden commented Jun 8, 2011

Here's the repo: https://github.com/aeden/rails31_authlogic.

To get it blow up run cucumber.

spastorino was assigned Jun 8, 2011

Same problem here, using ActionController::IntegrationTest, factory_girl, capybara & authlogic (no cucumber). I'll try to find out what's happening in the authlogic after_save callback. Trace:

ActionDispatch::ClosedError: Cannot modify cookies because it was closed. This means it was already streamed back to the client or converted to HTTP headers.
    /Users/nedforce/.rvm/gems/ruby-1.9.2-p180@rails31/gems/actionpack-3.1.0.rc1/lib/action_dispatch/middleware/cookies.rb:157:in `[]='
    /Users/nedforce/.rvm/gems/ruby-1.9.2-p180@rails31/gems/authlogic-3.0.3/lib/authlogic/session/cookies.rb:167:in `save_cookie'
    /Users/nedforce/.rvm/gems/ruby-1.9.2-p180@rails31/gems/activesupport-3.1.0.rc1/lib/active_support/callbacks.rb:395:in `_run_after_save_callbacks'
    /Users/nedforce/.rvm/gems/ruby-1.9.2-p180@rails31/gems/activesupport-3.1.0.rc1/lib/active_support/callbacks.rb:81:in `run_callbacks'
    /Users/nedforce/.rvm/gems/ruby-1.9.2-p180@rails31/gems/authlogic-3.0.3/lib/authlogic/session/callbacks.rb:87:in `after_save'
    /Users/nedforce/.rvm/gems/ruby-1.9.2-p180@rails31/gems/authlogic-3.0.3/lib/authlogic/session/existence.rb:71:in `save'
    /Users/nedforce/.rvm/gems/ruby-1.9.2-p180@rails31/gems/authlogic-3.0.3/lib/authlogic/session/existence.rb:30:in `create'
    /Users/nedforce/.rvm/gems/ruby-1.9.2-p180@rails31/gems/authlogic-3.0.3/lib/authlogic/acts_as_authentic/session_maintenance.rb:113:in `create_session'
    /Users/nedforce/.rvm/gems/ruby-1.9.2-p180@rails31/gems/authlogic-3.0.3/lib/authlogic/acts_as_authentic/session_maintenance.rb:103:in `maintain_sessions'
    /Users/nedforce/.rvm/gems/ruby-1.9.2-p180@rails31/gems/activesupport-3.1.0.rc1/lib/active_support/callbacks.rb:418:in `_run_save_callbacks'
    /Users/nedforce/.rvm/gems/ruby-1.9.2-p180@rails31/gems/activesupport-3.1.0.rc1/lib/active_support/callbacks.rb:81:in `run_callbacks'
    /Users/nedforce/.rvm/gems/ruby-1.9.2-p180@rails31/gems/activerecord-3.1.0.rc1/lib/active_record/callbacks.rb:264:in `create_or_update'
    /Users/nedforce/.rvm/gems/ruby-1.9.2-p180@rails31/gems/activerecord-3.1.0.rc1/lib/active_record/persistence.rb:53:in `save!'
    /Users/nedforce/.rvm/gems/ruby-1.9.2-p180@rails31/gems/activerecord-3.1.0.rc1/lib/active_record/validations.rb:56:in `save!'
    /Users/nedforce/.rvm/gems/ruby-1.9.2-p180@rails31/gems/activerecord-3.1.0.rc1/lib/active_record/attribute_methods/dirty.rb:33:in `save!'
    /Users/nedforce/.rvm/gems/ruby-1.9.2-p180@rails31/gems/activerecord-3.1.0.rc1/lib/active_record/transactions.rb:246:in `block in save!'
    /Users/nedforce/.rvm/gems/ruby-1.9.2-p180@rails31/gems/activerecord-3.1.0.rc1/lib/active_record/transactions.rb:295:in `block in with_transaction_returning_status'
    /Users/nedforce/.rvm/gems/ruby-1.9.2-p180@rails31/gems/activerecord-3.1.0.rc1/lib/active_record/connection_adapters/abstract/database_statements.rb:183:in `transaction'
    /Users/nedforce/.rvm/gems/ruby-1.9.2-p180@rails31/gems/activerecord-3.1.0.rc1/lib/active_record/transactions.rb:208:in `transaction'
    /Users/nedforce/.rvm/gems/ruby-1.9.2-p180@rails31/gems/activerecord-3.1.0.rc1/lib/active_record/transactions.rb:293:in `with_transaction_returning_status'
    /Users/nedforce/.rvm/gems/ruby-1.9.2-p180@rails31/gems/activerecord-3.1.0.rc1/lib/active_record/transactions.rb:246:in `save!'
    /Users/nedforce/.rvm/gems/ruby-1.9.2-p180@rails31/gems/factory_girl-1.3.3/lib/factory_girl/proxy/create.rb:6:in `result'
    /Users/nedforce/.rvm/gems/ruby-1.9.2-p180@rails31/gems/factory_girl-1.3.3/lib/factory_girl/factory.rb:330:in `run'
    /Users/nedforce/.rvm/gems/ruby-1.9.2-p180@rails31/gems/factory_girl-1.3.3/lib/factory_girl/factory.rb:273:in `create'
    /Users/nedforce/.rvm/gems/ruby-1.9.2-p180@rails31/gems/factory_girl-1.3.3/lib/factory_girl/factory.rb:304:in `default_strategy'
    /Users/nedforce/.rvm/gems/ruby-1.9.2-p180@rails31/gems/factory_girl-1.3.3/lib/factory_girl.rb:20:in `Factory'
    /Users/nedforce/projects/wizer/test/integration/authentication_test.rb:6:in `block in <class:AuthenticationTest>'

This has not been fixed in RC4 either. Is this an authlogic or an actiondispatch issue? Note that I found out that it works when running one test at a time, but running 'rake test:integration' when having multiple tests or when running one test class with multiple test definitions in it, it fails.

Owner

spastorino commented Jun 15, 2011

@moiristo @aeden @dreamr I'd like to see a minimal app without cucumber too. If you guys can set up the minimal app that makes this fail that would help a lot. So NO fgirl, NO cucumber, NO capybara is that possible?. Just Rails 3.1.rc4 + authlogic the latest version. I will take a look right now.

Owner

spastorino commented Jun 15, 2011

Another question the app works ok and it's failing in the test environment or do you get the error also in development and production?

No, it's only failing in the test env. I'll try to strip out fgirl & capybara in my current app..

Owner

spastorino commented Jun 15, 2011

@moiristo that's great if you can share with me a reduced sample app I will take a look ;)

Hi, I created a sample app using plain ol' ActionController::IntegrationTest which also raises the same error: https://github.com/moiristo/rails31_al_cookie_bug

Member

josevalim commented Jun 17, 2011

This is an authlogic bug. It is storing an instance of the controller in a thread variables and modifying the cookies after the response is sent back to the client.

You can clearly see in the backtrace that the error comes from a model callback. This is nasty. Storing the controller in threads variables so it can be accessible from the model is one of the worst ways to violate MVC.

josevalim closed this Jun 17, 2011

Contributor

subelsky commented Jun 26, 2011

Calling it a "crime" is a little harsh. The whole point of Authlogic is letting you abstract session data as just another model in your app. I'm going to try and think of a cleaner way to pass the session data that authlogic needs, in a cleaner way. Maybe as a before_filter or middleware.

Sjors commented Jul 27, 2011

How come this issue was closed 3 years before it was opened? I get the same error message running a Cucumber test as soon as I create a user. My app uses Authlogic too.
The issue is also discussed in the authlogic gem:
binarylogic/authlogic#262

sreid99 commented Aug 13, 2011

Don't think this is just an authlogic bug. I'm using devise / rails 3.1rc5 and also getting :

ActionDispatch::ClosedError / Cannot modify cookies because it was closed. This means it was already streamed back to the client or converted to HTTP headers.

actionpack (3.1.0.rc5) lib/action_dispatch/middleware/cookies.rb:162:in []=' actionpack (3.1.0.rc5) lib/action_dispatch/middleware/cookies.rb:291:in[]='
actionpack (3.1.0.rc5) lib/action_dispatch/middleware/session/cookie_store.rb:67:in set_cookie' rack (1.3.2) lib/rack/session/abstract/id.rb:311:incommit_session'
rack (1.3.2) lib/rack/session/abstract/id.rb:196:in context' rack (1.3.2) lib/rack/session/abstract/id.rb:190:incall'
actionpack (3.1.0.rc5) lib/action_dispatch/middleware/cookies.rb:326:in call' activerecord (3.1.0.rc5) lib/active_record/query_cache.rb:62:incall'
activerecord (3.1.0.rc5) lib/active_record/connection_adapters/abstract/connection_pool.rb:466:in call' actionpack (3.1.0.rc5) lib/action_dispatch/middleware/callbacks.rb:29:incall'
activesupport (3.1.0.rc5) lib/active_support/callbacks.rb:392:in _run_call_callbacks' activesupport (3.1.0.rc5) lib/active_support/callbacks.rb:81:insend'
activesupport (3.1.0.rc5) lib/active_support/callbacks.rb:81:in run_callbacks' actionpack (3.1.0.rc5) lib/action_dispatch/middleware/callbacks.rb:28:incall'
actionpack (3.1.0.rc5) lib/action_dispatch/middleware/reloader.rb:68:in call' actionpack (3.1.0.rc5) lib/action_dispatch/middleware/remote_ip.rb:48:incall'
vidibus-routing_error (0.2.0) lib/./lib/vidibus/routing_error/rack.rb:13:in call' actionpack (3.1.0.rc5) lib/action_dispatch/middleware/show_exceptions.rb:47:incall'
railties (3.1.0.rc5) lib/rails/rack/logger.rb:13:in call' rack (1.3.2) lib/rack/methodoverride.rb:24:incall'
rack (1.3.2) lib/rack/runtime.rb:17:in call' activesupport (3.1.0.rc5) lib/active_support/cache/strategy/local_cache.rb:72:incall'
rack (1.3.2) lib/rack/lock.rb:15:in call' actionpack (3.1.0.rc5) lib/action_dispatch/middleware/static.rb:53:incall'
railties (3.1.0.rc5) lib/rails/engine.rb:455:in call' railties (3.1.0.rc5) lib/rails/railtie/configurable.rb:30:insend'
railties (3.1.0.rc5) lib/rails/railtie/configurable.rb:30:in method_missing' rack (1.3.2) lib/rack/showexceptions.rb:24:incall'
railties (3.1.0.rc5) lib/rails/rack/content_length.rb:16:in call' railties (3.1.0.rc5) lib/rails/rack/log_tailer.rb:14:incall'
rack (1.3.2) lib/rack/handler/webrick.rb:59:in service' C:/RailsInstaller/Ruby1.8.7/lib/ruby/1.8/webrick/httpserver.rb:104:inservice'
C:/RailsInstaller/Ruby1.8.7/lib/ruby/1.8/webrick/httpserver.rb:65:in run' C:/RailsInstaller/Ruby1.8.7/lib/ruby/1.8/webrick/server.rb:173:instart_thread'
C:/RailsInstaller/Ruby1.8.7/lib/ruby/1.8/webrick/server.rb:162:in start' C:/RailsInstaller/Ruby1.8.7/lib/ruby/1.8/webrick/server.rb:162:instart_thread'
C:/RailsInstaller/Ruby1.8.7/lib/ruby/1.8/webrick/server.rb:95:in start' C:/RailsInstaller/Ruby1.8.7/lib/ruby/1.8/webrick/server.rb:92:ineach'
C:/RailsInstaller/Ruby1.8.7/lib/ruby/1.8/webrick/server.rb:92:in start' C:/RailsInstaller/Ruby1.8.7/lib/ruby/1.8/webrick/server.rb:23:instart'
C:/RailsInstaller/Ruby1.8.7/lib/ruby/1.8/webrick/server.rb:82:in start' rack (1.3.2) lib/rack/handler/webrick.rb:13:inrun'
rack (1.3.2) lib/rack/server.rb:265:in start' railties (3.1.0.rc5) lib/rails/commands/server.rb:70:instart'
railties (3.1.0.rc5) lib/rails/commands.rb:54
railties (3.1.0.rc5) lib/rails/commands.rb:49:in tap' railties (3.1.0.rc5) lib/rails/commands.rb:49 script/rails:6:inrequire'
script/rails:6

Owner

spastorino commented Aug 13, 2011

@sreid99 can you share a minimal failing app for us to check?

sreid99 commented Aug 13, 2011

That could take me quite a while - I assume you'd need access to the code ?
Is there a quicker way - logs files / doing some guided debugging myself etc. ?

Member

josevalim commented Aug 13, 2011

@sreid99 we do need a failure app to reproduce this.

sreid99 commented Aug 13, 2011

I managed to clear the error for my case. I had a line in the index view for my user controller, of the form :

<%= link_to "Re-generate all users", regenerate_all_users_user_path, :method => :put %>

I fixed it adding an unused param. :

<%= link_to "Re-generate all users", regenerate_all_users_user_path(@users.first), :method => :put %>

aeden commented Aug 13, 2011

@sreid99 you didn't fix it, you worked around the issue. Nothing wrong with that but the issue still needs to be fixed.

Member

sikachu commented Aug 14, 2011

What does vidibus-routing_error do? It's sound very fishy in that stack trace.

Sent from my iPad

On 13 ส.ค. 2554, at 10:55, sreid99reply@reply.github.com wrote:

Don't think this is just an authlogic bug. I'm using devise / rails 3.1rc5 and also getting :

ActionDispatch::ClosedError / Cannot modify cookies because it was closed. This means it was already streamed back to the client or converted to HTTP headers.

actionpack (3.1.0.rc5) lib/action_dispatch/middleware/cookies.rb:162:in []=' actionpack (3.1.0.rc5) lib/action_dispatch/middleware/cookies.rb:291:in[]='
actionpack (3.1.0.rc5) lib/action_dispatch/middleware/session/cookie_store.rb:67:in set_cookie' rack (1.3.2) lib/rack/session/abstract/id.rb:311:incommit_session'
rack (1.3.2) lib/rack/session/abstract/id.rb:196:in context' rack (1.3.2) lib/rack/session/abstract/id.rb:190:incall'
actionpack (3.1.0.rc5) lib/action_dispatch/middleware/cookies.rb:326:in call' activerecord (3.1.0.rc5) lib/active_record/query_cache.rb:62:incall'
activerecord (3.1.0.rc5) lib/active_record/connection_adapters/abstract/connection_pool.rb:466:in call' actionpack (3.1.0.rc5) lib/action_dispatch/middleware/callbacks.rb:29:incall'
activesupport (3.1.0.rc5) lib/active_support/callbacks.rb:392:in _run_call_callbacks' activesupport (3.1.0.rc5) lib/active_support/callbacks.rb:81:insend'
activesupport (3.1.0.rc5) lib/active_support/callbacks.rb:81:in run_callbacks' actionpack (3.1.0.rc5) lib/action_dispatch/middleware/callbacks.rb:28:incall'
actionpack (3.1.0.rc5) lib/action_dispatch/middleware/reloader.rb:68:in call' actionpack (3.1.0.rc5) lib/action_dispatch/middleware/remote_ip.rb:48:incall'
vidibus-routing_error (0.2.0) lib/./lib/vidibus/routing_error/rack.rb:13:in call' actionpack (3.1.0.rc5) lib/action_dispatch/middleware/show_exceptions.rb:47:incall'
railties (3.1.0.rc5) lib/rails/rack/logger.rb:13:in call' rack (1.3.2) lib/rack/methodoverride.rb:24:incall'
rack (1.3.2) lib/rack/runtime.rb:17:in call' activesupport (3.1.0.rc5) lib/active_support/cache/strategy/local_cache.rb:72:incall'
rack (1.3.2) lib/rack/lock.rb:15:in call' actionpack (3.1.0.rc5) lib/action_dispatch/middleware/static.rb:53:incall'
railties (3.1.0.rc5) lib/rails/engine.rb:455:in call' railties (3.1.0.rc5) lib/rails/railtie/configurable.rb:30:insend'
railties (3.1.0.rc5) lib/rails/railtie/configurable.rb:30:in method_missing' rack (1.3.2) lib/rack/showexceptions.rb:24:incall'
railties (3.1.0.rc5) lib/rails/rack/content_length.rb:16:in call' railties (3.1.0.rc5) lib/rails/rack/log_tailer.rb:14:incall'
rack (1.3.2) lib/rack/handler/webrick.rb:59:in service' C:/RailsInstaller/Ruby1.8.7/lib/ruby/1.8/webrick/httpserver.rb:104:inservice'
C:/RailsInstaller/Ruby1.8.7/lib/ruby/1.8/webrick/httpserver.rb:65:in run' C:/RailsInstaller/Ruby1.8.7/lib/ruby/1.8/webrick/server.rb:173:instart_thread'
C:/RailsInstaller/Ruby1.8.7/lib/ruby/1.8/webrick/server.rb:162:in start' C:/RailsInstaller/Ruby1.8.7/lib/ruby/1.8/webrick/server.rb:162:instart_thread'
C:/RailsInstaller/Ruby1.8.7/lib/ruby/1.8/webrick/server.rb:95:in start' C:/RailsInstaller/Ruby1.8.7/lib/ruby/1.8/webrick/server.rb:92:ineach'
C:/RailsInstaller/Ruby1.8.7/lib/ruby/1.8/webrick/server.rb:92:in start' C:/RailsInstaller/Ruby1.8.7/lib/ruby/1.8/webrick/server.rb:23:instart'
C:/RailsInstaller/Ruby1.8.7/lib/ruby/1.8/webrick/server.rb:82:in start' rack (1.3.2) lib/rack/handler/webrick.rb:13:inrun'
rack (1.3.2) lib/rack/server.rb:265:in start' railties (3.1.0.rc5) lib/rails/commands/server.rb:70:instart'
railties (3.1.0.rc5) lib/rails/commands.rb:54
railties (3.1.0.rc5) lib/rails/commands.rb:49:in tap' railties (3.1.0.rc5) lib/rails/commands.rb:49 script/rails:6:inrequire'
script/rails:6

Reply to this email directly or view it on GitHub:
#1452 (comment)

sreid99 commented Aug 14, 2011

vidibus-routing_error (https://github.com/vidibus/vidibus-routing_error) is used to workaround a 404 page error in rails 3 (see https://rails.lighthouseapp.com/projects/8994/tickets/4444-can-no-longer-rescue_from-actioncontrollerroutingerror). Without it I get a routing error displayed for invalid urls (e.g. www.example.com/33333), instead of a 404 page. The link above said it might be fixed in Rails 3.1.

I just removed vidibus-routing_error, and found the following :

  • the routing error display still exists in rails 3.1
  • instead of the original ActionDispatch::ClosedError error above, I'm now getting a 404 page when I use

<%= link_to "Re-generate all users", regenerate_all_users_user_path, :method => :put %>

The change below still works :

<%= link_to "Re-generate all users", regenerate_all_users_user_path(@users.first), :method => :put %>

For now vidibus-routing_error plus the "fix" above, solves both issues in my case.

Member

sikachu commented Aug 14, 2011

So that means the vidibus-routing_error plugin may access the cookie, and that regenerate_all_users_user_path path is actually not exists, or it requires that user argument. As that plugin trying to rescue the 404 error, it raises another error on accessing the cookie.

I think that mean there's nothing to be fixed here on the Rails side, as it should be fixed on the plugin by not accessing/modifying the cookie.

snelson commented Aug 15, 2011

I did some digging into this for AuthLogic and found it seems to indeed be an AuthLogic issue, but not where @josevalim was pointing. The issue is in its automatic session maintenance here:

https://github.com/binarylogic/authlogic/blob/master/lib/authlogic/acts_as_authentic/session_maintenance.rb#L66

So, if you create a model that actsasauthentic outside of a controller request, like to factory a user to login with, that's when you get ActionDispatch::ClosedError, not during the controller request.

More detail and possible solutions here:

binarylogic/authlogic#262 (comment)

subelsky referenced this issue in binarylogic/authlogic Oct 13, 2013

Open

Rails 3.1rc1 streaming breaks AuthLogic session #262

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