Bug 838428

Hope the following will be helpful to you:


Started GET "/app/terms/accept" for 203.114.244.88 at Mon Jul 09 05:23:30 -0400 2012
[Barista] Compiling all scripts for barista
[Barista] Compiling all coffeescripts
[Barista] Copying all javascripts
> Unable to verify cookie signature, session cannot be decoded
  Processing by TermsController#new as HTML
  Streamline call (428.0ms) roles! /wapps/streamline/cloudVerify.html [ response: {"username"=>"yujzhang+new8897", "roles"=>["simple_authenticated"]}, code: 200, args: {} ]
  Streamline call (525.7ms) terms /wapps/streamline/protected/findUnacknowledgedTerms.html?hostname=openshift.redhat.com&context=OPENSHIFT&locale=en [ response: {"unacknowledgedTerms"=>[{"termUrl"=>"http://openshift.redhat.com/app/legal/services_agreement", "termId"=>1046, "termTitle"=>"OpenShift Service Agreement"}, {"termUrl"=>"http://www.redhat.com/legal/legal_statement.html", "termId"=>1, "termTitle"=>"Red Hat Site Terms"}, {"termUrl"=>"https://access.redhat.com/help/terms_conditions.html", "termId"=>1010, "termTitle"=>"Red Hat Portals Terms of Use"}]}, code: 200, args: {} ]
Rendered layouts/_head.html.haml (12.8ms)
Rendered layouts/site/_stylesheets.html.haml (4.2ms)
Rendered layouts/simple/_header.html.haml (8.5ms)
Rendered layouts/site/_javascripts.html.haml (12.1ms)
Rendered terms/new.html.haml within layouts/simple (98.4ms)
Completed 200 OK in 1252ms (Views: 127.7ms | Streamline: 953.7ms)


Started POST "/app/terms" for 203.114.244.88 at Mon Jul 09 05:23:36 -0400 2012
[Barista] Compiling all scripts for barista
[Barista] Compiling all coffeescripts
[Barista] Copying all javascripts
> Unable to verify cookie signature, session cannot be decoded
  Processing by TermsController#create as HTML
  Parameters: {"authenticity_token"=>"vNoVUQMo1N0XNCkSNyfiJsrqF1F9PMMD2YduF9bmh88=", "utf8"=>"✓", "commit"=>"I Accept"}
Access denied: Request authenticity token does not match session {"session_id"=>"b7d3f4376e89f11bfc71904c93d71db2", "_csrf_token"=>"9TLl1sFGryo9DH1nyYy6PS6aMfyMGDX9mA1q1Dp1LNs="}
Redirected to https://openshifttest.redhat.com/app/logout?cause=Request+authenticity+token+does+not+match+session+%7B%22session_id%22%3D%3E%22b7d3f4376e89f11bfc71904c93d71db2%22%2C+%22_csrf_token%22%3D%3E%229TLl1sFGryo9DH1nyYy6PS6aMfyMGDX9mA1q1Dp1LNs%3D%22%7D&then=%2Fapp%2Faccount
Completed 302 Found in 3ms


Started GET "/app/logout?cause=Request+authenticity+token+does+not+match+session+%7B%22session_id%22%3D%3E%22b7d3f4376e89f11bfc71904c93d71db2%22%2C+%22_csrf_token%22%3D%3E%229TLl1sFGryo9DH1nyYy6PS6aMfyMGDX9mA1q1Dp1LNs%3D%22%7D&then=%2Fapp%2Faccount" for 203.114.244.88 at Mon Jul 09 05:23:36 -0400 2012
[Barista] Compiling all scripts for barista
[Barista] Compiling all coffeescripts
[Barista] Copying all javascripts
  Processing by LogoutController#show as HTML
  Parameters: {"then"=>"/app/account", "cause"=>"Request authenticity token does not match session {\"session_id\"=>\"b7d3f4376e89f11bfc71904c93d71db2\", \"_csrf_token\"=>\"9TLl1sFGryo9DH1nyYy6PS6aMfyMGDX9mA1q1Dp1LNs=\"}"}
  Streamline call (427.7ms) roles! /wapps/streamline/cloudVerify.html [ response: {"username"=>"yujzhang+new8897", "roles"=>["simple_authenticated"]}, code: 200, args: {} ]
  Streamline call (421.4ms) logout /wapps/sso/logout.html [ code: 302 ]
  Removing current SSO cookie value of '0|2nogIm2XAXEfYQ1YMoFc3EJwrcIgqBXZeVj'
