fxn
commented
1 year ago Quick heads up: I don't think the problem may be related to Zeitwerk, the code of this gem is autoloaded by Ruby, not Zeitwerk, and it is not reloaded.
Closed maximevaillancourt closed 1 year ago
fxn
commented
1 year ago Quick heads up: I don't think the problem may be related to Zeitwerk, the code of this gem is autoloaded by Ruby, not Zeitwerk, and it is not reloaded.
fxn
commented
1 year ago Since this is very strange, I think we could double-check some basic assumptions.
At the beginning of config/application.rb, before the application class gets defined, execute:
p Formtastic.object_id
p Object.const_source_location(:Formtastic, false)
p Formtastic::Helpers.object_id
p Formtastic.const_source_location(:Helpers, false)
p Formtastic::Helpers.constants(false)
p Formtastic::Helpers.autoload?(:FormHelper, false)Then, print the same traces when the exception is raised.
Let's see if we find something interesting.
byroot
commented
1 year ago So, I've debugged a couple similar-ish issues over the years, and so far the problem always have been more or less the same.
Generally what happens is some code (or require call) before the class definition that can sometime raise for whatever reason:
# foo.rb
something_that_sometimes_raise
class Foo
endThis is generally combined with something rescuing and swallowing the original error. When this happens the autoload is resolved, so it only try to load the file on the first attempt, so you end up with an undefined constant (sometime it's a partially defined class if the raising call is inside the class definition).
The way I generally debug this is to patch the code with something like:
begin
# original file content
rescue => error
log(error)
exit!(1)
endAnd wait for the error to happen and address the underlying error.
One thing Zeitwerk could do to help with these sort of problems it to rescue and logs errors when it loads a file. The problem being that in most cases the Zeitwerk logger isn't defined. So maybe it could call Kernel#warn? Not sure.
Hope the above helps.
maximevaillancourt
commented
1 year ago Thank you for the pointers folks, I appreciate your help.
TL;DR: Something seems fishy with Ruby's built-in autoload, or at least how it interacts with our Zeitwerk-enabled Rails 7 app on Ruby 3.2. It's particularly odd that we can only reproduce the issue—though intermittently/unreliably—in our CI pipeline, never locally or in production).
@fxn, as requested:
Failing case (intermittent, cannot be reproduced reliably)
Formtastic.object_id
61160
Object.const_source_location(:Formtastic, false)
["[redacted]/vendor/bundle/ruby/3.2.0/gems/formtastic-4.0.0/lib/formtastic/helpers.rb", 1]
Formtastic::Helpers.object_id
61180
Formtastic.const_source_location(:Helpers, false)
["[redacted]/vendor/bundle/ruby/3.2.0/gems/formtastic-4.0.0/lib/formtastic/helpers.rb", 2]
Formtastic::Helpers.constants(false)
[:Reflection, :ButtonsHelper, :ActionHelper, :ActionsHelper, :ErrorsHelper, :FieldsetWrapper, :FileColumnDetection, :InputHelper, :InputsHelper, :Enum, :FormHelper]
Formtastic::Helpers.autoload?(:FormHelper, false)
"formtastic/helpers/form_helper"
config.eager_load: true
uninitialized constant Formtastic::Helpers::FormHelper
[redacted]/vendor/bundle/ruby/3.2.0/gems/formtastic-4.0.0/lib/formtastic/helpers/form_helper.rb:49:in `<module:Helpers>'
[redacted]/vendor/bundle/ruby/3.2.0/gems/formtastic-4.0.0/lib/formtastic/helpers/form_helper.rb:2:in `<module:Formtastic>'
[redacted]/vendor/bundle/ruby/3.2.0/gems/formtastic-4.0.0/lib/formtastic/helpers/form_helper.rb:1:in `<top (required)>'
[redacted]/vendor/bundle/ruby/3.2.0/gems/bootsnap-1.15.0/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:32:in `require'
...Working case
Formtastic.object_id
60860
Object.const_source_location(:Formtastic, false)
["[redacted]/vendor/bundle/ruby/3.2.0/gems/formtastic-4.0.0/lib/formtastic/helpers.rb", 1]
Formtastic::Helpers.object_id
60880
Formtastic.const_source_location(:Helpers, false)
["[redacted]/vendor/bundle/ruby/3.2.0/gems/formtastic-4.0.0/lib/formtastic/helpers.rb", 2]
Formtastic::Helpers.constants(false)
[:Reflection, :ButtonsHelper, :ActionHelper, :ActionsHelper, :ErrorsHelper, :FieldsetWrapper, :FileColumnDetection, :InputHelper, :InputsHelper, :Enum, :FormHelper]
Formtastic::Helpers.autoload?(:FormHelper, false)
"formtastic/helpers/form_helper"
config.eager_load: true
Randomized with seed 59384
[tests running normally, as expected]
...It seems like the output is the same in both cases (except the differing object IDs, of course).
@byroot, I think you're onto something: I added rescue blocks (one in rails_helper.rb and another in Zeitwerk's Kernel#require via a monkey patch I defined in an initializer) and saw that when NameError: uninitialized constant <constant> shows up, there's sometimes a different exception being swallowed. As an example (it's another gem though), NameError: uninitialized constant InheritedResources::Actions shows up at the same time as NameError: uninitialized constant InheritedActions::Base (which is an open issue here).
When I take a step back now, there seems to be a pattern across the intermittent NameError exceptions I've run into so far, a pattern composed of the following elements:
NameError: uninitialized constant <constant> shows up, the constant is not present in $LOADED_FEATURES (which seems obvious now that I type this), and when things work as expected, the constant is present in $LOADED_FEATURES. The question is, why does the constant not show up in $LOADED_FEATURES in very rare cases, thus causing the NameError: uninitialized constant <constant> exception unreliably?autoloaded in their respective gems, which do not use Zeitwerk. A few examples:
ActionView::TemplatePath (view autoload line on GitHub)ActiveStorage::Attached (view autoload line on GitHub)Formtastic::Helpers::FormHelper (view autoload line on GitHub)InheritedResources::Actions (view autoload line on GitHub)ActiveAdmin::BaseController (view autoload line on GitHub)ViewComponent::Compiler or ViewComponent::TestHelpers (view autoload lines on GitHub)More context on this last one (ViewComponent gem) with regards to autoload being weird (and potentially using Zeitwerk in the gem to fix this) from August 2022 here: https://github.com/ViewComponent/view_component/pull/1471#pullrequestreview-1073257704
Again, thank you for your help so far, I appreciate it a ton!
fxn
commented
1 year ago @maximevaillancourt However, these are not the traces we want :). In a failing case, we want the traces before the application definition happens, and later when the exception happens (that is, you rescue it somehow and use the same code).
maximevaillancourt
commented
1 year ago D'oh, I misunderstood your request. I thought we wanted the traces from before the application definition happens in both the working and failing cases. I'll grab the traces after the exception shows up and report back. Thank you for clarifying!
maximevaillancourt
commented
1 year ago Here you go @fxn, traces as requested:
2023-01-19-formtastic-autoload-traces-before-after-nameerror-exception.txt
It looks like it's the same output both (A) before Application is defined and (B) in the rescue block after the exception happens.
I'm curious, what was your hunch? What did you expect to see differ before/after the exception? How can I help get us there?
fxn
commented
1 year ago Thanks, I'll have a look.
I don't have a hunch yet, but when doing remote debugging of weird scenarios it is important for me to build a factual understanding of the basics without assumptions.
fxn
commented
1 year ago Something that I find surprising is that the Formtastic constant is defined by lib/formtastic/helpers.rb instead of lib/formtastic.rb. This is odd because the entrypoint of the gem defines the constant and sets autoloads. Perhaps someone else is loading lib/formtastic/helpers.rb before the entrypoint is loaded?
Perhaps unrelated, but odd. I cannot dig into it now, will write back later.
fxn
commented
1 year ago Could you bundle open formtastic and edit lib/formtastic/helpers.rb putting pp caller_locations as first line in the file?
Maybe this is a red herring, but even just to help build a mental model of the situation, it would be cool to understand who is loading the file.
maximevaillancourt
commented
1 year ago Here it is, output of pp caller_locations added at the very top of lib/formtastic/helpers.rb in a fork (see commit) that I'm now using in our Rails app:
["[redacted]/vendor/bundle/ruby/3.2.0/gems/bootsnap-1.15.0/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:32:in `require'",
"[redacted]/vendor/bundle/ruby/3.2.0/gems/bootsnap-1.15.0/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:32:in `require'",
"[redacted]/vendor/bundle/ruby/3.2.0/bundler/gems/formtastic-154e78f3e503/lib/formtastic/inputs/base/associations.rb:5:in `<module:Associations>'",
"[redacted]/vendor/bundle/ruby/3.2.0/bundler/gems/formtastic-154e78f3e503/lib/formtastic/inputs/base/associations.rb:4:in `<module:Base>'",
"[redacted]/vendor/bundle/ruby/3.2.0/bundler/gems/formtastic-154e78f3e503/lib/formtastic/inputs/base/associations.rb:3:in `<module:Inputs>'",
"[redacted]/vendor/bundle/ruby/3.2.0/bundler/gems/formtastic-154e78f3e503/lib/formtastic/inputs/base/associations.rb:2:in `<module:Formtastic>'",
"[redacted]/vendor/bundle/ruby/3.2.0/bundler/gems/formtastic-154e78f3e503/lib/formtastic/inputs/base/associations.rb:1:in `<main>'",
"[redacted]/vendor/bundle/ruby/3.2.0/gems/bootsnap-1.15.0/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:32:in `require'",
"[redacted]/vendor/bundle/ruby/3.2.0/gems/bootsnap-1.15.0/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:32:in `require'",
"[redacted]/vendor/bundle/ruby/3.2.0/bundler/gems/formtastic-154e78f3e503/lib/formtastic/inputs/base.rb:70:in `<module:Base>'",
"[redacted]/vendor/bundle/ruby/3.2.0/bundler/gems/formtastic-154e78f3e503/lib/formtastic/inputs/base.rb:3:in `<module:Inputs>'",
"[redacted]/vendor/bundle/ruby/3.2.0/bundler/gems/formtastic-154e78f3e503/lib/formtastic/inputs/base.rb:2:in `<module:Formtastic>'",
"[redacted]/vendor/bundle/ruby/3.2.0/bundler/gems/formtastic-154e78f3e503/lib/formtastic/inputs/base.rb:1:in `<main>'",
"[redacted]/vendor/bundle/ruby/3.2.0/gems/bootsnap-1.15.0/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:32:in `require'",
"[redacted]/vendor/bundle/ruby/3.2.0/gems/bootsnap-1.15.0/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:32:in `require'",
"[redacted]/vendor/bundle/ruby/3.2.0/gems/activeadmin-2.13.1/lib/active_admin/form_builder.rb:5:in `<module:Inputs>'",
"[redacted]/vendor/bundle/ruby/3.2.0/gems/activeadmin-2.13.1/lib/active_admin/form_builder.rb:4:in `<module:Formtastic>'",
"[redacted]/vendor/bundle/ruby/3.2.0/gems/activeadmin-2.13.1/lib/active_admin/form_builder.rb:3:in `<main>'",
"[redacted]/vendor/bundle/ruby/3.2.0/gems/bootsnap-1.15.0/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:32:in `require'",
"[redacted]/vendor/bundle/ruby/3.2.0/gems/bootsnap-1.15.0/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:32:in `require'",
"[redacted]/vendor/bundle/ruby/3.2.0/gems/activeadmin-2.13.1/lib/active_admin/filters/forms.rb:6:in `<module:Filters>'",
"[redacted]/vendor/bundle/ruby/3.2.0/gems/activeadmin-2.13.1/lib/active_admin/filters/forms.rb:3:in `<module:ActiveAdmin>'",
"[redacted]/vendor/bundle/ruby/3.2.0/gems/activeadmin-2.13.1/lib/active_admin/filters/forms.rb:2:in `<main>'",
"[redacted]/vendor/bundle/ruby/3.2.0/gems/bootsnap-1.15.0/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:32:in `require'",
"[redacted]/vendor/bundle/ruby/3.2.0/gems/bootsnap-1.15.0/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:32:in `require'",
"[redacted]/vendor/bundle/ruby/3.2.0/gems/activeadmin-2.13.1/lib/active_admin/filters.rb:5:in `<main>'",
"[redacted]/vendor/bundle/ruby/3.2.0/gems/bootsnap-1.15.0/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:32:in `require'",
"[redacted]/vendor/bundle/ruby/3.2.0/gems/bootsnap-1.15.0/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:32:in `require'",
"[redacted]/vendor/bundle/ruby/3.2.0/gems/activeadmin-2.13.1/lib/active_admin.rb:129:in `<main>'",
"[redacted]/vendor/bundle/ruby/3.2.0/gems/bootsnap-1.15.0/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:32:in `require'",
"[redacted]/vendor/bundle/ruby/3.2.0/gems/bootsnap-1.15.0/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:32:in `require'",
"[redacted]/vendor/bundle/ruby/3.2.0/gems/activeadmin-2.13.1/lib/activeadmin.rb:2:in `<main>'",
"[redacted]/vendor/bundle/ruby/3.2.0/gems/bootsnap-1.15.0/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:32:in `require'",
"[redacted]/vendor/bundle/ruby/3.2.0/gems/bootsnap-1.15.0/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:32:in `require'",
"/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/bundler-2.4.3/lib/bundler/runtime.rb:60:in `block (2 levels) in require'",
"/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/bundler-2.4.3/lib/bundler/runtime.rb:55:in `each'",
"/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/bundler-2.4.3/lib/bundler/runtime.rb:55:in `block in require'",
"/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/bundler-2.4.3/lib/bundler/runtime.rb:44:in `each'",
"/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/bundler-2.4.3/lib/bundler/runtime.rb:44:in `require'",
"/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/bundler-2.4.3/lib/bundler.rb:195:in `require'",
"[redacted]/config/application.rb:20:in `<top (required)>'",
"[redacted]/config/environment.rb:4:in `require_relative'",
"[redacted]/config/environment.rb:4:in `<top (required)>'",
"[redacted]/spec/rails_helper.rb:8:in `require'",
"[redacted]/spec/rails_helper.rb:8:in `<top (required)>'",
"[redacted]/vendor/bundle/ruby/3.2.0/gems/rspec-core-3.12.0/lib/rspec/core/configuration.rb:2117:in `require'",
"[redacted]/vendor/bundle/ruby/3.2.0/gems/rspec-core-3.12.0/lib/rspec/core/configuration.rb:2117:in `load_file_handling_errors'",
"[redacted]/vendor/bundle/ruby/3.2.0/gems/rspec-core-3.12.0/lib/rspec/core/configuration.rb:1576:in `block in requires='",
"[redacted]/vendor/bundle/ruby/3.2.0/gems/rspec-core-3.12.0/lib/rspec/core/configuration.rb:1576:in `each'",
"[redacted]/vendor/bundle/ruby/3.2.0/gems/rspec-core-3.12.0/lib/rspec/core/configuration.rb:1576:in `requires='",
"[redacted]/vendor/bundle/ruby/3.2.0/gems/rspec-core-3.12.0/lib/rspec/core/configuration_options.rb:113:in `block in process_options_into'",
"[redacted]/vendor/bundle/ruby/3.2.0/gems/rspec-core-3.12.0/lib/rspec/core/configuration_options.rb:112:in `each'",
"[redacted]/vendor/bundle/ruby/3.2.0/gems/rspec-core-3.12.0/lib/rspec/core/configuration_options.rb:112:in `process_options_into'",
"[redacted]/vendor/bundle/ruby/3.2.0/gems/rspec-core-3.12.0/lib/rspec/core/configuration_options.rb:22:in `configure'",
"[redacted]/vendor/bundle/ruby/3.2.0/gems/rspec-core-3.12.0/lib/rspec/core/runner.rb:132:in `configure'",
"[redacted]/vendor/bundle/ruby/3.2.0/gems/rspec-core-3.12.0/lib/rspec/core/runner.rb:99:in `setup'",
"[redacted]/vendor/bundle/ruby/3.2.0/gems/rspec-core-3.12.0/lib/rspec/core/runner.rb:86:in `run'",
"[redacted]/vendor/bundle/ruby/3.2.0/gems/rspec-core-3.12.0/lib/rspec/core/runner.rb:71:in `run'",
"[redacted]/vendor/bundle/ruby/3.2.0/gems/rspec-core-3.12.0/lib/rspec/core/runner.rb:45:in `invoke'",
"[redacted]/vendor/bundle/ruby/3.2.0/gems/rspec-core-3.12.0/exe/rspec:4:in `<top (required)>'",
"[redacted]/vendor/bundle/ruby/3.2.0/bin/rspec:25:in `load'",
"[redacted]/vendor/bundle/ruby/3.2.0/bin/rspec:25:in `<top (required)>'",
"/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/bundler-2.4.3/lib/bundler/cli/exec.rb:58:in `load'",
"/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/bundler-2.4.3/lib/bundler/cli/exec.rb:58:in `kernel_load'",
"/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/bundler-2.4.3/lib/bundler/cli/exec.rb:23:in `run'",
"/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/bundler-2.4.3/lib/bundler/cli.rb:491:in `exec'",
"/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/bundler-2.4.3/lib/bundler/vendor/thor/lib/thor/command.rb:27:in `run'",
"/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/bundler-2.4.3/lib/bundler/vendor/thor/lib/thor/invocation.rb:127:in `invoke_command'",
"/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/bundler-2.4.3/lib/bundler/vendor/thor/lib/thor.rb:392:in `dispatch'",
"/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/bundler-2.4.3/lib/bundler/cli.rb:34:in `dispatch'",
"/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/bundler-2.4.3/lib/bundler/vendor/thor/lib/thor/base.rb:485:in `start'",
"/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/bundler-2.4.3/lib/bundler/cli.rb:28:in `start'",
"/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/bundler-2.4.3/exe/bundle:45:in `block in <top (required)>'",
"/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/bundler-2.4.3/lib/bundler/friendly_errors.rb:117:in `with_friendly_errors'",
"/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/bundler-2.4.3/exe/bundle:33:in `<top (required)>'",
"/opt/hostedtoolcache/Ruby/3.2.0/x64/bin/bundle:25:in `load'",
"/opt/hostedtoolcache/Ruby/3.2.0/x64/bin/bundle:25:in `<main>'"]Then, shortly after, right when we try to set up the test environment (rspec-based), the exception raises. Here's the stack trace:
...
config.eager_load: true
in zeitwerk.rb monkey patch LoadError / NameError rescue block, exception + backtrace:
uninitialized constant Formtastic::Helpers::FormHelper
[redacted]/vendor/bundle/ruby/3.2.0/bundler/gems/formtastic-154e78f3e503/lib/formtastic/helpers/form_helper.rb:49:in `<module:Helpers>'
[redacted]/vendor/bundle/ruby/3.2.0/bundler/gems/formtastic-154e78f3e503/lib/formtastic/helpers/form_helper.rb:2:in `<module:Formtastic>'
[redacted]/vendor/bundle/ruby/3.2.0/bundler/gems/formtastic-154e78f3e503/lib/formtastic/helpers/form_helper.rb:1:in `<top (required)>'
[redacted]/vendor/bundle/ruby/3.2.0/gems/bootsnap-1.15.0/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:32:in `require'
[redacted]/vendor/bundle/ruby/3.2.0/gems/bootsnap-1.15.0/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:32:in `require'
[redacted]/config/initializers/zeitwerk.rb:20:in `require'
[redacted]/vendor/bundle/ruby/3.2.0/bundler/gems/formtastic-154e78f3e503/lib/formtastic/engine.rb:7:in `block (2 levels) in <class:Engine>'
[redacted]/vendor/bundle/ruby/3.2.0/gems/activesupport-7.0.4.1/lib/active_support/lazy_load_hooks.rb:95:in `class_eval'
[redacted]/vendor/bundle/ruby/3.2.0/gems/activesupport-7.0.4.1/lib/active_support/lazy_load_hooks.rb:95:in `block in execute_hook'
[redacted]/vendor/bundle/ruby/3.2.0/gems/activesupport-7.0.4.1/lib/active_support/lazy_load_hooks.rb:85:in `with_execution_control'
[redacted]/vendor/bundle/ruby/3.2.0/gems/activesupport-7.0.4.1/lib/active_support/lazy_load_hooks.rb:90:in `execute_hook'
[redacted]/vendor/bundle/ruby/3.2.0/gems/activesupport-7.0.4.1/lib/active_support/lazy_load_hooks.rb:60:in `block in on_load'
[redacted]/vendor/bundle/ruby/3.2.0/gems/activesupport-7.0.4.1/lib/active_support/lazy_load_hooks.rb:59:in `each'
[redacted]/vendor/bundle/ruby/3.2.0/gems/activesupport-7.0.4.1/lib/active_support/lazy_load_hooks.rb:59:in `on_load'
[redacted]/vendor/bundle/ruby/3.2.0/bundler/gems/formtastic-154e78f3e503/lib/formtastic/engine.rb:6:in `block in <class:Engine>'
[redacted]/vendor/bundle/ruby/3.2.0/gems/railties-7.0.4.1/lib/rails/initializable.rb:32:in `instance_exec'
[redacted]/vendor/bundle/ruby/3.2.0/gems/railties-7.0.4.1/lib/rails/initializable.rb:32:in `run'
[redacted]/vendor/bundle/ruby/3.2.0/gems/railties-7.0.4.1/lib/rails/initializable.rb:61:in `block in run_initializers'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/3.2.0/tsort.rb:228:in `block in tsort_each'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/3.2.0/tsort.rb:350:in `block (2 levels) in each_strongly_connected_component'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/3.2.0/tsort.rb:431:in `each_strongly_connected_component_from'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/3.2.0/tsort.rb:349:in `block in each_strongly_connected_component'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/3.2.0/tsort.rb:347:in `each'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/3.2.0/tsort.rb:347:in `call'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/3.2.0/tsort.rb:347:in `each_strongly_connected_component'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/3.2.0/tsort.rb:226:in `tsort_each'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/3.2.0/tsort.rb:205:in `tsort_each'
[redacted]/vendor/bundle/ruby/3.2.0/gems/railties-7.0.4.1/lib/rails/initializable.rb:60:in `run_initializers'
[redacted]/vendor/bundle/ruby/3.2.0/gems/railties-7.0.4.1/lib/rails/application.rb:372:in `initialize!'
[redacted]/config/environment.rb:7:in `<top (required)>'
[redacted]/spec/rails_helper.rb:8:in `require'
[redacted]/spec/rails_helper.rb:8:in `<top (required)>'
[redacted]/vendor/bundle/ruby/3.2.0/gems/rspec-core-3.12.0/lib/rspec/core/configuration.rb:2117:in `require'
[redacted]/vendor/bundle/ruby/3.2.0/gems/rspec-core-3.12.0/lib/rspec/core/configuration.rb:2117:in `load_file_handling_errors'
[redacted]/vendor/bundle/ruby/3.2.0/gems/rspec-core-3.12.0/lib/rspec/core/configuration.rb:1576:in `block in requires='
[redacted]/vendor/bundle/ruby/3.2.0/gems/rspec-core-3.12.0/lib/rspec/core/configuration.rb:1576:in `each'
[redacted]/vendor/bundle/ruby/3.2.0/gems/rspec-core-3.12.0/lib/rspec/core/configuration.rb:1576:in `requires='
[redacted]/vendor/bundle/ruby/3.2.0/gems/rspec-core-3.12.0/lib/rspec/core/configuration_options.rb:113:in `block in process_options_into'
[redacted]/vendor/bundle/ruby/3.2.0/gems/rspec-core-3.12.0/lib/rspec/core/configuration_options.rb:112:in `each'
[redacted]/vendor/bundle/ruby/3.2.0/gems/rspec-core-3.12.0/lib/rspec/core/configuration_options.rb:112:in `process_options_into'
[redacted]/vendor/bundle/ruby/3.2.0/gems/rspec-core-3.12.0/lib/rspec/core/configuration_options.rb:22:in `configure'
[redacted]/vendor/bundle/ruby/3.2.0/gems/rspec-core-3.12.0/lib/rspec/core/runner.rb:132:in `configure'
[redacted]/vendor/bundle/ruby/3.2.0/gems/rspec-core-3.12.0/lib/rspec/core/runner.rb:99:in `setup'
[redacted]/vendor/bundle/ruby/3.2.0/gems/rspec-core-3.12.0/lib/rspec/core/runner.rb:86:in `run'
[redacted]/vendor/bundle/ruby/3.2.0/gems/rspec-core-3.12.0/lib/rspec/core/runner.rb:71:in `run'
[redacted]/vendor/bundle/ruby/3.2.0/gems/rspec-core-3.12.0/lib/rspec/core/runner.rb:45:in `invoke'
[redacted]/vendor/bundle/ruby/3.2.0/gems/rspec-core-3.12.0/exe/rspec:4:in `<top (required)>'
[redacted]/vendor/bundle/ruby/3.2.0/bin/rspec:25:in `load'
[redacted]/vendor/bundle/ruby/3.2.0/bin/rspec:25:in `<top (required)>'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/bundler-2.4.3/lib/bundler/cli/exec.rb:58:in `load'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/bundler-2.4.3/lib/bundler/cli/exec.rb:58:in `kernel_load'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/bundler-2.4.3/lib/bundler/cli/exec.rb:23:in `run'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/bundler-2.4.3/lib/bundler/cli.rb:491:in `exec'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/bundler-2.4.3/lib/bundler/vendor/thor/lib/thor/command.rb:27:in `run'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/bundler-2.4.3/lib/bundler/vendor/thor/lib/thor/invocation.rb:127:in `invoke_command'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/bundler-2.4.3/lib/bundler/vendor/thor/lib/thor.rb:392:in `dispatch'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/bundler-2.4.3/lib/bundler/cli.rb:34:in `dispatch'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/bundler-2.4.3/lib/bundler/vendor/thor/lib/thor/base.rb:485:in `start'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/bundler-2.4.3/lib/bundler/cli.rb:28:in `start'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/bundler-2.4.3/exe/bundle:45:in `block in <top (required)>'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/bundler-2.4.3/lib/bundler/friendly_errors.rb:117:in `with_friendly_errors'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/bundler-2.4.3/exe/bundle:33:in `<top (required)>'
/opt/hostedtoolcache/Ruby/3.2.0/x64/bin/bundle:25:in `load'
/opt/hostedtoolcache/Ruby/3.2.0/x64/bin/bundle:25:in `<main>'config/application.rb:20 looks like this:
Bundler.require(*Rails.groups)spec/rails_helper.rb:8 looks like this:
require File.expand_path("../config/environment", __dir__)config/environment.rb looks like this:
Could it be that lib/formtastic/inputs/base/associations.rb is the first file (naive guess from the potential alphabetical ordering) that includes a line containing module Base that wasn't loaded yet (from lib/formtastic/inputs/base.rb) for some reason?
fxn
commented
1 year ago Thanks for all the tests! I am seeing data that does not seem to square, which is a good thing.
Given this data, to complete the picture I'd like to ask you for a final test. Could you please copy and paste that code with the traces into the engine initializer that is raising, just before the include line? Should look like this
initializer 'formtastic.initialize' do
ActiveSupport.on_load(:action_view) do
p Formtastic.object_id
p Object.const_source_location(:Formtastic, false)
p Formtastic::Helpers.object_id
p Formtastic.const_source_location(:Helpers, false)
p Formtastic::Helpers.constants(false)
p Formtastic::Helpers.autoload?(:FormHelper, false)
include Formtastic::Helpers::FormHelper
end
endImportant that it is the code verbatim and not a call to some global method or something, to verify constant name resolution in the spot where the failure happens. Important also that the code is located within the block, as in the example.
We are intereseted here in the traces for a successful execution, and the ones when the include fails.
fxn
commented
1 year ago Oh! I didn't say it, but please leave the other two as well! I'd like to compare the output of the three of them in the same process.
maximevaillancourt
commented
1 year ago Thank you for your patience, I've been running specs like a madman trying to reproduce the problem 😄
See the two attached files. I'm not seeing anything particularly telling — let me know if you see something relevant.
2023-01-20-formtastic-lib-engine-traces-failure.txt 2023-01-20-formtastic-lib-engine-traces-success.txt
For reference, here's the custom Formtastic branch I've been using (in case you're curious about the formtastic-related line numbers in the stack traces): https://github.com/formtastic/formtastic/compare/master...maximevaillancourt:formtastic:4.0-stable-print-caller-locations
A non-nil return value from autoload? means the constant wasn't loaded (yet), right? If so, I don't understand why we don't see nil as the output of autoload? in the success case 🤔
maximevaillancourt
commented
1 year ago Either way, something seems weird with the order in which constants marked to be autoloaded actually get loaded. It smells like a race condition, or at least some kind of randomized ordering that could be causing this to happen only sometimes. I've been playing with replacing autoload with require in lib/formtastic/helpers.rb to see if there's a deterministic order in which we can always load or crash the app, and found this:
# lib/formtastic/helpers.rb
module Formtastic
module Helpers
# Current code in formtastic v4.0.0-stable, leads to intermittent
# `NameError: uninitialized constant Formtastic::Helpers::FormHelper`
# autoload :ButtonsHelper, 'formtastic/helpers/buttons_helper'
# autoload :ActionHelper, 'formtastic/helpers/action_helper'
# autoload :ActionsHelper, 'formtastic/helpers/actions_helper'
# autoload :ErrorsHelper, 'formtastic/helpers/errors_helper'
# autoload :FieldsetWrapper, 'formtastic/helpers/fieldset_wrapper'
# autoload :FileColumnDetection, 'formtastic/helpers/file_column_detection'
# autoload :FormHelper, 'formtastic/helpers/form_helper'
# autoload :InputHelper, 'formtastic/helpers/input_helper'
# autoload :InputsHelper, 'formtastic/helpers/inputs_helper'
# autoload :Reflection, 'formtastic/helpers/reflection'
# autoload :Enum, 'formtastic/helpers/enum'
# The app boots fine with these `require` calls in this order
# require 'formtastic/helpers/reflection'
# require 'formtastic/helpers/file_column_detection'
# require 'formtastic/helpers/errors_helper'
# require 'formtastic/helpers/fieldset_wrapper'
# require 'formtastic/helpers/actions_helper'
# require 'formtastic/helpers/action_helper'
# require 'formtastic/helpers/enum'
# require 'formtastic/helpers/inputs_helper'
# require 'formtastic/helpers/input_helper'
# require 'formtastic/helpers/form_helper'
# The app also boots somehow with these, with form_helper commented out (!?)
require 'formtastic/helpers/reflection'
require 'formtastic/helpers/file_column_detection'
require 'formtastic/helpers/errors_helper'
require 'formtastic/helpers/fieldset_wrapper'
require 'formtastic/helpers/actions_helper'
require 'formtastic/helpers/action_helper'
require 'formtastic/helpers/enum'
require 'formtastic/helpers/inputs_helper'
require 'formtastic/helpers/input_helper'
# require 'formtastic/helpers/form_helper'
end
endI haven't been able to find a way to reliably reproduce NameError: uninitialized constant Formtastic::Helpers::FormHelper yet.
fxn
commented
1 year ago Thanks @maximevaillancourt. These traces certainly have puzzling data. I'll summarize what I find contradictory in them.
The last one narrowed down things. I was hoping within the initializer the constants did not evaluate to what we expect. But they do, and the module state is the same.
So, I'd like to see with my own eyes that no autoloading attempt is done whatsoever to that file, or refute this. In either case, we'll narrow this down even further.
Could you please write pp caller_locations at the top of lib/formtastic/helpers/form_helper.rb? When a failure happens, do you see those traces anywhere printed? If no, that is a data point, if yes, could you please share?
Is this test suite executing code concurrently in any way when you reproduce?
fxn
commented
1 year ago Ah, just in case the file is attempted to be loaded, in addition to tha trace, it would be a good idea to wrap the entire contents in a begin/rescue as suggested by @byroot.
maximevaillancourt
commented
1 year ago Here are the requested traces, including pp caller_locations at the top of lib/formtastic/helpers/form_helper.rb, and the exceptions printed from the rescue block wrapping the entire module in lib/formtastic/helpers/form_helper.rb (as implemented here).
2023-01-21-formtastic-formhelper-caller-locations-trace.txt
Is this test suite executing code concurrently in any way when you reproduce?
That has been one of my hypotheses since the beginning of this investigation since we have with some tests running web requests through Puma, but I've forced the thread count to be 1 and the problem would still show up from time to time in that configuration. Either way, when it does show up, the NameError exception happens before the test suite even starts, so I'm not convinced it's related to the tests themselves (the exception seems to happen when trying to load the environment / the Rails app, which happens via rails_helper.rb).
Once again, thank you for your help with this, I appreciate it a lot!
fxn
commented
1 year ago Awesome, quick reply to thank you for your persistence triggering the failures.
Great that concurrency is no involved. I was wondering about a possible fiber scheduler. If this happens only during boot, bin/rails r 1 is enough to reproduce, and we don't even have that variable.
I have a busy weekend, but will compile what I find suspicious and write back.
Thanks again!
fxn
commented
1 year ago BTW, the fact that this happens during the boot process does not square with the fact that this does not fail consistently. In a normal initialzation, things load in exactly the same order and if something is not correct they always fail.
This is just a remark at 23:12 PM in case it triggers some idea about this particular application, not my detailed compilation of suspicions in which this is one the items :).
maximevaillancourt
commented
1 year ago Good callout: you're right that it doesn't happen during the boot process, since I'm unable to reproduce the exception at all when running only bin/rails r 1 alone. I also went ahead and tried running ruby spec/rails_helper.rb by itself (which gets loaded for our tests), and that doesn't reproduce the exception either. An hypothesis based on the previous sentences would be that it's the combination of different things going on (potentially in different / random order) when we run tests that affects $LOAD_PATH or $LOADED_FEATURES.
However, this is what I see when tests fail:
An error occurred while loading rails_helper.
Failure/Error: require File.expand_path("../config/environment", __dir__)When I wrote "booting the app", what I really meant was "loading the environment", and looking at the stack traces I shared earlier (e.g. here), this is the common entrypoint:
# config/environment.rb, line 7
Rails.application.initialize!Good, that solves it.
I you need ro run specs to reproduce, I wonder if passing the same seed that triggered a failure could result in subsequent consistent failures.
maximevaillancourt
commented
1 year ago (note that I added some context in this comment since you replied)
I wonder if passing the same seed that triggered a failure could result in subsequent consistent failures.
I configured rspec to run tests in a deterministic order, so there's no seed involved at all:
RSpec.configure do |config|
config.order = :defined # instead of :random
...
endOur CI suite is also configured to deterministically run the same set of tests, yet I'm able to retry a run (with the same commit SHA) and sometimes get an exception, and sometimes not, even if the same set of tests coming from the same commit should run in the same order every time (and this goes both ways: a run that failed can succeed if retried, and conversely a run that succeeded can fail if retried). Puzzling situation.
maximevaillancourt
commented
1 year ago In case it helps with identifying a common thread, we're also seeing the intermittent NameError: uninitialized constant <constant> exceptions with the following constants in addition to Formtastic::Helpers::FormHelper:
ActiveStorage::Attached (GitHub issue in rails/rails for this one here)ActiveStorage::Attached::Changes::CreateOneActionView::TemplatePathInheritedResources::ActionsRailsSemanticLogger::ActionView::LogSubscriberRailsSemanticLogger::ActiveJob::LogSubscriberRailsSemanticLogger::ActiveRecord::LogSubscriberViewComponent::CompilerViewComponent::TestHelpersfxn
commented
1 year ago Awesome, I believe this observation is very important, because that probably means what we see in this gem is a consequence of something more generic.
My hunch is that there is something in the app or some of it dependencies causing this somehow. Most likely not even directly related to any of the gems for which constants get missed.
fxn
commented
1 year ago OK, here's my summary of the things that I find puzzling:
We have seen that this can be triggered by specs, but sometimes it shows up, and sometimes not, despite specs run in the same order always. The kind of thing we are observing seems deterministic if things load linearly, but it is not. Hypothesis: There is something non-deterministic we are missing.
The line that triggers the error is always the same one. So, it is not exactly random either. This may be important.
Formtastic::HelpersWe have verified that the class and module objects are the same when the application boots, just before the line where the error happens, and later on. This is good.
We have also seen that:
NameError: uninitialized constant Formtastic::Helpers::FormHelper is raised.Formtastic::Helpers.constants contains :FormHelper in the three spots.Formtastic::Helpers.autoload?(:FormHelper) returns "formtastic/helpers/form_helper" in the three spots.However, this state is odd. Let me show some autoload scenarios:
FormHelper gets defined and nothing is raised, the symbol :FormHelper remains in constants, and autoload? returns nil.
FormHelper gets defined, and something is raised, you get the raised exception, the symbol :FormHelper remains in constants, and autoload? still has the 2nd argument passed to autoload (the path to be required).FormHelper does not get defined, and nothing is raised, you get a NameError with the expected "uninitialized constant" message raised in the place with the constant reference, the symbol :FormHelper remains in constants, and autoload? returns nil.We have seen the file that defines Formtastic::Helpers::FormHelper gets executed, the autoload does get triggered.
Obviously, when the error is hit, we are not in (1).
If we look at _lib/formtastic/helpers/formhelper.rb, the constant is clearly defined because before the constant definition we only have comments. Therefore, we are not in (3). Also, this is consistent with the fact that autoload? is not nil after the exception happened. 👍
We seem to be in (2), but then why do we get uninitialized constant Formtastic::Helpers::FormHelper? Shouldn't we be getting a different error message?
Is someone shallowing the actual exception and reraising as NameError?
@maximevaillancourt when you wrap the entire _lib/formtastic/helpers/formhelper.rb file in begin/rescue, which are the exceptions as inspected within that rescue clause? I have searched for it in the existing traces, but have not found it, please excuse if I missed it.
We have seen that Object.const_source_location(:Formtastic, false) returns lib/formtastic/helpers.rb.
If we look at the entrypoint of Active Admin, it has a require "formtastic" in line 8. Now, if we look at the entrypoint of Formtastic, it defines its engine if under Rails, and moves on otherwise.
Now, both lib/formtastic/engine.rb and lib/formtastic.rb have module Formtastic. So, if under Rails, const_source_location should say lib/formtastic/engine.rb. How on earth does Ruby say the constant is defined in lib/formtastic/helpers.rb? The traces above say that loading that file is triggered by line 129 of _lib/activeadmin.rb. The constant Formtastic is more than defined when you reach line 129.
So, this is a summary of the things that I find puzzling in the investigation so far. I'll sleep on it, let's see if any of us has an eureka moment :).
fxn
commented
1 year ago Re Formtastic constant definition. In a vanilla Rails application I just created:
% bin/rails r 'p Object.const_source_location(:Formtastic)'
["/Users/fxn/.rbenv/versions/3.0.2/lib/ruby/gems/3.0.0/gems/formtastic-4.0.0/lib/formtastic/engine.rb", 1]as expected.
If you load Active Admin, or you load Formtastic, you get that under Rails. Now, in theory someone could be loading lib/formtastic/helpers.rb directly, yes, but then caller_locations would not show the backtrace that it shows.
fxn
commented
1 year ago @maximevaillancourt does your application run under Spring?
maximevaillancourt
commented
1 year ago Most excellent summary. Thank you for writing this up!
My hunch is that there is something in the app or some of it dependencies causing this somehow. Most likely not even directly related to any of the gems for which constants get missed.
Agreed.
Hypothesis: There is something non-deterministic we are missing.
Again, agreed.
We seem to be in (2), but then why do we get uninitialized constant
Formtastic::Helpers::FormHelper? Shouldn't we be getting a different error message?
Right, I've been throwing rescue blocks everywhere (for LoadError and NameError specifically, and also for StandardError as a fallback), but I haven't seen any StandardError being rescued somehow. I might be doing something wrong though (in terms of printing and re-raising, maybe I shouldn't re-raise?)
@maximevaillancourt when you wrap the entire _lib/formtastic/helpers/formhelper.rb file in
begin/rescue, which are the exceptions as inspected within thatrescueclause? I have searched for it in the existing traces, but have not found it, please excuse if I missed it.
It's in the trace linked in this comment, and it's still Formtastic::Helpers::FormHelper somehow (here's the rescue block implementation if you're curious):
***************** BEGIN LoadError, NameError rescue in lib/formtastic/helpers/form_helper.rb *********************
uninitialized constant Formtastic::Helpers::FormHelper
[redacted]/vendor/bundle/ruby/3.2.0/bundler/gems/formtastic-cdd80373bc4f/lib/formtastic/helpers/form_helper.rb:54:in `<module:Helpers>'
[redacted]/vendor/bundle/ruby/3.2.0/bundler/gems/formtastic-cdd80373bc4f/lib/formtastic/helpers/form_helper.rb:7:in `<module:Formtastic>'
[redacted]/vendor/bundle/ruby/3.2.0/bundler/gems/formtastic-cdd80373bc4f/lib/formtastic/helpers/form_helper.rb:6:in `<top (required)>'
[redacted]/vendor/bundle/ruby/3.2.0/gems/bootsnap-1.15.0/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:32:in `require'
[redacted]/vendor/bundle/ruby/3.2.0/gems/bootsnap-1.15.0/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:32:in `require'
[redacted]/config/initializers/zeitwerk.rb:19:in `require'
[redacted]/vendor/bundle/ruby/3.2.0/bundler/gems/formtastic-cdd80373bc4f/lib/formtastic/engine.rb:15:in `block (2 levels) in <class:Engine>'
[redacted]/vendor/bundle/ruby/3.2.0/gems/activesupport-7.0.4.1/lib/active_support/lazy_load_hooks.rb:95:in `class_eval'
[redacted]/vendor/bundle/ruby/3.2.0/gems/activesupport-7.0.4.1/lib/active_support/lazy_load_hooks.rb:95:in `block in execute_hook'
[redacted]/vendor/bundle/ruby/3.2.0/gems/activesupport-7.0.4.1/lib/active_support/lazy_load_hooks.rb:85:in `with_execution_control'
[redacted]/vendor/bundle/ruby/3.2.0/gems/activesupport-7.0.4.1/lib/active_support/lazy_load_hooks.rb:90:in `execute_hook'
[redacted]/vendor/bundle/ruby/3.2.0/gems/activesupport-7.0.4.1/lib/active_support/lazy_load_hooks.rb:60:in `block in on_load'
[redacted]/vendor/bundle/ruby/3.2.0/gems/activesupport-7.0.4.1/lib/active_support/lazy_load_hooks.rb:59:in `each'
[redacted]/vendor/bundle/ruby/3.2.0/gems/activesupport-7.0.4.1/lib/active_support/lazy_load_hooks.rb:59:in `on_load'
[redacted]/vendor/bundle/ruby/3.2.0/bundler/gems/formtastic-cdd80373bc4f/lib/formtastic/engine.rb:6:in `block in <class:Engine>'
[redacted]/vendor/bundle/ruby/3.2.0/gems/railties-7.0.4.1/lib/rails/initializable.rb:32:in `instance_exec'
[redacted]/vendor/bundle/ruby/3.2.0/gems/railties-7.0.4.1/lib/rails/initializable.rb:32:in `run'
[redacted]/vendor/bundle/ruby/3.2.0/gems/railties-7.0.4.1/lib/rails/initializable.rb:61:in `block in run_initializers'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/3.2.0/tsort.rb:228:in `block in tsort_each'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/3.2.0/tsort.rb:350:in `block (2 levels) in each_strongly_connected_component'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/3.2.0/tsort.rb:431:in `each_strongly_connected_component_from'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/3.2.0/tsort.rb:349:in `block in each_strongly_connected_component'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/3.2.0/tsort.rb:347:in `each'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/3.2.0/tsort.rb:347:in `call'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/3.2.0/tsort.rb:347:in `each_strongly_connected_component'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/3.2.0/tsort.rb:226:in `tsort_each'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/3.2.0/tsort.rb:205:in `tsort_each'
[redacted]/vendor/bundle/ruby/3.2.0/gems/railties-7.0.4.1/lib/rails/initializable.rb:60:in `run_initializers'
[redacted]/vendor/bundle/ruby/3.2.0/gems/railties-7.0.4.1/lib/rails/application.rb:372:in `initialize!'
[redacted]/config/environment.rb:7:in `<top (required)>'
[redacted]/spec/rails_helper.rb:8:in `require'
[redacted]/spec/rails_helper.rb:8:in `<top (required)>'
[redacted]/vendor/bundle/ruby/3.2.0/gems/rspec-core-3.12.0/lib/rspec/core/configuration.rb:2117:in `require'
[redacted]/vendor/bundle/ruby/3.2.0/gems/rspec-core-3.12.0/lib/rspec/core/configuration.rb:2117:in `load_file_handling_errors'
[redacted]/vendor/bundle/ruby/3.2.0/gems/rspec-core-3.12.0/lib/rspec/core/configuration.rb:1576:in `block in requires='
[redacted]/vendor/bundle/ruby/3.2.0/gems/rspec-core-3.12.0/lib/rspec/core/configuration.rb:1576:in `each'
[redacted]/vendor/bundle/ruby/3.2.0/gems/rspec-core-3.12.0/lib/rspec/core/configuration.rb:1576:in `requires='
[redacted]/vendor/bundle/ruby/3.2.0/gems/rspec-core-3.12.0/lib/rspec/core/configuration_options.rb:113:in `block in process_options_into'
[redacted]/vendor/bundle/ruby/3.2.0/gems/rspec-core-3.12.0/lib/rspec/core/configuration_options.rb:112:in `each'
[redacted]/vendor/bundle/ruby/3.2.0/gems/rspec-core-3.12.0/lib/rspec/core/configuration_options.rb:112:in `process_options_into'
[redacted]/vendor/bundle/ruby/3.2.0/gems/rspec-core-3.12.0/lib/rspec/core/configuration_options.rb:22:in `configure'
[redacted]/vendor/bundle/ruby/3.2.0/gems/rspec-core-3.12.0/lib/rspec/core/runner.rb:132:in `configure'
[redacted]/vendor/bundle/ruby/3.2.0/gems/rspec-core-3.12.0/lib/rspec/core/runner.rb:99:in `setup'
[redacted]/vendor/bundle/ruby/3.2.0/gems/rspec-core-3.12.0/lib/rspec/core/runner.rb:86:in `run'
[redacted]/vendor/bundle/ruby/3.2.0/gems/rspec-core-3.12.0/lib/rspec/core/runner.rb:71:in `run'
[redacted]/vendor/bundle/ruby/3.2.0/gems/rspec-core-3.12.0/lib/rspec/core/runner.rb:45:in `invoke'
[redacted]/vendor/bundle/ruby/3.2.0/gems/rspec-core-3.12.0/exe/rspec:4:in `<top (required)>'
[redacted]/vendor/bundle/ruby/3.2.0/bin/rspec:25:in `load'
[redacted]/vendor/bundle/ruby/3.2.0/bin/rspec:25:in `<top (required)>'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/bundler-2.4.3/lib/bundler/cli/exec.rb:58:in `load'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/bundler-2.4.3/lib/bundler/cli/exec.rb:58:in `kernel_load'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/bundler-2.4.3/lib/bundler/cli/exec.rb:23:in `run'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/bundler-2.4.3/lib/bundler/cli.rb:491:in `exec'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/bundler-2.4.3/lib/bundler/vendor/thor/lib/thor/command.rb:27:in `run'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/bundler-2.4.3/lib/bundler/vendor/thor/lib/thor/invocation.rb:127:in `invoke_command'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/bundler-2.4.3/lib/bundler/vendor/thor/lib/thor.rb:392:in `dispatch'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/bundler-2.4.3/lib/bundler/cli.rb:34:in `dispatch'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/bundler-2.4.3/lib/bundler/vendor/thor/lib/thor/base.rb:485:in `start'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/bundler-2.4.3/lib/bundler/cli.rb:28:in `start'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/bundler-2.4.3/exe/bundle:45:in `block in <top (required)>'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/bundler-2.4.3/lib/bundler/friendly_errors.rb:117:in `with_friendly_errors'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/bundler-2.4.3/exe/bundle:33:in `<top (required)>'
/opt/hostedtoolcache/Ruby/3.2.0/x64/bin/bundle:25:in `load'
/opt/hostedtoolcache/Ruby/3.2.0/x64/bin/bundle:25:in `<main>'How on earth does Ruby say the constant is defined in lib/formtastic/helpers.rb?
Could it have something to do with the ActiveSupport.on_load block implemented here? Maybe the callback fires at different times when the Rails environment is loaded, thus triggering the exception only sometimes?
Your entire paragraph in the "Formtastic is defined in lib/formtastic/helpers.rb" section is particularly interesting and makes me think it's getting closer to the root cause.
When autoload statements get evaluated, are they always treated in the same way? Is there something that can affect how they're interpreted? I ask because I've seen some recent changes in Ruby around potential race conditions with autoload.
@maximevaillancourt does your application run under Spring?
Only in development: the spring gem is only present in the development group of our Gemfile. I even tried running spring stop before our tests start running in CI, and it failed because Spring simply isn't loaded in the test environment, which is what I wanted to confirm, so definitely no Spring involved. I've since tried my best to replicate our CI setup locally by doing everything with the BUNDLE_WITHOUT=development:production environment variable, CI=true, RAILS_ENV=test and ENVIRONMENT=test to only install test gems, but that still hasn't allowed me to reproduce the bug locally yet.
fxn
commented
1 year ago OK, we got a new puzzling data point: The exception is not raised in the middle of the evaluation of _lib/formtastic/helpers/formhelper.rb, it is evaluated on line 54 of your patched Formtastic which is (indentation removed):
module FormHelperthis suggests some kind of inception mixed with some kind of bad internal state.
Could it have something to do with the ActiveSupport.on_load block implemented here? Maybe the callback fires at different times when the Rails environment is loaded, thus triggering the exception only sometimes?
In principle that one is deterministic. Initializers get ordered by Rails in topological order, that is why we see "tsort" in the backtraces. Then, whenever actionview/lib/action_view/base.rb is loaded and the bottom of the file reached, Active Support knows that it is loaded. Existing on_load blocks get executed, and subsequent ones run on the spot.
Your entire paragraph in the "Formtastic is defined in lib/formtastic/helpers.rb" section is particularly interesting and makes me think it's getting closer to the root cause.
Agree.
When autoload statements get evaluated, are they always treated in the same way? Is there something that can affect how they're interpreted?
When there is a constant lookup, a class or module is checked, and the constant is not in memory properly, but has an autoload for it, the autoload is triggered. There is an inception case in which the lookup happens because Ruby tries to see if the constant after a class or module keyword stores a class or module object, and therefore has to reopen them. For example, given this foo.rb:
$LOAD_PATH << __dir__
module M
autoload :C, 'c'
end
# Done in the same file, could be somewhere else.
module M
class C
end
endand this c.rb:
puts "AUTOLOADED!"
module M
class C
end
endyou'll see running foo.rb triggers the autoload when the definition of M::C is attempted and indeed that definition reopens the class defined in c.rb.
But, in any case, the constant is found and everything works as expected.
I ask because I've seen some recent changes in Ruby around potential race conditions with autoload.
That particular race condition does not affect this case, because there you have two different constants pointing to the same file. Autoload and constant references are synchronized, so, if thread T reaches A while another thread is in the middle of autoloading A, thread T is going to block and only resume when the autoload has finished.
Last paragraph about not being able to reproduce locally seems interesting.
My hunch is that something is messing up with constants in memory and/or $LOADED_FEATURES. And this should be unrelated to Rails autoloading or reloading, because we are seeing this in regular 3rd party files and constants not managed by Rails.
fxn
commented
1 year ago With all this, I would laser-focus the investigation in understanding what's the deal with the reported constant definition information for Formtastic. Would put traces in several places to see they are printed (could require "formtastic" return false due to some corrupted state even if the constant is not defined? that would be consistent with line 129 ending up defining Formtastic.), and also to monitor that in every meaningful place Formtastic.object_id is the same. In particular in the line right after module Formtastic in lib/formtastic.rb and lib/formtastic/engine.rb.
fxn
commented
1 year ago There is something that decorates require, deals with $LOADED_FEATURES, and has a global scope, not circumscribed to the application: Bootsnap.
In my experience, Bootsnap works wonderfully and transparently. I doubt it has anything to do with this. But given the coincidence in the features that I suspect could be into play here, I believe we have to verify if the failure happens without Bootsnap or not (DISABLE_BOOTSNAP=1).
maximevaillancourt
commented
1 year ago Something seems deeply wrong: if I disable Bootsnap, I start getting a bunch of (again, intermittent) LoadError: cannot load such file <file> (note, not NameError) calls for different constants—some internal, some from external gems. Probably the same root cause, just different symptoms.
fxn
commented
1 year ago Interesting!
I'd suggest to disable Bootsnap during this investigation then. I am pretty sure Bootsnap is good, but if you are seeing different results, I think it is better to not have a cache of data that may be wrong from the start. The situation is puzzling, in order to ease reasoning about the problem, the less moving parts we have, the better.
fxn
commented
1 year ago Could there be something funky related to the file system in CI?
maximevaillancourt
commented
1 year ago Possible. I've been tearing out all the caching layers + SSH'ing into the CI runners to see what's going on. Two hypotheses I'm exploring now:
LoadError may raise when a file can't be read by the CI runner user (say because it doesn't have the read permission)maximevaillancourt
commented
1 year ago Update on permissions: the permissions are the same on files that show up in $LOADED_PATHS and those that don't (and end up raising NameError or LoadError).
maximevaillancourt
commented
1 year ago Okay, here's a definite thing that's happening: somehow, some files get removed from $LOADED_FEATURES, and when that happens, NameError/LoadError shows up (which seems obvious now that I write it down). I just don't understand why, or how a single file would be removed from $LOADED_FEATURES (and not its siblings within a namespace/directory), and even less which that would happen in an intermittent fashion, especially considering that its direct parent directory (or one of its parent directories) is present in $LOAD_PATH.
A note on local reproduction: I've had a colleague accidentally reproduce the bug locally on his machine (the only time we've seen it locally!), never to be reproduced again locally to this day.
Considering we have pretty fast machines for local development, and considering the GitHub Actions workers are not that fast (from anecdotal evidence of me playing around in one of their CI runners via SSH), this bug really smells like some kind of race condition, where something gets added/removed from $LOADED_FEATURES and when two things try to load/unload code, the result is a mangled $LOADED_FEATURES, leading to intermittent NameError/LoadError.
@fxn: are you aware of anything (not Bootsnap or Spring, those are disabled) that would remove entries from $LOADED_FEATURES, whether in Rails itself or else? 🤔
fxn
commented
1 year ago Yes, that happens when Rails reloads. The files that correspond to constants autoloaded by Rails get removed from $LOADED_FEATURES, and the constants themselves deleted.
That way, after reload, files can be required again to load the new code. Otherwise, idempotence would prevent it.
However, in CI you normally do not reload. And this logic completely ignores 3rd party code. Rails does not mess with $LOADED_FEATURES entries not managed by Rails.
maximevaillancourt
commented
1 year ago Otherwise, idempotence would prevent it.
I see, that makes sense. Can't load the new code without unloading the old one.
That way, after reload, files can be required again to load the new code.
Is there a possibility that this step fails sometimes? As in, the "un-loading" works, but the subsequent load of the new code doesn't?
However, in CI you normally do not reload.
Right. Even with config.eager_load = true and config.cache_classes = true, no Spring installed, and Bootsnap disabled, the intermittent exceptions happen.
maximevaillancourt
commented
1 year ago ~I found a way to reliably reproduce NameError: uninitialized constant Formtastic::Helpers::FormHelper, but it's not a great reproduction case because it doesn't involve controlling a particular environmental variable, instead it directly plays with $LOADED_FEATURES. Anyway, here goes, in case it's useful:~
formtastic_dir = Gem::Specification.find_by_name("formtastic").gem_dir
$LOADED_FEATURES << File.join(formtastic_dir, "lib/formtastic/helpers/form_helper.rb")~^ Adding the above to config/test.rb (before Rails.application.configure do) reliably raises NameError. I'm not entirely sure why, but I imagine it's because we mess with the internal state, leading subsequent Kernel#require calls to break.~
~That being said, I guess it's possible that this is the weird state we end up in when NameError shows up intermittently in CI?~
Edit: this seems incorrect, since my observations have been the opposite: form_helper.rb is not in $LOADED_FEATURES when the exceptions show up.
Anyway, here's a useful insight: Rails.autoloaders.log! prints the exact same output in both success and failure scenarios ✅
fxn
commented
1 year ago Is there a possibility that this step fails sometimes? As in, the "un-loading" works, but the subsequent load of the new code doesn't?
It canntot be entirely ruled out, but I'd be surprised if that happens. For once, Zeitwerk is used quite a bit (passed 200 million downloads recently), and has not had a known bug for a long time. Even more, if the application does not reload, no unloading or $LOADED_FEATURES mutation happens at all.
Even with config.eager_load = true and config.cache_classes = true, no Spring installed, and Bootsnap disabled, the intermittent exceptions happen.
Excellent, that reduces the scope.
So, since errors changed, let's see where we are now. Do you still hit the failure in the same place with the include?
What does
bin/rails r 'p Object.const_source_location(:Formtastic)'print now?
maximevaillancourt
commented
1 year ago Do you still hit the failure in the same place with the
include?
When disabling Bootsnap, instead of intermittent NameError exceptions, we get intermittent LoadError instead, but not for the same constants as before. Some are the same, but some are new.
What does
bin/rails r 'p Object.const_source_location(:Formtastic)'print now?
Here's what I get in my local development environment (where Spring exists):
# With Bootsnap enabled
➜ spring stop && bin/rails r 'p Object.const_source_location(:Formtastic)'
Spring stopped.
2023-01-24 11:35:45.577751 D [46984:10000] Sidekiq -- Sidekiq Pro client with Sidekiq::RedisConnection::RedisAdapter options {:url=>nil}
2023-01-24 11:35:45.577814 D [46984:10000] Sidekiq -- ReliablePush activated
2023-01-24 11:35:46.177227 I [46984:10000] Rails -- Initializing websocket
Running via Spring preloader in process 46996
["/Users/work/.rbenv/versions/3.2.0/lib/ruby/gems/3.2.0/gems/formtastic-4.0.0/lib/formtastic/engine.rb", 1]
# With Bootsnap disabled
➜ spring stop && DISABLE_BOOTSNAP=1 RAILS_ENV=test bin/rails r 'p Object.const_source_location(:Formtastic)'
Spring stopped.
Type application/netcdf is already registered as a variant of application/netcdf.
["/Users/work/.rbenv/versions/3.2.0/lib/ruby/gems/3.2.0/gems/formtastic-4.0.0/lib/formtastic/engine.rb", 1]I've been trying to nuke certain gems from our repository to see if one's responsible for a bad require statement somewhere, but haven't found anything yet.
One thing worth noting:
NameError is the exception class), I noticed that all the constants we see the exceptions for are marked to be autoloaded in their respective gems. In other words, the common thread in that scenario is that there is an autoload call for each constant we see raise in NameError. Some examples:
ActionView::TemplatePath (view autoload line on GitHub)Formtastic::Helpers::FormHelper (view autoload line on GitHub)InheritedResources::Actions (view autoload line on GitHub)ActiveAdmin::BaseController (view autoload line on GitHub) LoadError is the exception class), I haven't found a pattern. It's a bit all over the place.fxn
commented
1 year ago Oh, so now we get the expected file for the constant definition? Maybe because you ran it locally instead of CI?
I believe it is a step forward that without Bootsnap we get LoadError, because that removes "constants" from the equation and things are reduced to stuff dealing with files. From now on, I'd suggest that we continue debugging always without Bootsnap and without Spring because that leaves us closer to the problem, the results with them enabled don't matter any more and may distract us from the root cause.
Could we do some simple tests? Like, catch some LoadError, print the stacktrace of the exception, and print some sanity checks about the reported file, like File.exist?, listing permissions, or any other metadata that may be interesting to check, or may show that something funky is going on.
maximevaillancourt
commented
1 year ago Oh, so now we get the expected file for the constant definition? Maybe because you ran it locally instead of CI?
Almost certainly because it was locally, yes. Let me retry in CI once I can reproduce an exception.
From now on, I'd suggest that we continue debugging always without Bootsnap and without Spring because that leaves us closer to the problem, the results with them enabled don't matter any more and may distract us from the root cause.
Agreed!
maximevaillancourt
commented
1 year ago Could we do some simple tests? Like, catch some
LoadError, print the stacktrace of the exception, and print some sanity checks about the reported file, likeFile.exist?, listing permissions, or any other metadata that may be interesting to check, or may show that something funky is going on.
Okay, here's a bunch of fun stuff I captured.
Methodology:
BUNDLE_WITHOUT=development:production bundle to install gems (without Spring)DISABLE_BOOTSNAP=1 BUNDLE_WITHOUT=development:production RAILS_ENV=test bundle exec rspec spec/foo.rbI was able to trigger the exceptions in 20% of rspec runs.
Comments incoming...
maximevaillancourt
commented
1 year ago I wrapped the entire contents of spec/rails_helper.rb in a begin/rescue block to catch LoadError exceptions.
LoadError: cannot load such file -- quuxapp/lib/quux.rbapp/lib/quux.rb is not present in $LOADED_FEATURESapp/lib is in $LOAD_PATHGiven the above, why isn't app/lib/quux.rb in $LOADED_FEATURES?
From: [redacted]/spec/rails_helper.rb:67 :
62: end
63: end
64: rescue LoadError, NameError => e
65: puts e
66: puts e.backtrace
=> 67: binding.pry
68: raise
69: end
[11] pry(main)> e
=> #<LoadError: cannot load such file -- quux>
[12] pry(main)> Quux
NameError: uninitialized constant Quux
from (pry):11:in `rescue in <top (required)>'
Caused by LoadError: cannot load such file -- quux
from /opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/zeitwerk-2.6.6/lib/zeitwerk/kernel.rb:38:in `require'
[13] pry(main)> File.exist?("[redacted]/app/lib/quux.rb")
=> true
[14] pry(main)> $LOADED_FEATURES.filter { |p| p.to_s.include?("quux") }
=> []
[15] pry(main)> $LOAD_PATH.filter { |p| p.to_s.include?("app/") }
=> ["[redacted]/app/admin",
"[redacted]/app/components",
"[redacted]/app/constraints",
"[redacted]/app/contracts",
"[redacted]/app/controllers",
"[redacted]/app/controllers/concerns",
"[redacted]/app/emails",
"[redacted]/app/lib",
"[redacted]/app/models",
"[redacted]/app/models/concerns",
"[redacted]/app/policies",
"[redacted]/app/presenters",
"[redacted]/app/queries",
"[redacted]/app/serializers",
"[redacted]/app/services",
"[redacted]/app/subscribers",
"[redacted]/app/validators",
"[redacted]/app/workers",
"/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/turbo-rails-1.3.2/app/channels",
"/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/turbo-rails-1.3.2/app/controllers",
"/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/turbo-rails-1.3.2/app/helpers",
"/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/turbo-rails-1.3.2/app/models",
"/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/turbo-rails-1.3.2/app/models/concerns",
"/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/turbo-rails-1.3.2/app/jobs",
"/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/lookbook-1.5.0/app/components",
"/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/lookbook-1.5.0/app/channels",
"/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/lookbook-1.5.0/app/controllers",
"/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/lookbook-1.5.0/app/controllers/concerns",
"/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/lookbook-1.5.0/app/helpers",
"/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/view_component-2.82.0/app/controllers",
"/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/view_component-2.82.0/app/controllers/concerns",
"/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/view_component-2.82.0/app/helpers",
"/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/inherited_resources-1.13.1/app/controllers",
"/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/activestorage-7.0.4.1/app/controllers",
"/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/activestorage-7.0.4.1/app/controllers/concerns",
"/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/activestorage-7.0.4.1/app/jobs",
"/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/activestorage-7.0.4.1/app/models"]ActiveAdmin showed up a few times as one of the constants that failed to load.
Here's a successful case:
runner@fv-az572-781:~/[redacted]$ DISABLE_BOOTSNAP=1 BUNDLE_WITHOUT=development:production RAILS_ENV=test rspec spec/lib/foo_spec.rb
==== ActiveAdmin ====
60920
["/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/activeadmin-2.13.1/lib/active_admin/helpers/i18n.rb", 2]
nil
Randomized with seed 42217
...
From: [redacted]/spec/rails_helper.rb:61 :
56: config.before { Rails.cache.clear }
57:
58: config.before(:suite) { SlackSubscriber.disable }
59:
60: config.after(:suite) do
=> 61: binding.pry
62: end
63: end
64: rescue LoadError, NameError => e
65: puts e
66: puts e.backtrace
[1] pry(#<RSpec::Core::AnonymousExampleGroup>)> ActiveAdmin.object_id
=> 60920
[2] pry(#<RSpec::Core::AnonymousExampleGroup>)> Object.const_source_location(:ActiveAdmin, false)
=> ["/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/activeadmin-2.13.1/lib/active_admin/helpers/i18n.rb", 2]
[3] pry(#<RSpec::Core::AnonymousExampleGroup>)> Object.autoload?(:ActiveAdmin, false)
=> nilAnd now here's a failure case, again for ActiveAdmin. LoadError: cannot load such file -- active_admin raised... but somehow ActiveAdmin is defined and can be referenced.
Maybe ActiveAdmin was loaded once successfully, but subsequent loads somehow fail?
==== ActiveAdmin, in config/application.rb ====
object_id: 60920
const_source_location: ["/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/activeadmin-2.13.1/lib/active_admin/helpers/i18n.rb", 2]
autoload?: nil
cannot load such file -- active_admin
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/zeitwerk-2.6.6/lib/zeitwerk/kernel.rb:38:in `require'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/zeitwerk-2.6.6/lib/zeitwerk/kernel.rb:38:in `require'
[redacted]/config/initializers/active_admin.rb:3:in `<top (required)>'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/railties-7.0.4.1/lib/rails/engine.rb:667:in `load'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/railties-7.0.4.1/lib/rails/engine.rb:667:in `block in load_config_initializer'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/activesupport-7.0.4.1/lib/active_support/notifications.rb:208:in `instrument'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/railties-7.0.4.1/lib/rails/engine.rb:666:in `load_config_initializer'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/railties-7.0.4.1/lib/rails/engine.rb:620:in `block (2 levels) in <class:Engine>'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/railties-7.0.4.1/lib/rails/engine.rb:619:in `each'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/railties-7.0.4.1/lib/rails/engine.rb:619:in `block in <class:Engine>'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/railties-7.0.4.1/lib/rails/initializable.rb:32:in `instance_exec'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/railties-7.0.4.1/lib/rails/initializable.rb:32:in `run'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/railties-7.0.4.1/lib/rails/initializable.rb:61:in `block in run_initializers'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/3.2.0/tsort.rb:228:in `block in tsort_each'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/3.2.0/tsort.rb:350:in `block (2 levels) in each_strongly_connected_component'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/3.2.0/tsort.rb:422:in `block (2 levels) in each_strongly_connected_component_from'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/3.2.0/tsort.rb:431:in `each_strongly_connected_component_from'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/3.2.0/tsort.rb:421:in `block in each_strongly_connected_component_from'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/railties-7.0.4.1/lib/rails/initializable.rb:50:in `each'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/railties-7.0.4.1/lib/rails/initializable.rb:50:in `tsort_each_child'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/3.2.0/tsort.rb:415:in `call'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/3.2.0/tsort.rb:415:in `each_strongly_connected_component_from'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/3.2.0/tsort.rb:349:in `block in each_strongly_connected_component'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/3.2.0/tsort.rb:347:in `each'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/3.2.0/tsort.rb:347:in `call'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/3.2.0/tsort.rb:347:in `each_strongly_connected_component'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/3.2.0/tsort.rb:226:in `tsort_each'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/3.2.0/tsort.rb:205:in `tsort_each'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/railties-7.0.4.1/lib/rails/initializable.rb:60:in `run_initializers'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/railties-7.0.4.1/lib/rails/application.rb:372:in `initialize!'
[redacted]/config/environment.rb:7:in `<top (required)>'
<internal:/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/3.2.0/rubygems/core_ext/kernel_require.rb>:85:in `require'
<internal:/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/3.2.0/rubygems/core_ext/kernel_require.rb>:85:in `require'
[redacted]/spec/rails_helper.rb:6:in `<top (required)>'
<internal:/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/3.2.0/rubygems/core_ext/kernel_require.rb>:85:in `require'
<internal:/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/3.2.0/rubygems/core_ext/kernel_require.rb>:85:in `require'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/rspec-core-3.12.0/lib/rspec/core/configuration.rb:2117:in `load_file_handling_errors'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/rspec-core-3.12.0/lib/rspec/core/configuration.rb:1576:in `block in requires='
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/rspec-core-3.12.0/lib/rspec/core/configuration.rb:1576:in `each'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/rspec-core-3.12.0/lib/rspec/core/configuration.rb:1576:in `requires='
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/rspec-core-3.12.0/lib/rspec/core/configuration_options.rb:113:in `block in process_options_into'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/rspec-core-3.12.0/lib/rspec/core/configuration_options.rb:112:in `each'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/rspec-core-3.12.0/lib/rspec/core/configuration_options.rb:112:in `process_options_into'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/rspec-core-3.12.0/lib/rspec/core/configuration_options.rb:22:in `configure'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/rspec-core-3.12.0/lib/rspec/core/runner.rb:132:in `configure'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/rspec-core-3.12.0/lib/rspec/core/runner.rb:99:in `setup'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/rspec-core-3.12.0/lib/rspec/core/runner.rb:86:in `run'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/rspec-core-3.12.0/lib/rspec/core/runner.rb:71:in `run'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/rspec-core-3.12.0/lib/rspec/core/runner.rb:45:in `invoke'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/rspec-core-3.12.0/exe/rspec:4:in `<top (required)>'
/opt/hostedtoolcache/Ruby/3.2.0/x64/bin/rspec:25:in `load'
/opt/hostedtoolcache/Ruby/3.2.0/x64/bin/rspec:25:in `<main>'
From: [redacted]/spec/rails_helper.rb:67 :
62: end
63: end
64: rescue LoadError, NameError => e
65: puts e
66: puts e.backtrace
=> 67: binding.pry
68: raise
69: end
[17] pry(main)> e
=> #<LoadError: cannot load such file -- active_admin>
[18] pry(main)> require 'active_admin'
LoadError: cannot load such file -- active_admin
from /opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/zeitwerk-2.6.6/lib/zeitwerk/kernel.rb:38:in `require'
Caused by LoadError: cannot load such file -- active_admin
from /opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/zeitwerk-2.6.6/lib/zeitwerk/kernel.rb:38:in `require'
[19] pry(main)> ActiveAdmin
=> ActiveAdmin
[20] pry(main)> Object.const_source_location(:ActiveAdmin, false)
=> ["/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/activeadmin-2.13.1/lib/active_admin/helpers/i18n.rb", 2]
[21] pry(main)> File.exist?("/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/activeadmin-2.13.1/lib/active_admin/helpers/i18n.rb")
=> true
[22] pry(main)> e
=> #<LoadError: cannot load such file -- active_admin>
[23] pry(main)> ActiveAdmin.object_id
=> 60920
[24] pry(main)> Object.autoload?(:ActiveAdmin, false)
=> nilI also checked the i18n.rb file's permissions: it's readable by all three permission groups.
runner@fv-az572-781:/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/activeadmin-2.13.1/lib/active_admin/helpers$ ls -la
total 28
drwxrwxrwx+ 3 runner docker 4096 Jan 24 20:35 .
drwxrwxrwx+ 14 runner docker 4096 Jan 24 20:35 ..
-rw-r--r--+ 1 runner docker 561 Jan 24 20:35 collection.rb
-rw-r--r--+ 1 runner docker 130 Jan 24 20:35 i18n.rb
-rw-r--r--+ 1 runner docker 1091 Jan 24 20:35 optional_display.rb
drwxrwxrwx+ 2 runner docker 4096 Jan 24 20:35 routes
-rw-r--r--+ 1 runner docker 719 Jan 24 20:35 scope_chain.rbI then started comparing $LOAD_PATH to see if anything was different in successful and failure scenario, and the only differences I could identify (using diff) were the following:
runner@fv-az572-781:~/[redacted]$ diff load-path-failure.txt load-path-success.txt
63a64,65
> /opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/rspec-support-3.12.0/lib
> /opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/rspec-core-3.12.0/lib
225,226d226
< /opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/rspec-core-3.12.0/lib
< /opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/rspec-support-3.12.0/libNot sure if that changes anything... likely a red herring.
maximevaillancourt
commented
1 year ago Last one: I got a weird threading-related exception.
After adding the following to zeitwerk's Kernel#require:
def require(...)
rescue => e
puts e
end... this happened:
runner@fv-az572-781:~/[redacted]$ DISABLE_BOOTSNAP=1 BUNDLE_WITHOUT=development:production RAILS_ENV=test rspec spec/lib/foo_spec.rb
==== ActiveAdmin ====
60920
["/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/activeadmin-2.13.1/lib/active_admin/helpers/i18n.rb", 2]
nil
uninitialized constant SemanticLogger::Log
#<Thread:0x00007f334ee4dfa8 /opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/semantic_logger-4.12.0/lib/semantic_logger/appender/async.rb:77 run> terminated with exception (report_on_exception is true):
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/semantic_logger-4.12.0/lib/semantic_logger/base.rb:329:in `log_internal': uninitialized constant SemanticLogger::Base::Log (NameError)
log = Log.new(name, level, index)
^^^
from /opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/semantic_logger-4.12.0/lib/semantic_logger/base.rb:84:in `trace'
from /opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/semantic_logger-4.12.0/lib/semantic_logger/appender/async.rb:119:in `process'
from /opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/semantic_logger-4.12.0/lib/semantic_logger/appender/async.rb:77:in `block in thread'
uninitialized constant SemanticLogger::Base::Log
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/semantic_logger-4.12.0/lib/semantic_logger/base.rb:329:in `log_internal'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/semantic_logger-4.12.0/lib/semantic_logger/base.rb:84:in `debug'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/sidekiq-6.5.8/lib/sidekiq/redis_connection.rb:146:in `log_info'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/sidekiq-6.5.8/lib/sidekiq/redis_connection.rb:103:in `create'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/sidekiq-6.5.8/lib/sidekiq.rb:205:in `redis='
[redacted]/config/initializers/sidekiq.rb:50:in `block in <top (required)>'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/sidekiq-6.5.8/lib/sidekiq.rb:152:in `configure_client'
[redacted]/config/initializers/sidekiq.rb:49:in `<top (required)>'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/railties-7.0.4.1/lib/rails/engine.rb:667:in `load'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/railties-7.0.4.1/lib/rails/engine.rb:667:in `block in load_config_initializer'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/activesupport-7.0.4.1/lib/active_support/notifications.rb:208:in `instrument'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/railties-7.0.4.1/lib/rails/engine.rb:666:in `load_config_initializer'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/railties-7.0.4.1/lib/rails/engine.rb:620:in `block (2 levels) in <class:Engine>'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/railties-7.0.4.1/lib/rails/engine.rb:619:in `each'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/railties-7.0.4.1/lib/rails/engine.rb:619:in `block in <class:Engine>'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/railties-7.0.4.1/lib/rails/initializable.rb:32:in `instance_exec'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/railties-7.0.4.1/lib/rails/initializable.rb:32:in `run'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/railties-7.0.4.1/lib/rails/initializable.rb:61:in `block in run_initializers'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/3.2.0/tsort.rb:228:in `block in tsort_each'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/3.2.0/tsort.rb:350:in `block (2 levels) in each_strongly_connected_component'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/3.2.0/tsort.rb:422:in `block (2 levels) in each_strongly_connected_component_from'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/3.2.0/tsort.rb:431:in `each_strongly_connected_component_from'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/3.2.0/tsort.rb:421:in `block in each_strongly_connected_component_from'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/railties-7.0.4.1/lib/rails/initializable.rb:50:in `each'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/railties-7.0.4.1/lib/rails/initializable.rb:50:in `tsort_each_child'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/3.2.0/tsort.rb:415:in `call'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/3.2.0/tsort.rb:415:in `each_strongly_connected_component_from'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/3.2.0/tsort.rb:349:in `block in each_strongly_connected_component'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/3.2.0/tsort.rb:347:in `each'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/3.2.0/tsort.rb:347:in `call'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/3.2.0/tsort.rb:347:in `each_strongly_connected_component'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/3.2.0/tsort.rb:226:in `tsort_each'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/3.2.0/tsort.rb:205:in `tsort_each'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/railties-7.0.4.1/lib/rails/initializable.rb:60:in `run_initializers'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/railties-7.0.4.1/lib/rails/application.rb:372:in `initialize!'
[redacted]/config/environment.rb:7:in `<top (required)>'
<internal:/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/3.2.0/rubygems/core_ext/kernel_require.rb>:85:in `require'
<internal:/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/3.2.0/rubygems/core_ext/kernel_require.rb>:85:in `require'
[redacted]/spec/rails_helper.rb:6:in `<top (required)>'
<internal:/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/3.2.0/rubygems/core_ext/kernel_require.rb>:85:in `require'
<internal:/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/3.2.0/rubygems/core_ext/kernel_require.rb>:85:in `require'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/rspec-core-3.12.0/lib/rspec/core/configuration.rb:2117:in `load_file_handling_errors'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/rspec-core-3.12.0/lib/rspec/core/configuration.rb:1576:in `block in requires='
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/rspec-core-3.12.0/lib/rspec/core/configuration.rb:1576:in `each'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/rspec-core-3.12.0/lib/rspec/core/configuration.rb:1576:in `requires='
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/rspec-core-3.12.0/lib/rspec/core/configuration_options.rb:113:in `block in process_options_into'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/rspec-core-3.12.0/lib/rspec/core/configuration_options.rb:112:in `each'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/rspec-core-3.12.0/lib/rspec/core/configuration_options.rb:112:in `process_options_into'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/rspec-core-3.12.0/lib/rspec/core/configuration_options.rb:22:in `configure'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/rspec-core-3.12.0/lib/rspec/core/runner.rb:132:in `configure'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/rspec-core-3.12.0/lib/rspec/core/runner.rb:99:in `setup'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/rspec-core-3.12.0/lib/rspec/core/runner.rb:86:in `run'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/rspec-core-3.12.0/lib/rspec/core/runner.rb:71:in `run'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/rspec-core-3.12.0/lib/rspec/core/runner.rb:45:in `invoke'
/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/rspec-core-3.12.0/exe/rspec:4:in `<top (required)>'
/opt/hostedtoolcache/Ruby/3.2.0/x64/bin/rspec:25:in `load'
/opt/hostedtoolcache/Ruby/3.2.0/x64/bin/rspec:25:in `<main>'
From: [redacted]/spec/rails_helper.rb:67 :
62: end
63: end
64: rescue LoadError, NameError => e
65: puts e
66: puts e.backtrace
=> 67: binding.pry
68: raise
69: end
[1] pry(main)> e
=> #<NameError: uninitialized constant SemanticLogger::Base::Log>
[2] pry(main)> exit
An error occurred while loading rails_helper.
Failure/Error: require File.expand_path("../config/environment", __dir__)
NameError:
uninitialized constant SemanticLogger::Base::Log
# ./config/initializers/sidekiq.rb:50:in `block in <top (required)>'
# ./config/initializers/sidekiq.rb:49:in `<top (required)>'
# ./config/environment.rb:7:in `<top (required)>'
# ./spec/rails_helper.rb:6:in `<top (required)>'
No examples found.rails_semantic_logger is a gem we use in our app, but we don't reference any of these constants directly ourselves.
Thanks for all the help so far, I appreciate it a ton (it's keeping me sane) and I really owe you one 😄
⚠️ Potential fix (Feb 2023) Hello! If you arrived here from a search engine, here's a potential solution: try removing the
semantic_loggergem from your project. More details here.Versions
Problem description
In some of our CI runs (GitHub Actions, Intel x86-64-based workers, Ubuntu 22.04), we're seeing
NameError: uninitialized constant Formtastic::Helpers::FormHelperexceptions when trying to boot our Rails app or running tests. This exception raises very rarely (say, 1 in 20 runs), and I've been unable to reproduce it reliably (either locally or in CI). It smells like a race condition.Example (
config.eager_loadwasfalsein this case, but I've also seen this happening when it wastrue):After many attempts though, I was able to log
$LOADED_FEATURESand noticed thatform_helper.rbis not in this list, however all other sibling helpers are present:I see that
form_helper.rbis marked for autoloading here, so I'm not sure whyform_helper.rbis not in$LOADED_FEATURESlike the other helpers.I also see however that
FormHelperis directly referenced here, so I wonder if that might have something to do withform_helper.rbbeing absent from$LOADED_FEATURES.This problem might be related to or caused by Zeitwerk or Bootsnap. I have a related GitHub issue open in Rails itself to explore the Zeitwerk angle: https://github.com/rails/rails/issues/45600
This old issue seems similar, but I'm not sure if there's anything from this one that we can apply here.
Any thoughts about this one?