Greenlight: Improve user notification upon failed ldap authentication request (CSRF token expired)

[simonschweizer]

We observe the following error / fatal log messages in our server log file, resulting in a 500 response to clients.

Context: We are using an ldap authentication provider in our environment.

2020-11-06 09:01:59 +0000 - WARN: [UUID] Can't verify CSRF token authenticity.
2020-11-06 09:01:59 +0000 - INFO: [UUID] method=POST path=/b/auth/ldap format=html controller=SessionsController action=ldap status=422 error='ActionController::InvalidAuthenticityToken: ActionController::InvalidAuthenticityToken' duration=6.43 view=0.00 db=0.93 host=greenlight
2020-11-06 09:01:59 +0000 - FATAL: [UUID]
2020-11-06 09:01:59 +0000 - FATAL: [UUID] ActionController::InvalidAuthenticityToken (ActionController::InvalidAuthenticityToken):
2020-11-06 09:01:59 +0000 - FATAL: [UUID]
2020-11-06 09:01:59 +0000 - FATAL: [UUID] vendor/bundle/ruby/2.5.0/gems/actionpack-5.2.4.4/lib/action_controller/metal/request_forgery_protection.rb:211:in `handle_unverified_request'
[UUID] vendor/bundle/ruby/2.5.0/gems/actionpack-5.2.4.4/lib/action_controller/metal/request_forgery_protection.rb:243:in `handle_unverified_request'
[UUID] vendor/bundle/ruby/2.5.0/gems/actionpack-5.2.4.4/lib/action_controller/metal/request_forgery_protection.rb:238:in `verify_authenticity_token'
[UUID] vendor/bundle/ruby/2.5.0/gems/activesupport-5.2.4.4/lib/active_support/callbacks.rb:426:in `block in make_lambda'
[UUID] vendor/bundle/ruby/2.5.0/gems/activesupport-5.2.4.4/lib/active_support/callbacks.rb:179:in `block (2 levels) in halting_and_conditional'
[UUID] vendor/bundle/ruby/2.5.0/gems/actionpack-5.2.4.4/lib/abstract_controller/callbacks.rb:34:in `block (2 levels) in <module:Callbacks>'
[UUID] vendor/bundle/ruby/2.5.0/gems/activesupport-5.2.4.4/lib/active_support/callbacks.rb:180:in `block in halting_and_conditional'
[UUID] vendor/bundle/ruby/2.5.0/gems/activesupport-5.2.4.4/lib/active_support/callbacks.rb:513:in `block in invoke_before'
[UUID] vendor/bundle/ruby/2.5.0/gems/activesupport-5.2.4.4/lib/active_support/callbacks.rb:513:in `each'
[UUID] vendor/bundle/ruby/2.5.0/gems/activesupport-5.2.4.4/lib/active_support/callbacks.rb:513:in `invoke_before'
[UUID] vendor/bundle/ruby/2.5.0/gems/activesupport-5.2.4.4/lib/active_support/callbacks.rb:131:in `run_callbacks'
[UUID] vendor/bundle/ruby/2.5.0/gems/actionpack-5.2.4.4/lib/abstract_controller/callbacks.rb:41:in `process_action'
[UUID] vendor/bundle/ruby/2.5.0/gems/actionpack-5.2.4.4/lib/action_controller/metal/rescue.rb:22:in `process_action'
[UUID] vendor/bundle/ruby/2.5.0/gems/actionpack-5.2.4.4/lib/action_controller/metal/instrumentation.rb:34:in `block in process_action'
[UUID] vendor/bundle/ruby/2.5.0/gems/activesupport-5.2.4.4/lib/active_support/notifications.rb:168:in `block in instrument'
[UUID] vendor/bundle/ruby/2.5.0/gems/activesupport-5.2.4.4/lib/active_support/notifications/instrumenter.rb:23:in `instrument'
[UUID] vendor/bundle/ruby/2.5.0/gems/activesupport-5.2.4.4/lib/active_support/notifications.rb:168:in `instrument'
[UUID] vendor/bundle/ruby/2.5.0/gems/actionpack-5.2.4.4/lib/action_controller/metal/instrumentation.rb:32:in `process_action'
[UUID] vendor/bundle/ruby/2.5.0/gems/actionpack-5.2.4.4/lib/action_controller/metal/params_wrapper.rb:256:in `process_action'
[UUID] vendor/bundle/ruby/2.5.0/gems/activerecord-5.2.4.4/lib/active_record/railties/controller_runtime.rb:24:in `process_action'
[UUID] vendor/bundle/ruby/2.5.0/gems/actionpack-5.2.4.4/lib/abstract_controller/base.rb:134:in `process'
[UUID] vendor/bundle/ruby/2.5.0/gems/actionview-5.2.4.4/lib/action_view/rendering.rb:32:in `process'
[UUID] vendor/bundle/ruby/2.5.0/gems/actionpack-5.2.4.4/lib/action_controller/metal.rb:191:in `dispatch'
[UUID] vendor/bundle/ruby/2.5.0/gems/actionpack-5.2.4.4/lib/action_controller/metal.rb:252:in `dispatch'
[UUID] vendor/bundle/ruby/2.5.0/gems/actionpack-5.2.4.4/lib/action_dispatch/routing/route_set.rb:52:in `dispatch'
[UUID] vendor/bundle/ruby/2.5.0/gems/actionpack-5.2.4.4/lib/action_dispatch/routing/route_set.rb:34:in `serve'
[UUID] vendor/bundle/ruby/2.5.0/gems/actionpack-5.2.4.4/lib/action_dispatch/journey/router.rb:52:in `block in serve'
[UUID] vendor/bundle/ruby/2.5.0/gems/actionpack-5.2.4.4/lib/action_dispatch/journey/router.rb:35:in `each'
[UUID] vendor/bundle/ruby/2.5.0/gems/actionpack-5.2.4.4/lib/action_dispatch/journey/router.rb:35:in `serve'
[UUID] vendor/bundle/ruby/2.5.0/gems/actionpack-5.2.4.4/lib/action_dispatch/routing/route_set.rb:840:in `call'
[UUID] vendor/bundle/ruby/2.5.0/gems/omniauth-1.9.1/lib/omniauth/builder.rb:45:in `call'
[UUID] vendor/bundle/ruby/2.5.0/gems/http_accept_language-2.1.1/lib/http_accept_language/middleware.rb:14:in `call'
[UUID] vendor/bundle/ruby/2.5.0/gems/rack-2.2.3/lib/rack/tempfile_reaper.rb:15:in `call'
[UUID] vendor/bundle/ruby/2.5.0/gems/rack-2.2.3/lib/rack/etag.rb:27:in `call'
[UUID] vendor/bundle/ruby/2.5.0/gems/rack-2.2.3/lib/rack/conditional_get.rb:40:in `call'
[UUID] vendor/bundle/ruby/2.5.0/gems/rack-2.2.3/lib/rack/head.rb:12:in `call'
[UUID] vendor/bundle/ruby/2.5.0/gems/actionpack-5.2.4.4/lib/action_dispatch/http/content_security_policy.rb:18:in `call'
[UUID] vendor/bundle/ruby/2.5.0/gems/rack-2.2.3/lib/rack/session/abstract/id.rb:266:in `context'
[UUID] vendor/bundle/ruby/2.5.0/gems/rack-2.2.3/lib/rack/session/abstract/id.rb:260:in `call'
[UUID] vendor/bundle/ruby/2.5.0/gems/actionpack-5.2.4.4/lib/action_dispatch/middleware/cookies.rb:670:in `call'
[UUID] vendor/bundle/ruby/2.5.0/gems/actionpack-5.2.4.4/lib/action_dispatch/middleware/callbacks.rb:28:in `block in call'
[UUID] vendor/bundle/ruby/2.5.0/gems/activesupport-5.2.4.4/lib/active_support/callbacks.rb:98:in `run_callbacks'
[UUID] vendor/bundle/ruby/2.5.0/gems/actionpack-5.2.4.4/lib/action_dispatch/middleware/callbacks.rb:26:in `call'
[UUID] vendor/bundle/ruby/2.5.0/gems/actionpack-5.2.4.4/lib/action_dispatch/middleware/debug_exceptions.rb:61:in `call'
[UUID] vendor/bundle/ruby/2.5.0/gems/actionpack-5.2.4.4/lib/action_dispatch/middleware/show_exceptions.rb:33:in `call'
[UUID] vendor/bundle/ruby/2.5.0/gems/lograge-0.11.2/lib/lograge/rails_ext/rack/logger.rb:15:in `call_app'
[UUID] vendor/bundle/ruby/2.5.0/gems/railties-5.2.4.4/lib/rails/rack/logger.rb:26:in `block in call'
[UUID] vendor/bundle/ruby/2.5.0/gems/activesupport-5.2.4.4/lib/active_support/tagged_logging.rb:71:in `block in tagged'
[UUID] vendor/bundle/ruby/2.5.0/gems/activesupport-5.2.4.4/lib/active_support/tagged_logging.rb:28:in `tagged'
[UUID] vendor/bundle/ruby/2.5.0/gems/activesupport-5.2.4.4/lib/active_support/tagged_logging.rb:71:in `tagged'
[UUID] vendor/bundle/ruby/2.5.0/gems/railties-5.2.4.4/lib/rails/rack/logger.rb:26:in `call'
[UUID] vendor/bundle/ruby/2.5.0/gems/actionpack-5.2.4.4/lib/action_dispatch/middleware/remote_ip.rb:81:in `call'
[UUID] vendor/bundle/ruby/2.5.0/gems/request_store-1.5.0/lib/request_store/middleware.rb:19:in `call'
[UUID] vendor/bundle/ruby/2.5.0/gems/actionpack-5.2.4.4/lib/action_dispatch/middleware/request_id.rb:27:in `call'
[UUID] vendor/bundle/ruby/2.5.0/gems/rack-2.2.3/lib/rack/method_override.rb:24:in `call'
[UUID] vendor/bundle/ruby/2.5.0/gems/rack-2.2.3/lib/rack/runtime.rb:22:in `call'
[UUID] vendor/bundle/ruby/2.5.0/gems/actionpack-5.2.4.4/lib/action_dispatch/middleware/executor.rb:14:in `call'
[UUID] vendor/bundle/ruby/2.5.0/gems/actionpack-5.2.4.4/lib/action_dispatch/middleware/static.rb:127:in `call'
[UUID] vendor/bundle/ruby/2.5.0/gems/rack-2.2.3/lib/rack/sendfile.rb:110:in `call'
[UUID] vendor/bundle/ruby/2.5.0/gems/railties-5.2.4.4/lib/rails/engine.rb:524:in `call'
[UUID] vendor/bundle/ruby/2.5.0/gems/rack-2.2.3/lib/rack/urlmap.rb:74:in `block in call'
[UUID] vendor/bundle/ruby/2.5.0/gems/rack-2.2.3/lib/rack/urlmap.rb:58:in `each'
[UUID] vendor/bundle/ruby/2.5.0/gems/rack-2.2.3/lib/rack/urlmap.rb:58:in `call'
[UUID] vendor/bundle/ruby/2.5.0/gems/puma-3.12.6/lib/puma/configuration.rb:227:in `call'
[UUID] vendor/bundle/ruby/2.5.0/gems/puma-3.12.6/lib/puma/server.rb:706:in `handle_request'
[UUID] vendor/bundle/ruby/2.5.0/gems/puma-3.12.6/lib/puma/server.rb:476:in `process_client'
[UUID] vendor/bundle/ruby/2.5.0/gems/puma-3.12.6/lib/puma/server.rb:334:in `block in run'
[UUID] vendor/bundle/ruby/2.5.0/gems/puma-3.12.6/lib/puma/thread_pool.rb:135:in `block in spawn_thread'`

