rails: sporadic "undefined method `+' for nil:NilClass" from router

Steps to reproduce

This happens often enough in our test suite to be annoying, but I do not know how to reproduce it. I am raising the issue here in the hopes that someone can point me in the right direction to track it down 😃

Expected behavior

No Exception should be raised

Actual behavior

Usually our tests pass, but sometimes the following exception is raised.

(The line is idx = @offsets[x - 1] + x so clearly there is no offset at index ‘x -1’ but I’m not sure what the implications of that are…)

undefined method `+' for nil:NilClass02:53
         vendor/bundle/ruby/3.0.0/gems/actionpack-6.1.4.1/lib/action_dispatch/journey/path/pattern.rb:130:in `[]'02:53
         vendor/bundle/ruby/3.0.0/gems/actionpack-6.1.4.1/lib/action_dispatch/journey/router.rb:127:in `block (2 levels) in find_routes'02:53
         vendor/bundle/ruby/3.0.0/gems/actionpack-6.1.4.1/lib/action_dispatch/journey/router.rb:126:in `each'02:53
         vendor/bundle/ruby/3.0.0/gems/actionpack-6.1.4.1/lib/action_dispatch/journey/router.rb:126:in `each_with_index'02:53
         vendor/bundle/ruby/3.0.0/gems/actionpack-6.1.4.1/lib/action_dispatch/journey/router.rb:126:in `block in find_routes'02:53
         vendor/bundle/ruby/3.0.0/gems/actionpack-6.1.4.1/lib/action_dispatch/journey/router.rb:123:in `map!'02:53
         vendor/bundle/ruby/3.0.0/gems/actionpack-6.1.4.1/lib/action_dispatch/journey/router.rb:123:in `find_routes'02:53
         vendor/bundle/ruby/3.0.0/gems/actionpack-6.1.4.1/lib/action_dispatch/journey/router.rb:32:in `serve'02:53
         vendor/bundle/ruby/3.0.0/gems/actionpack-6.1.4.1/lib/action_dispatch/routing/route_set.rb:842:in `call'02:53
         vendor/bundle/ruby/3.0.0/gems/omniauth-2.0.4/lib/omniauth/strategy.rb:202:in `call!'02:53
         vendor/bundle/ruby/3.0.0/gems/omniauth-2.0.4/lib/omniauth/strategy.rb:169:in `call'02:53
         vendor/bundle/ruby/3.0.0/gems/omniauth-2.0.4/lib/omniauth/builder.rb:45:in `call'02:53
         vendor/bundle/ruby/3.0.0/gems/warden-1.2.9/lib/warden/manager.rb:36:in `block in call'02:53
         vendor/bundle/ruby/3.0.0/gems/warden-1.2.9/lib/warden/manager.rb:34:in `catch'02:53
         vendor/bundle/ruby/3.0.0/gems/warden-1.2.9/lib/warden/manager.rb:34:in `call'02:53
         vendor/bundle/ruby/3.0.0/gems/rack-2.2.3/lib/rack/tempfile_reaper.rb:15:in `call'02:53
         vendor/bundle/ruby/3.0.0/gems/rack-2.2.3/lib/rack/etag.rb:27:in `call'02:53
         vendor/bundle/ruby/3.0.0/gems/rack-2.2.3/lib/rack/conditional_get.rb:27:in `call'02:53
         vendor/bundle/ruby/3.0.0/gems/rack-2.2.3/lib/rack/head.rb:12:in `call'02:53
         vendor/bundle/ruby/3.0.0/gems/actionpack-6.1.4.1/lib/action_dispatch/http/permissions_policy.rb:22:in `call'02:53
         vendor/bundle/ruby/3.0.0/gems/actionpack-6.1.4.1/lib/action_dispatch/http/content_security_policy.rb:18:in `call'02:53
         vendor/bundle/ruby/3.0.0/gems/rack-2.2.3/lib/rack/session/abstract/id.rb:266:in `context'02:53
         vendor/bundle/ruby/3.0.0/gems/rack-2.2.3/lib/rack/session/abstract/id.rb:260:in `call'02:53
         vendor/bundle/ruby/3.0.0/gems/actionpack-6.1.4.1/lib/action_dispatch/middleware/cookies.rb:689:in `call'02:53
         vendor/bundle/ruby/3.0.0/gems/actionpack-6.1.4.1/lib/action_dispatch/middleware/callbacks.rb:27:in `block in call'02:53
         vendor/bundle/ruby/3.0.0/gems/activesupport-6.1.4.1/lib/active_support/callbacks.rb:98:in `run_callbacks'02:53
         vendor/bundle/ruby/3.0.0/gems/actionpack-6.1.4.1/lib/action_dispatch/middleware/callbacks.rb:26:in `call'02:53
         vendor/bundle/ruby/3.0.0/gems/actionpack-6.1.4.1/lib/action_dispatch/middleware/executor.rb:14:in `call'02:53
         vendor/bundle/ruby/3.0.0/gems/actionpack-6.1.4.1/lib/action_dispatch/middleware/actionable_exceptions.rb:18:in `call'02:53
         vendor/bundle/ruby/3.0.0/gems/rollbar-3.2.0/lib/rollbar/middleware/rails/rollbar.rb:25:in `block in call'02:53
         vendor/bundle/ruby/3.0.0/gems/rollbar-3.2.0/lib/rollbar.rb:145:in `scoped'02:53
         vendor/bundle/ruby/3.0.0/gems/rollbar-3.2.0/lib/rollbar/middleware/rails/rollbar.rb:22:in `call'02:53
         vendor/bundle/ruby/3.0.0/gems/actionpack-6.1.4.1/lib/action_dispatch/middleware/debug_exceptions.rb:29:in `call'02:53
         vendor/bundle/ruby/3.0.0/gems/rollbar-3.2.0/lib/rollbar/middleware/rails/show_exceptions.rb:22:in `call_with_rollbar'02:53
         vendor/bundle/ruby/3.0.0/gems/actionpack-6.1.4.1/lib/action_dispatch/middleware/show_exceptions.rb:33:in `call'02:53
         vendor/bundle/ruby/3.0.0/gems/railties-6.1.4.1/lib/rails/rack/logger.rb:37:in `call_app'02:53
         vendor/bundle/ruby/3.0.0/gems/railties-6.1.4.1/lib/rails/rack/logger.rb:26:in `block in call'02:53
         vendor/bundle/ruby/3.0.0/gems/activesupport-6.1.4.1/lib/active_support/tagged_logging.rb:99:in `block in tagged'02:53
         vendor/bundle/ruby/3.0.0/gems/activesupport-6.1.4.1/lib/active_support/tagged_logging.rb:37:in `tagged'02:53
         vendor/bundle/ruby/3.0.0/gems/activesupport-6.1.4.1/lib/active_support/tagged_logging.rb:99:in `tagged'02:53
         vendor/bundle/ruby/3.0.0/gems/railties-6.1.4.1/lib/rails/rack/logger.rb:26:in `call'02:53
         vendor/bundle/ruby/3.0.0/gems/actionpack-6.1.4.1/lib/action_dispatch/middleware/remote_ip.rb:81:in `call'02:53
         vendor/bundle/ruby/3.0.0/gems/request_store-1.5.0/lib/request_store/middleware.rb:19:in `call'02:53
         vendor/bundle/ruby/3.0.0/gems/actionpack-6.1.4.1/lib/action_dispatch/middleware/request_id.rb:26:in `call'02:53
         vendor/bundle/ruby/3.0.0/gems/rack-2.2.3/lib/rack/method_override.rb:24:in `call'02:53
         vendor/bundle/ruby/3.0.0/gems/rack-2.2.3/lib/rack/runtime.rb:22:in `call'02:53
         vendor/bundle/ruby/3.0.0/gems/activesupport-6.1.4.1/lib/active_support/cache/strategy/local_cache_middleware.rb:29:in `call'02:53
         vendor/bundle/ruby/3.0.0/gems/actionpack-6.1.4.1/lib/action_dispatch/middleware/executor.rb:14:in `call'02:53
         vendor/bundle/ruby/3.0.0/gems/actionpack-6.1.4.1/lib/action_dispatch/middleware/static.rb:24:in `call'02:53
         vendor/bundle/ruby/3.0.0/gems/actionpack-6.1.4.1/lib/action_dispatch/middleware/static.rb:24:in `call'02:53
         vendor/bundle/ruby/3.0.0/gems/rack-2.2.3/lib/rack/sendfile.rb:110:in `call'02:53
 02:53
         vendor/bundle/ruby/3.0.0/gems/webpacker-5.4.2/lib/webpacker/dev_server_proxy.rb:25:in `perform_request'02:53
         vendor/bundle/ruby/3.0.0/gems/rack-proxy-0.7.0/lib/rack/proxy.rb:63:in `call'02:53
         vendor/bundle/ruby/3.0.0/gems/railties-6.1.4.1/lib/rails/engine.rb:539:in `call'02:53
         vendor/bundle/ruby/3.0.0/gems/rack-2.2.3/lib/rack/urlmap.rb:74:in `block in call'02:53
         vendor/bundle/ruby/3.0.0/gems/rack-2.2.3/lib/rack/urlmap.rb:58:in `each'02:53
         vendor/bundle/ruby/3.0.0/gems/rack-2.2.3/lib/rack/urlmap.rb:58:in `call'02:53
         vendor/bundle/ruby/3.0.0/gems/capybara-3.35.3/lib/capybara/server/middleware.rb:60:in `call'02:53
         vendor/bundle/ruby/3.0.0/gems/puma-5.4.0/lib/puma/configuration.rb:249:in `call'02:53
         vendor/bundle/ruby/3.0.0/gems/puma-5.4.0/lib/puma/request.rb:77:in `block in handle_request'02:53
         vendor/bundle/ruby/3.0.0/gems/puma-5.4.0/lib/puma/thread_pool.rb:340:in `with_force_shutdown'02:53
         fvendor/bundle/ruby/3.0.0/gems/puma-5.4.0/lib/puma/request.rb:76:in `handle_request'02:53
         vendor/bundle/ruby/3.0.0/gems/puma-5.4.0/lib/puma/server.rb:440:in `process_client'02:53
         vendor/bundle/ruby/3.0.0/gems/puma-5.4.0/lib/puma/thread_pool.rb:147:in `block in spawn_thread'

System configuration

Rails version: 6.1.4.1

Ruby version: 3.0.0

About this issue

Original URL
State: closed
Created 3 years ago
Reactions: 1
Comments: 23 (17 by maintainers)

Commits related to this issue

Refactor offsets method to avoid race condition In environments where the routes aren't eager loaded such as development or test a race condition could occur where two requests would trigger the `off... — committed to pixeltrix/rails by pixeltrix 2 years ago

