janko / sequel-activerecord_connection

Allows Sequel to reuse Active Record's database connection
MIT License
137 stars 11 forks source link

(maybe) another AR<->Sequel transaction management issue #11

Closed bjeanes closed 4 years ago

bjeanes commented 4 years ago

I am opening this as a placeholder while I try to dig into it. Understandably, these types of issues are very hard to nail down.

So far the primary thing (I think) I have determined is that the issue happens in the first test that runs after a test which purposefully causes an invalid authenticity token[1]. The invalid auth test causes a stack trace which looks like so:

2020-10-08 05:07:28 +0000: Rack app error handling request { POST /sign_up }
#<ActionController::InvalidAuthenticityToken: ActionController::InvalidAuthenticityToken>
/bundle/gems/actionpack-5.2.4.4/lib/action_controller/metal/request_forgery_protection.rb:211:in `handle_unverified_request'
/bundle/gems/actionpack-5.2.4.4/lib/action_controller/metal/request_forgery_protection.rb:243:in `handle_unverified_request'
/bundle/gems/actionpack-5.2.4.4/lib/action_controller/metal/request_forgery_protection.rb:238:in `verify_authenticity_token'
/bundle/gems/rodauth-rails-0.3.0/lib/rodauth/rails/feature.rb:87:in `rails_check_csrf!'
/bundle/gems/rodauth-rails-0.3.0/lib/rodauth/rails/feature.rb:33:in `check_csrf'
/bundle/gems/rodauth-2.4.0/lib/rodauth.rb:122:in `block (2 levels) in route'
/bundle/gems/roda-3.36.0/lib/roda/request.rb:564:in `if_match'
/bundle/gems/roda-3.36.0/lib/roda/request.rb:169:in `is'
/bundle/gems/rodauth-2.4.0/lib/rodauth.rb:121:in `block in route'
/bundle/gems/rodauth-2.4.0/lib/rodauth/features/base.rb:152:in `route!'
/bundle/gems/rodauth-2.4.0/lib/rodauth.rb:349:in `rodauth'
/app/app/core/authentication/rodauth_config.rb:435:in `block in <class:RodauthConfig>'
/bundle/gems/roda-3.36.0/lib/roda.rb:502:in `_roda_run_main_route'
/bundle/gems/roda-3.36.0/lib/roda/plugins/middleware.rb:146:in `_roda_run_main_route'
/bundle/gems/roda-3.36.0/lib/roda/plugins/_before_hook.rb:27:in `_roda_run_main_route'
/bundle/gems/roda-3.36.0/lib/roda.rb:480:in `block in _roda_handle_main_route'
/bundle/gems/roda-3.36.0/lib/roda.rb:478:in `catch'
/bundle/gems/roda-3.36.0/lib/roda.rb:478:in `_roda_handle_main_route'
/bundle/gems/roda-3.36.0/lib/roda/plugins/error_handler.rb:87:in `_roda_handle_main_route'
/bundle/gems/roda-3.36.0/lib/roda.rb:366:in `block in base_rack_app_callable'
/bundle/gems/roda-3.36.0/lib/roda.rb:53:in `call'
/bundle/gems/roda-3.36.0/lib/roda/plugins/middleware.rb:105:in `block in call'
/bundle/gems/roda-3.36.0/lib/roda/plugins/middleware.rb:103:in `catch'
/bundle/gems/roda-3.36.0/lib/roda/plugins/middleware.rb:103:in `call'
/bundle/gems/rodauth-rails-0.3.0/lib/rodauth/rails/middleware.rb:16:in `block in call'
/bundle/gems/rodauth-rails-0.3.0/lib/rodauth/rails/middleware.rb:15:in `catch'
/bundle/gems/rodauth-rails-0.3.0/lib/rodauth/rails/middleware.rb:15:in `call'
/bundle/gems/rack-2.2.3/lib/rack/static.rb:161:in `call'
/bundle/gems/remotipart-1.4.4/lib/remotipart/middleware.rb:32:in `call'
/bundle/gems/rack-2.2.3/lib/rack/tempfile_reaper.rb:15:in `call'
/bundle/gems/rack-2.2.3/lib/rack/etag.rb:27:in `call'
/bundle/gems/rack-2.2.3/lib/rack/conditional_get.rb:40:in `call'
/bundle/gems/rack-2.2.3/lib/rack/head.rb:12:in `call'
/bundle/gems/actionpack-5.2.4.4/lib/action_dispatch/http/content_security_policy.rb:18:in `call'
/bundle/gems/rack-2.2.3/lib/rack/session/abstract/id.rb:266:in `context'
/bundle/gems/rack-2.2.3/lib/rack/session/abstract/id.rb:260:in `call'
/bundle/gems/actionpack-5.2.4.4/lib/action_dispatch/middleware/cookies.rb:670:in `call'
/bundle/gems/actionpack-5.2.4.4/lib/action_dispatch/middleware/callbacks.rb:28:in `block in call'
/bundle/gems/activesupport-5.2.4.4/lib/active_support/callbacks.rb:98:in `run_callbacks'
/bundle/gems/actionpack-5.2.4.4/lib/action_dispatch/middleware/callbacks.rb:26:in `call'
/bundle/gems/better_errors-2.5.0/lib/better_errors/middleware.rb:59:in `call'
/bundle/gems/actionpack-5.2.4.4/lib/action_dispatch/middleware/debug_exceptions.rb:61:in `call'
/bundle/gems/actionpack-5.2.4.4/lib/action_dispatch/middleware/show_exceptions.rb:33:in `call'
/bundle/gems/railties-5.2.4.4/lib/rails/rack/logger.rb:38:in `call_app'
/bundle/gems/railties-5.2.4.4/lib/rails/rack/logger.rb:26:in `block in call'
/bundle/gems/activesupport-5.2.4.4/lib/active_support/tagged_logging.rb:71:in `block in tagged'
/bundle/gems/activesupport-5.2.4.4/lib/active_support/tagged_logging.rb:28:in `tagged'
/bundle/gems/activesupport-5.2.4.4/lib/active_support/tagged_logging.rb:71:in `tagged'
/bundle/gems/railties-5.2.4.4/lib/rails/rack/logger.rb:26:in `call'
/bundle/bundler/gems/ahoy-9bea8cbeaf96/lib/ahoy/engine.rb:22:in `call_with_quiet_ahoy'
/bundle/gems/actionpack-5.2.4.4/lib/action_dispatch/middleware/remote_ip.rb:81:in `call'
/bundle/gems/request_store-1.5.0/lib/request_store/middleware.rb:19:in `call'
/bundle/gems/actionpack-5.2.4.4/lib/action_dispatch/middleware/request_id.rb:27:in `call'
/bundle/gems/rack-2.2.3/lib/rack/method_override.rb:24:in `call'
/bundle/gems/rack-2.2.3/lib/rack/runtime.rb:22:in `call'
/bundle/gems/activesupport-5.2.4.4/lib/active_support/cache/strategy/local_cache_middleware.rb:29:in `call'
/bundle/gems/actionpack-5.2.4.4/lib/action_dispatch/middleware/executor.rb:14:in `call'
/bundle/gems/actionpack-5.2.4.4/lib/action_dispatch/middleware/static.rb:127:in `call'
/bundle/gems/rack-2.2.3/lib/rack/sendfile.rb:110:in `call'
/bundle/gems/rack-cors-1.0.5/lib/rack/cors.rb:98:in `call'
/bundle/gems/sentry-raven-2.13.0/lib/raven/integrations/rack.rb:51:in `call'
/bundle/gems/railties-5.2.4.4/lib/rails/engine.rb:524:in `call'
/bundle/gems/rack-2.2.3/lib/rack/urlmap.rb:74:in `block in call'
/bundle/gems/rack-2.2.3/lib/rack/urlmap.rb:58:in `each'
/bundle/gems/rack-2.2.3/lib/rack/urlmap.rb:58:in `call'
/bundle/gems/capybara-2.15.1/lib/capybara/server.rb:44:in `call'
/bundle/gems/puma-4.3.5/lib/puma/configuration.rb:228:in `call'
/bundle/gems/puma-4.3.5/lib/puma/server.rb:713:in `handle_request'
/bundle/gems/puma-4.3.5/lib/puma/server.rb:472:in `process_client'
/bundle/gems/puma-4.3.5/lib/puma/server.rb:328:in `block in run'
/bundle/gems/puma-4.3.5/lib/puma/thread_pool.rb:134:in `block in spawn_thread'

(Of note here for rodauth-rails is that exceptions raised from the rails_controller_instance are dumped as unstyled backtraces from the Rack app and not handled in an expected way, from a Rails perspective. I'm glad I know this now because I'll have to massage that).

I don't know enough about how RSpec/Capybara/whatever works to have formed a great mental model of what's going awry here, but I have a fuzzy notion that the way in which this exception is raised essentially from within Rack middleware might be bypassing some necessary accounting on sequel-activerecord_connection's part. Maybe? Does that sound plausible?

Regardless, using a global before(:example) hook in the tests to check the pristineness (pristinity?) of the DB, the next test to run has a dirty DB and the log/test.log file shows a COMMIT during a create_account in Roda.

NOTE: I am not totally confident my theory is correct here as I can't seem to reproduce it when just running the authentication token spec followed by any other spec. So something more might be at play, which I can't yet see...

[1]: We have a specific test for how we handle this as a common issue with mobile use on our app is that certain browsers (AFAICR just Safari on iOS) will sometimes evict the browser from memory while it is not the active app, which will clear session-lifetime cookies, but it will preserve the page. This causes regular form submissions with invalid auth tokens, and so we have extra behaviour here (redirect to login, flash message, including special handling for XHR requests).

bjeanes commented 4 years ago

I think this is a false alarm. Closing while I continue to investigate and will re-open if need be.

bjeanes commented 4 years ago

Yes. Apologies for the runaround here. A painful interaction of circumstances led me to this situation:

  1. For some surprising historical reason, this project apparently does not run specs in a random order (but can be made to)
  2. For other debateable reasons, every example apparently re-seeds the PRNG causing fixture data to be deterministic within every example (so the first generated email in spec1 is the same as the first in spec2)
  3. The spec file which contains the spec which runs directly after the authenticity token spec contained a before(:context) which polluted the DB, which then conflicted with the following tests
  4. My branch moving our auth to Rodauth consolidates both user and admin records into a singular auth.accounts table, which caused the issue to become visible.

Specifically what through me for a loop was the COMMITs in the log/test.log file. This is because the before(:context) is simply running outside of any particular spec's transaction, but I didn't know from the log output that it wasn't coming from within a test. :man_facepalming:

Sorry again. I think I just got flashbacks to the other week tracking down open/closed transactions.