This results in an ugly, non formatted view, displaying only the 500 message to clients:

This reduces the UX for clients/users and should be improved. Suggestion: Catch the error and send a 4XX response aiming towards an appropriate message so that users can better understand what they can / should do on their side.

The observed behaviour can be reproduced in different browsers (current Chrome, current Firefox and maybe others).

[simonschweizer]

Addition: We found that the same behaviour can be observed when the internal authentication provider is used.

The same error message is displayed to end users.

When reproducing on demo.bigbluebutton.org we see a slightly different error message:

An unhandled lowlevel error occurred. The application logs may have details.

You can reproduce this error on every greenlight instance by opening the login page, delete the cookies and click login.

[farhatahmad]

Is the only time this error happens is if you delete all your cookies? Or is that just the easiest way to reproduce?

[simonschweizer]

Thanks for your fast response @ farhatahmad.

That's the easiest way to reproduce.

In general this error is hard to reproduce - the logs are only reporting the same error as in the log output shown in the issue description.

Generally these might be users that idle to long (e.g. overnight) on the login page, but we also had users that started the browser, opened Greenlight and tried to login without cookie removal or major interruptions.

As we were unable to track down the origin of the error (which occurs not so often and it's effects are not severe), we suggest to at least then display the login page with a note to login again.

[farhatahmad]

I've been wanting to take a look at this for a while now - but I was able to mix the majority of the CSRF issues that were occurring (mostly on room join). I'll see if there's an easy way to catch these exceptions