Rendered layouts/_head.html.haml (12.9ms)
Rendered layouts/site/_stylesheets.html.haml (4.9ms)
Rendered layouts/simple/_header.html.haml (9.2ms)
Rendered layouts/site/_javascripts.html.haml (13.0ms)
Rendered logout/show.html.haml within layouts/simple (200.0ms)
Completed 200 OK in 1114ms (Views: 204.0ms | Streamline: 849.1ms)

I pushed changes to master that provide better debugging of failures to deserialize the request when the user is in development mode.  Please update your devenv so that you have commit "Add better debugging to session_trace..." c226c1c and recreate your scenario.

This is the signout on cookies issue, not an issue specific to the new feature (I was able to login successfully locally).

Was able to recreate locally 

> Session unreadable (ArgumentError: dump format error(0x85)): BAh7DSIKbG9naW4iG2Njb2xlbWFuKzI0QHJlZGhhdC5jb20iEF9jc3JmX3Rva2VuIjE2R2tvVzUwZFlPRkR0bEFPWEhvSWxVUDVVVG96blN2ZGVja2tVUkx3L3djPSIKZmxhc2hJQzolQWN0aW9uRGlzcGF0Y2g6OkZsYXNoOjpGbGFzaEhhc2h7BjoLbm90aWNlIidDcmVhdGUgeW91ciBmaXJzdCBhcHBsaWNhdGlvbiBub3chBjoKQHVzZWRvOghTZXQGOgpAaGFzaHsAIgt0aWNrZXQiKjB8UlhiTXBtU21EN2dkSXN2cEp0eUpLVjBrOWhRcGVhS3M0V1MiD3Nlc3Npb25faWQiJTAwMTgxMmM5ZWUwNGY3NDAxNGE0OTEwNDc1Y2I4ZDJhIgp0ZXJtc1QiFHRpY2tldF92ZXJpZmllZGwrB5Tx k8iFHN0cmVhbWxpbmVfdHlwZToLc2ltcGxl

This is caused by a cookie escaping/unescaping problem that has been in our codebase since september of last year.  The session cookie was not properly encoded when written to the response (specifically, + was not converted to %2B) and so when it was then returned to the user it was not properly decoded (+ decodes to space).  This meant the session was invalid and could not be loaded.

The original patch was to let rh_sso be written without encoding (2fb92fbd), but the patch applied to all cookies.  Made the patch only apply to specific known cookies.

Waiting for clean build to merge.