Most upvoted comments

Ah I see, then why not slightly refactor this method as:

@offset ||= begin

end

This way, in case of a race condition, both thread do the work, which isn’t a big deal, but both have the same result.

byroot on Mar 12, 2022

I was actually referring to the fact that the system tests are running separately from one another. 1 being the test runner itself, and the other being the application itself that headless Chrome connects to.

agrobbin on Jan 12, 2022

I take back my previous comment about load order, as it doesn’t appear to happen from the beginning of the test, it’s somewhere in the middle, or even towards the end. In our log/test.log, here is the last thing that happens before the ROLLBACK is triggered for the test in question:

[3b3a86de-5636-4648-9f9d-d92d14d7937a] Started GET "/rails/active_storage/disk/eyJfcmFpbHMiOnsibWVzc2FnZSI6IkJBaDdDVG9JYTJWNVNTSWhkMmQyWVdjelltVjFaVEEyTkdZd2F6TnNlV295T0drMmVqaDVhUVk2QmtWVU9oQmthWE53YjNOcGRHbHZia2tpUDJsdWJHbHVaVHNnWm1sc1pXNWhiV1U5SW1GMllYUmhjaTV3Ym1jaU95Qm1hV3hsYm1GdFpTbzlWVlJHTFRnbkoyRjJZWFJoY2k1d2JtY0dPd1pVT2hGamIyNTBaVzUwWDNSNWNHVkpJZzVwYldGblpTOXdibWNHT3daVU9oRnpaWEoyYVdObFgyNWhiV1U2Q1hSbGMzUT0iLCJleHAiOiIyMDIwLTA1LTAxVDExOjA1OjQwLjk0N1oiLCJwdXIiOiJibG9iX2tleSJ9fQ==--4d7f4959c53c7f784676530ab0d98afc1fce7185/avatar.png" for 127.0.0.1 at 2020-05-01 04:00:41 -0700
[b3178459-7713-45ed-92f7-92c9bda079fa] Started GET "/rails/active_storage/disk/eyJfcmFpbHMiOnsibWVzc2FnZSI6IkJBaDdDVG9JYTJWNVNTSWhjSEZxWjNoNGJHMXRZekUxYzNOblluRnhjemRuWlc5M01qUm1hZ1k2QmtWVU9oQmthWE53YjNOcGRHbHZia2tpWjJsdWJHbHVaVHNnWm1sc1pXNWhiV1U5SW5abGJtUnlMV1JsWm1GMWJIUXRZMjl0Y0dGdWVTMXBZMjl1TG5CdVp5STdJR1pwYkdWdVlXMWxLajFWVkVZdE9DY25kbVZ1WkhJdFpHVm1ZWFZzZEMxamIyMXdZVzU1TFdsamIyNHVjRzVuQmpzR1ZEb1JZMjl1ZEdWdWRGOTBlWEJsU1NJT2FXMWhaMlV2Y0c1bkJqc0dWRG9SYzJWeWRtbGpaVjl1WVcxbE9nbDBaWE4wIiwiZXhwIjoiMjAyMC0wNS0wMVQxMTowNTo0MC45NjJaIiwicHVyIjoiYmxvYl9rZXkifX0=--237baeabe52f0e96b876ce21f855816c014bf257/vendr-default-company-icon.png" for 127.0.0.1 at 2020-05-01 04:00:41 -0700
[b3178459-7713-45ed-92f7-92c9bda079fa] Processing by ActiveStorage::DiskController#show as PNG
[b3178459-7713-45ed-92f7-92c9bda079fa]   Parameters: {"encoded_key"=>"[FILTERED]", "filename"=>"vendr-default-company-icon"}
[b3178459-7713-45ed-92f7-92c9bda079fa] Completed 200 OK in 1ms (ActiveRecord: 0.0ms | Allocations: 380)
[3b3a86de-5636-4648-9f9d-d92d14d7937a] Processing by ActiveStorage::DiskController#show as PNG
[3b3a86de-5636-4648-9f9d-d92d14d7937a]   Parameters: {"encoded_key"=>"[FILTERED]", "filename"=>"avatar"}
[3b3a86de-5636-4648-9f9d-d92d14d7937a] Completed 200 OK in 0ms (ActiveRecord: 0.0ms | Allocations: 351)

After this test fails, the rest of the test suite continues on its merry way, so it doesn’t seem to be leaking this state across tests, and fail everything from then on, which is… actually even more surprising to me.

agrobbin on Jan 12, 2022