Bug 1417661

Created attachment 1245911 [details]
screenshot

Description of problem:

I was logged in with a user I created to cfme. after about an hour I went back to the cfme and got re-directed to the login screen. 
I tried to log in with the admin user (not the user I was logged in with before) and the UI login page seems to get stuck (see screenshot). 
you can keep on pressing the login button and you would get an authentication error. 
we have to reload the page completely and try to login again for a successful login

Version-Release number of selected component (if applicable):

cfme-5.7.1.0-2.el7cf.x86_64

Please note - this was done on a podfied cfme (don't think it's related but mentioning in case it is) 


How reproducible:

randomly (happened a few times)

Steps to Reproduce:
1. create a user with permission role for compute -> containers and log in
2. let the session time out and get re-directed to the main page for login
3. try to login with admin user

Actual results:

we are not logged in. 
both user and password are greyed out but the login button is available 
when pressing the login button and grepping logs we get an error message in the production log for wrong credentials. 

Expected results:

we should be able to login with a different user after a timeout. 

Additional info:

This was tested on a podfied cfme but I don't think it's related to the fact it's a pod. 

sh-4.2# tail -f * |grep -i error
tail: error reading ‘apache’: Is a directory
tail: apache: cannot follow end of this type of file; giving up on this name


[----] F, [2017-01-30T14:39:56.548995 #1862:19b11fc] FATAL -- : Error caught: [ActionController::InvalidAuthenticityToken] ActionController::InvalidAuthenticityToken
[----] F, [2017-01-30T14:40:00.356234 #1862:19af7d0] FATAL -- : Error caught: [ActionController::InvalidAuthenticityToken] ActionController::InvalidAuthenticityToken
^C



/opt/rh/cfme-gemset/gems/actionpack-5.0.0.1/lib/action_controller/metal/request_forgery_protection.rb:195:in `handle_unverified_request'
/opt/rh/cfme-gemset/gems/actionpack-5.0.0.1/lib/action_controller/metal/request_forgery_protection.rb:223:in `handle_unverified_request'
/opt/rh/cfme-gemset/gems/actionpack-5.0.0.1/lib/action_controller/metal/request_forgery_protection.rb:218:in `verify_authenticity_token'
/opt/rh/cfme-gemset/gems/activesupport-5.0.0.1/lib/active_support/callbacks.rb:382:in `block in make_lambda'
/opt/rh/cfme-gemset/gems/activesupport-5.0.0.1/lib/active_support/callbacks.rb:150:in `block (2 levels) in halting_and_conditional'
/opt/rh/cfme-gemset/gems/actionpack-5.0.0.1/lib/abstract_controller/callbacks.rb:12:in `block (2 levels) in <module:Callbacks>'
/opt/rh/cfme-gemset/gems/activesupport-5.0.0.1/lib/active_support/callbacks.rb:151:in `block in halting_and_conditional'
/opt/rh/cfme-gemset/gems/activesupport-5.0.0.1/lib/active_support/callbacks.rb:454:in `block in call'
/opt/rh/cfme-gemset/gems/activesupport-5.0.0.1/lib/active_support/callbacks.rb:454:in `each'
/opt/rh/cfme-gemset/gems/activesupport-5.0.0.1/lib/active_support/callbacks.rb:454:in `call'
/opt/rh/cfme-gemset/gems/activesupport-5.0.0.1/lib/active_support/callbacks.rb:101:in `__run_callbacks__'
/opt/rh/cfme-gemset/gems/activesupport-5.0.0.1/lib/active_support/callbacks.rb:750:in `_run_process_action_callbacks'
/opt/rh/cfme-gemset/gems/activesupport-5.0.0.1/lib/active_support/callbacks.rb:90:in `run_callbacks'
/opt/rh/cfme-gemset/gems/actionpack-5.0.0.1/lib/abstract_controller/callbacks.rb:19:in `process_action'
/opt/rh/cfme-gemset/gems/actionpack-5.0.0.1/lib/action_controller/metal/rescue.rb:20:in `process_action'
/opt/rh/cfme-gemset/gems/actionpack-5.0.0.1/lib/action_controller/metal/instrumentation.rb:32:in `block in process_action'
/opt/rh/cfme-gemset/gems/activesupport-5.0.0.1/lib/active_support/notifications.rb:164:in `block in instrument'
/opt/rh/cfme-gemset/gems/activesupport-5.0.0.1/lib/active_support/notifications/instrumenter.rb:21:in `instrument'
/opt/rh/cfme-gemset/gems/activesupport-5.0.0.1/lib/active_support/notifications.rb:164:in `instrument'
/opt/rh/cfme-gemset/gems/actionpack-5.0.0.1/lib/action_controller/metal/instrumentation.rb:30:in `process_action'
/opt/rh/cfme-gemset/gems/actionpack-5.0.0.1/lib/action_controller/metal/params_wrapper.rb:248:in `process_action'
/opt/rh/cfme-gemset/gems/activerecord-5.0.0.1/lib/active_record/railties/controller_runtime.rb:18:in `process_action'
/opt/rh/cfme-gemset/gems/actionpack-5.0.0.1/lib/abstract_controller/base.rb:126:in `process'
/opt/rh/cfme-gemset/gems/actionview-5.0.0.1/lib/action_view/rendering.rb:30:in `process'
/opt/rh/cfme-gemset/gems/actionpack-5.0.0.1/lib/action_controller/metal.rb:190:in `dispatch'
/opt/rh/cfme-gemset/gems/actionpack-5.0.0.1/lib/action_controller/metal.rb:262:in `dispatch'
/opt/rh/cfme-gemset/gems/actionpack-5.0.0.1/lib/action_dispatch/routing/route_set.rb:50:in `dispatch'
/opt/rh/cfme-gemset/gems/actionpack-5.0.0.1/lib/action_dispatch/routing/route_set.rb:32:in `serve'
/opt/rh/cfme-gemset/gems/actionpack-5.0.0.1/lib/action_dispatch/journey/router.rb:39:in `block in serve'
/opt/rh/cfme-gemset/gems/actionpack-5.0.0.1/lib/action_dispatch/journey/router.rb:26:in `each'
/opt/rh/cfme-gemset/gems/actionpack-5.0.0.1/lib/action_dispatch/journey/router.rb:26:in `serve'
/opt/rh/cfme-gemset/gems/actionpack-5.0.0.1/lib/action_dispatch/routing/route_set.rb:725:in `call'
/opt/rh/cfme-gemset/gems/secure_headers-3.0.3/lib/secure_headers/middleware.rb:10:in `call'
/opt/rh/cfme-gemset/gems/rack-2.0.1/lib/rack/etag.rb:25:in `call'
/opt/rh/cfme-gemset/gems/rack-2.0.1/lib/rack/conditional_get.rb:38:in `call'
/opt/rh/cfme-gemset/gems/rack-2.0.1/lib/rack/head.rb:12:in `call'
/opt/rh/cfme-gemset/gems/rack-2.0.1/lib/rack/session/abstract/id.rb:222:in `context'
/opt/rh/cfme-gemset/gems/rack-2.0.1/lib/rack/session/abstract/id.rb:216:in `call'
/opt/rh/cfme-gemset/gems/actionpack-5.0.0.1/lib/action_dispatch/middleware/cookies.rb:613:in `call'
/opt/rh/cfme-gemset/gems/actionpack-5.0.0.1/lib/action_dispatch/middleware/callbacks.rb:38:in `block in call'
/opt/rh/cfme-gemset/gems/activesupport-5.0.0.1/lib/active_support/callbacks.rb:97:in `__run_callbacks__'
/opt/rh/cfme-gemset/gems/activesupport-5.0.0.1/lib/active_support/callbacks.rb:750:in `_run_call_callbacks'
/opt/rh/cfme-gemset/gems/activesupport-5.0.0.1/lib/active_support/callbacks.rb:90:in `run_callbacks'
/opt/rh/cfme-gemset/gems/actionpack-5.0.0.1/lib/action_dispatch/middleware/callbacks.rb:36:in `call'
/opt/rh/cfme-gemset/gems/actionpack-5.0.0.1/lib/action_dispatch/middleware/remote_ip.rb:79:in `call'
/opt/rh/cfme-gemset/gems/actionpack-5.0.0.1/lib/action_dispatch/middleware/debug_exceptions.rb:49:in `call'
/opt/rh/cfme-gemset/gems/actionpack-5.0.0.1/lib/action_dispatch/middleware/show_exceptions.rb:31:in `call'
/opt/rh/cfme-gemset/gems/railties-5.0.0.1/lib/rails/rack/logger.rb:36:in `call_app'
/opt/rh/cfme-gemset/gems/railties-5.0.0.1/lib/rails/rack/logger.rb:26:in `call'
/opt/rh/cfme-gemset/gems/request_store-1.3.2/lib/request_store/middleware.rb:9:in `call'
/opt/rh/cfme-gemset/gems/actionpack-5.0.0.1/lib/action_dispatch/middleware/request_id.rb:24:in `call'
/opt/rh/cfme-gemset/gems/rack-2.0.1/lib/rack/method_override.rb:22:in `call'
/opt/rh/cfme-gemset/gems/rack-2.0.1/lib/rack/runtime.rb:22:in `call'
/opt/rh/cfme-gemset/gems/activesupport-5.0.0.1/lib/active_support/cache/strategy/local_cache_middleware.rb:28:in `call'
/opt/rh/cfme-gemset/gems/actionpack-5.0.0.1/lib/action_dispatch/middleware/executor.rb:12:in `call'
/opt/rh/cfme-gemset/gems/rack-2.0.1/lib/rack/sendfile.rb:111:in `call'
/opt/rh/cfme-gemset/gems/railties-5.0.0.1/lib/rails/engine.rb:522:in `call'
/opt/rh/rh-ruby23/root/usr/share/gems/gems/puma-3.3.0/lib/puma/configuration.rb:224:in `call'
/opt/rh/rh-ruby23/root/usr/share/gems/gems/puma-3.3.0/lib/puma/server.rb:561:in `handle_request'
/opt/rh/rh-ruby23/root/usr/share/gems/gems/puma-3.3.0/lib/puma/server.rb:406:in `process_client'
/opt/rh/rh-ruby23/root/usr/share/gems/gems/puma-3.3.0/lib/puma/server.rb:271:in `block in run'
/opt/rh/rh-ruby23/root/usr/share/gems/gems/puma-3.3.0/lib/puma/thread_pool.rb:111:in `block in spawn_thread'
[----] I, [2017-01-30T14:39:56.549811 #1862:19b11fc]  INFO -- :   Rendered layouts/_exception_contents.html.haml (0.1ms)
[----] I, [2017-01-30T14:39:56.550244 #1862:19b11fc]  INFO -- : Completed 200 OK in 2ms (Views: 0.9ms | ActiveRecord: 0.0ms)
[----] I, [2017-01-30T14:39:59.764846 #1875:19a3e58]  INFO -- : Started DELETE "/api/auth" for 127.0.0.1 at 2017-01-30 14:39:59 +0000
[----] I, [2017-01-30T14:39:59.766581 #1875:19a3e58]  INFO -- : Processing by Api::AuthController#destroy as JSON
[----] I, [2017-01-30T14:39:59.775363 #1875:199c874]  INFO -- : Started GET "/api/auth?requester_type=ui" for 127.0.0.1 at 2017-01-30 14:39:59 +0000
[----] I, [2017-01-30T14:39:59.780167 #1875:199c874]  INFO -- : Processing by Api::AuthController#show as JSON
[----] I, [2017-01-30T14:39:59.780272 #1875:199c874]  INFO -- :   Parameters: {"requester_type"=>"ui"}
[----] I, [2017-01-30T14:39:59.875674 #1875:19a3e58]  INFO -- : Completed 204 No Content in 109ms (ActiveRecord: 0.0ms)
[----] I, [2017-01-30T14:39:59.966945 #1875:199c874]  INFO -- : Completed 200 OK in 187ms (Views: 0.2ms | ActiveRecord: 0.0ms)
[----] I, [2017-01-30T14:40:00.125264 #1875:199e138]  INFO -- : Started GET "/api/auth?requester_type=ws" for 127.0.0.1 at 2017-01-30 14:40:00 +0000
[----] I, [2017-01-30T14:40:00.128136 #1875:199e138]  INFO -- : Processing by Api::AuthController#show as JSON
[----] I, [2017-01-30T14:40:00.128605 #1875:199e138]  INFO -- :   Parameters: {"requester_type"=>"ws"}
[----] I, [2017-01-30T14:40:00.147380 #1875:199e138]  INFO -- : Completed 200 OK in 19ms (Views: 0.3ms | ActiveRecord: 0.0ms)
[----] I, [2017-01-30T14:40:00.315976 #1862:19ac92c]  INFO -- : Started GET "/" for 127.0.0.1 at 2017-01-30 14:40:00 +0000
[----] I, [2017-01-30T14:40:00.317443 #1862:19ac92c]  INFO -- : Processing by DashboardController#login as HTML
[----] I, [2017-01-30T14:40:00.318935 #1862:19b0734]  INFO -- : Started GET "/" for 127.0.0.1 at 2017-01-30 14:40:00 +0000
[----] I, [2017-01-30T14:40:00.320645 #1862:19b0734]  INFO -- : Processing by DashboardController#login as HTML
[----] I, [2017-01-30T14:40:00.341831 #1862:19ac92c]  INFO -- :   Rendering dashboard/login.html.haml within layouts/login
[----] I, [2017-01-30T14:40:00.344980 #1862:19af7d0]  INFO -- : Started POST "/dashboard/authenticate?button=login" for 127.0.0.1 at 2017-01-30 14:40:00 +0000
[----] I, [2017-01-30T14:40:00.348110 #1862:19af7d0]  INFO -- : Processing by DashboardController#authenticate as JS
[----] I, [2017-01-30T14:40:00.348334 #1862:19af7d0]  INFO -- :   Parameters: {"user_name"=>"admin", "user_password"=>"[FILTERED]", "browser_name"=>"Firefox", "browser_version"=>"38", "browser_os"=>"Linux", "user_TZO"=>"0", "button"=>"login"}
[----] I, [2017-01-30T14:40:00.352007 #1862:19ac92c]  INFO -- :   Rendered layouts/_spinner.html.haml (9.0ms)
[----] I, [2017-01-30T14:40:00.352470 #1862:19ac92c]  INFO -- :   Rendered layouts/_flash_msg.html.haml (0.1ms)
[----] I, [2017-01-30T14:40:00.353074 #1862:19ac92c]  INFO -- :   Rendered dashboard/_login_more.html.haml (0.1ms)
[----] W, [2017-01-30T14:40:00.355938 #1862:19af7d0]  WARN -- : Can't verify CSRF token authenticity.
[----] F, [2017-01-30T14:40:00.356234 #1862:19af7d0] FATAL -- : Error caught: [ActionController::InvalidAuthenticityToken] ActionController::InvalidAuthenticityToken