(In reply to comment #4)
Tried this on devenv_1882 today, I registered a new account and after clicking to the "Accept" button ,I was token to the https://ec2-107-22-63-243.compute-1.amazonaws.com/app/console/application_types page, but meet "ActiveResource::ServerError in ApplicationTypesController#index " error, the log is as following:

Started GET "/app/console/application_types" for 203.114.244.88 at Mon Jul 09 23:39:39 -0400 2012
[Barista] Compiling all scripts for barista
[Barista] Compiling all coffeescripts
[Barista] Copying all javascripts
> Session: {"terms"=>true, "ticket_verified"=>1341891568, "ticket"=>"0|MrtFuaKzi4ZVFH5xkpXK1WlNXuLHhiYeukg", "streamline_type"=>:simple, "_csrf_token"=>"mrdIqzKQMzs6ER6cn6tNRCvZaLTWexfGHkyDV7R9X80=", "session_id"=>"7edebcd42ea7577cff3dc9e1264611e3", "flash"=>{:notice=>"Create your first application now!"}, "login"=>"yujzhang+iio"}
  Processing by ApplicationTypesController#index as HTML
  Login required
  Session contents: {"terms"=>true, "ticket_verified"=>1341891568, "ticket"=>"0|MrtFuaKzi4ZVFH5xkpXK1WlNXuLHhiYeukg", "streamline_type"=>:simple, "_csrf_token"=>"mrdIqzKQMzs6ER6cn6tNRCvZaLTWexfGHkyDV7R9X80=", "session_id"=>"7edebcd42ea7577cff3dc9e1264611e3", "flash"=>{:notice=>"Create your first application now!"}, "login"=>"yujzhang+iio"}
  ^[[1m^[[34mOpenShift API (186.7ms)^[[0m ^[[1m^[[1mget^[[0m https://localhost:443/broker/rest/cartridges.json [ code: ^[[1m^[[1m500^[[0m ]
Completed 500 Internal Server Error in 243ms

ActiveResource::ServerError (Failed.  Response code = 500.  Response message = Internal Server Error.):
  lib/active_resource/persistent_connection.rb:188:in `handle_response'
  lib/active_resource/persistent_connection.rb:155:in `request'
  app/models/rest_api/base.rb:627:in `get'
  lib/active_resource/persistent_connection.rb:267:in `with_auth'
  app/models/rest_api/base.rb:627:in `get'
  app/models/rest_api/base.rb:509:in `find_every'
  app/models/rest_api/base.rb:344:in `find'
  app/models/rest_api/cacheable.rb:41:in `send'
  app/models/rest_api/cacheable.rb:41:in `all'
  app/models/rest_api/cacheable.rb:40:in `all'
  app/models/cartridge_type.rb:104:in `standalone'
  app/models/application_type.rb:64:in `find_every'
  app/models/application_type.rb:52:in `find'
  app/models/application_type.rb:43:in `all'
  app/controllers/application_types_controller.rb:4:in `index'
  app/models/rest_api/railties/controller_runtime.rb:12:in `process_action'
  lib/streamline/railties/controller_runtime.rb:12:in `process_action'

Rendered /usr/lib/ruby/gems/1.8/gems/actionpack-3.0.13/lib/action_dispatch/middleware/templates/rescues/_trace.erb (2.4ms)
Rendered /usr/lib/ruby/gems/1.8/gems/actionpack-3.0.13/lib/action_dispatch/middleware/templates/rescues/_request_and_response.erb (101.8ms)
Rendered /usr/lib/ruby/gems/1.8/gems/actionpack-3.0.13/lib/action_dispatch/middleware/templates/rescues/diagnostics.erb within rescues/layout (110.9ms)


Started GET "/app/console/application_types" for 203.114.244.88 at Mon Jul 09 23:39:48 -0400 2012
[Barista] Compiling all scripts for barista
[Barista] Compiling all coffeescripts
[Barista] Copying all javascripts
> Session: {"terms"=>true, "ticket_verified"=>1341891568, "ticket"=>"0|MrtFuaKzi4ZVFH5xkpXK1WlNXuLHhiYeukg", "streamline_type"=>:simple, "_csrf_token"=>"mrdIqzKQMzs6ER6cn6tNRCvZaLTWexfGHkyDV7R9X80=", "session_id"=>"7edebcd42ea7577cff3dc9e1264611e3", "flash"=>{:notice=>"Create your first application now!"}, "login"=>"yujzhang+iio"}
  Processing by ApplicationTypesController#index as HTML
  Login required
  Session contents: {"terms"=>true, "ticket_verified"=>1341891568, "ticket"=>"0|MrtFuaKzi4ZVFH5xkpXK1WlNXuLHhiYeukg", "streamline_type"=>:simple, "_csrf_token"=>"mrdIqzKQMzs6ER6cn6tNRCvZaLTWexfGHkyDV7R9X80=", "session_id"=>"7edebcd42ea7577cff3dc9e1264611e3", "flash"=>{:notice=>"Create your first application now!"}, "login"=>"yujzhang+iio"}
  ^[[1m^[[34mOpenShift API (184.5ms)^[[0m ^[[1m^[[1mget^[[0m https://localhost:443/broker/rest/cartridges.json [ code: ^[[1m^[[1m500^[[0m ]
Completed 500 Internal Server Error in 233ms

ActiveResource::ServerError (Failed.  Response code = 500.  Response message = Internal Server Error.):
  lib/active_resource/persistent_connection.rb:188:in `handle_response'
  lib/active_resource/persistent_connection.rb:155:in `request'
  app/models/rest_api/base.rb:627:in `get'
  lib/active_resource/persistent_connection.rb:267:in `with_auth'
  app/models/rest_api/base.rb:627:in `get'
  app/models/rest_api/base.rb:509:in `find_every'
  app/models/rest_api/base.rb:344:in `find'
  app/models/rest_api/cacheable.rb:41:in `send'
  app/models/rest_api/cacheable.rb:41:in `all'
  app/models/rest_api/cacheable.rb:40:in `all'
  app/models/cartridge_type.rb:104:in `standalone'
  app/models/application_type.rb:64:in `find_every'
  app/models/application_type.rb:52:in `find'
  app/models/application_type.rb:43:in `all'
  app/controllers/application_types_controller.rb:4:in `index'
  app/models/rest_api/railties/controller_runtime.rb:12:in `process_action'

Rendered /usr/lib/ruby/gems/1.8/gems/actionpack-3.0.13/lib/action_dispatch/middleware/templates/rescues/_trace.erb (2.3ms)
Rendered /usr/lib/ruby/gems/1.8/gems/actionpack-3.0.13/lib/action_dispatch/middleware/templates/rescues/_request_and_response.erb (98.8ms)
Rendered /usr/lib/ruby/gems/1.8/gems/actionpack-3.0.13/lib/action_dispatch/middleware/templates/rescues/diagnostics.erb within rescues/layout (107.1ms)

Please check this asap in case it will also block today's testing.

This caused by our config error, tested this issue again, the bug has been fixed now.