Intermittent `NameError: uninitialized constant Formtastic::Helpers::FormHelper`

Question

Intermittent `NameError: uninitialized constant Formtastic::Helpers::FormHelper`

Closed this issue 2 years ago · 72 comments

maximevaillancourt commented 2 years ago

⚠️ Potential fix (Feb 2023)
Hello! If you arrived here from a search engine, here's a potential solution: try removing the semantic_logger gem from your project. More details here.

Versions

Ruby 3.0.2
Rails 7.0.4 (Zeitwerk 2.6.6)
Formtastic 4.0.0
ActiveAdmin 2.13.1
Bootsnap 1.15.0
Bundler 2.4.3

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::FormHelper exceptions 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_load was false in this case, but I've also seen this happening when it was true):

2023-01-19T01:14:49.2901209Z rails aborted!
2023-01-19T01:14:49.2901774Z NameError: uninitialized constant Formtastic::Helpers::FormHelper
2023-01-19T01:14:49.2902781Z [redacted]/vendor/bundle/ruby/3.2.0/gems/formtastic-4.0.0/lib/formtastic/engine.rb:7:in `block (2 levels) in <class:Engine>'
2023-01-19T01:14:49.2903831Z [redacted]/vendor/bundle/ruby/3.2.0/gems/activesupport-7.0.4.1/lib/active_support/lazy_load_hooks.rb:95:in `class_eval'
2023-01-19T01:14:49.2904925Z [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'
2023-01-19T01:14:49.2906004Z [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'
2023-01-19T01:14:49.2907047Z [redacted]/vendor/bundle/ruby/3.2.0/gems/activesupport-7.0.4.1/lib/active_support/lazy_load_hooks.rb:90:in `execute_hook'
2023-01-19T01:14:49.2908112Z [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'
2023-01-19T01:14:49.2909119Z [redacted]/vendor/bundle/ruby/3.2.0/gems/activesupport-7.0.4.1/lib/active_support/lazy_load_hooks.rb:59:in `each'
2023-01-19T01:14:49.2910121Z [redacted]/vendor/bundle/ruby/3.2.0/gems/activesupport-7.0.4.1/lib/active_support/lazy_load_hooks.rb:59:in `on_load'
2023-01-19T01:14:49.2911123Z [redacted]/vendor/bundle/ruby/3.2.0/gems/formtastic-4.0.0/lib/formtastic/engine.rb:6:in `block in <class:Engine>'
2023-01-19T01:14:49.2912084Z [redacted]/vendor/bundle/ruby/3.2.0/gems/railties-7.0.4.1/lib/rails/initializable.rb:32:in `instance_exec'
2023-01-19T01:14:49.2913006Z [redacted]/vendor/bundle/ruby/3.2.0/gems/railties-7.0.4.1/lib/rails/initializable.rb:32:in `run'
2023-01-19T01:14:49.2914001Z [redacted]/vendor/bundle/ruby/3.2.0/gems/railties-7.0.4.1/lib/rails/initializable.rb:61:in `block in run_initializers'
2023-01-19T01:14:49.2914710Z /opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/3.2.0/tsort.rb:228:in `block in tsort_each'
2023-01-19T01:14:49.2915449Z /opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/3.2.0/tsort.rb:350:in `block (2 levels) in each_strongly_connected_component'
2023-01-19T01:14:49.2916376Z /opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/3.2.0/tsort.rb:431:in `each_strongly_connected_component_from'
2023-01-19T01:14:49.2917103Z /opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/3.2.0/tsort.rb:349:in `block in each_strongly_connected_component'
2023-01-19T01:14:49.2917717Z /opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/3.2.0/tsort.rb:347:in `each'
2023-01-19T01:14:49.2918300Z /opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/3.2.0/tsort.rb:347:in `call'
2023-01-19T01:14:49.2918950Z /opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/3.2.0/tsort.rb:347:in `each_strongly_connected_component'
2023-01-19T01:14:49.2919575Z /opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/3.2.0/tsort.rb:226:in `tsort_each'
2023-01-19T01:14:49.2920173Z /opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/3.2.0/tsort.rb:205:in `tsort_each'
2023-01-19T01:14:49.2921081Z [redacted]/vendor/bundle/ruby/3.2.0/gems/railties-7.0.4.1/lib/rails/initializable.rb:60:in `run_initializers'
2023-01-19T01:14:49.2922036Z [redacted]/vendor/bundle/ruby/3.2.0/gems/railties-7.0.4.1/lib/rails/application.rb:372:in `initialize!'
2023-01-19T01:14:49.2922765Z [redacted]/config/environment.rb:7:in `<main>'
2023-01-19T01:14:49.2923982Z [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'
2023-01-19T01:14:49.2925046Z [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'
2023-01-19T01:14:49.2925985Z [redacted]/vendor/bundle/ruby/3.2.0/gems/zeitwerk-2.6.6/lib/zeitwerk/kernel.rb:38:in `require'
2023-01-19T01:14:49.2926932Z [redacted]/vendor/bundle/ruby/3.2.0/gems/railties-7.0.4.1/lib/rails/application.rb:348:in `require_environment!'
2023-01-19T01:14:49.2927933Z [redacted]/vendor/bundle/ruby/3.2.0/gems/railties-7.0.4.1/lib/rails/application.rb:511:in `block in run_tasks_blocks'
2023-01-19T01:14:49.2928881Z [redacted]/vendor/bundle/ruby/3.2.0/gems/rake-13.0.6/lib/rake/task.rb:281:in `block in execute'
2023-01-19T01:14:49.2929709Z [redacted]/vendor/bundle/ruby/3.2.0/gems/rake-13.0.6/lib/rake/task.rb:281:in `each'
2023-01-19T01:14:49.2930532Z [redacted]/vendor/bundle/ruby/3.2.0/gems/rake-13.0.6/lib/rake/task.rb:281:in `execute'
2023-01-19T01:14:49.2931446Z [redacted]/vendor/bundle/ruby/3.2.0/gems/rake-13.0.6/lib/rake/task.rb:219:in `block in invoke_with_call_chain'
2023-01-19T01:14:49.2932331Z [redacted]/vendor/bundle/ruby/3.2.0/gems/rake-13.0.6/lib/rake/task.rb:199:in `synchronize'
2023-01-19T01:14:49.2933221Z [redacted]/vendor/bundle/ruby/3.2.0/gems/rake-13.0.6/lib/rake/task.rb:199:in `invoke_with_call_chain'
2023-01-19T01:14:49.2934067Z [redacted]/vendor/bundle/ruby/3.2.0/gems/rake-13.0.6/lib/rake/task.rb:188:in `invoke'
2023-01-19T01:14:49.2935066Z [redacted]/vendor/bundle/ruby/3.2.0/gems/sprockets-rails-3.4.2/lib/sprockets/rails/task.rb:61:in `block (2 levels) in define'
2023-01-19T01:14:49.2935994Z [redacted]/vendor/bundle/ruby/3.2.0/gems/rake-13.0.6/lib/rake/task.rb:281:in `block in execute'
2023-01-19T01:14:49.2936817Z [redacted]/vendor/bundle/ruby/3.2.0/gems/rake-13.0.6/lib/rake/task.rb:281:in `each'
2023-01-19T01:14:49.2937654Z [redacted]/vendor/bundle/ruby/3.2.0/gems/rake-13.0.6/lib/rake/task.rb:281:in `execute'
2023-01-19T01:14:49.2938565Z [redacted]/vendor/bundle/ruby/3.2.0/gems/rake-13.0.6/lib/rake/task.rb:219:in `block in invoke_with_call_chain'
2023-01-19T01:14:49.2939429Z [redacted]/vendor/bundle/ruby/3.2.0/gems/rake-13.0.6/lib/rake/task.rb:199:in `synchronize'
2023-01-19T01:14:49.2940329Z [redacted]/vendor/bundle/ruby/3.2.0/gems/rake-13.0.6/lib/rake/task.rb:199:in `invoke_with_call_chain'
2023-01-19T01:14:49.2941389Z [redacted]/vendor/bundle/ruby/3.2.0/gems/rake-13.0.6/lib/rake/task.rb:243:in `block in invoke_prerequisites'
2023-01-19T01:14:49.2942238Z [redacted]/vendor/bundle/ruby/3.2.0/gems/rake-13.0.6/lib/rake/task.rb:241:in `each'
2023-01-19T01:14:49.2943130Z [redacted]/vendor/bundle/ruby/3.2.0/gems/rake-13.0.6/lib/rake/task.rb:241:in `invoke_prerequisites'
2023-01-19T01:14:49.2944070Z [redacted]/vendor/bundle/ruby/3.2.0/gems/rake-13.0.6/lib/rake/task.rb:218:in `block in invoke_with_call_chain'
2023-01-19T01:14:49.2944946Z [redacted]/vendor/bundle/ruby/3.2.0/gems/rake-13.0.6/lib/rake/task.rb:199:in `synchronize'
2023-01-19T01:14:49.2945847Z [redacted]/vendor/bundle/ruby/3.2.0/gems/rake-13.0.6/lib/rake/task.rb:199:in `invoke_with_call_chain'
2023-01-19T01:14:49.2946689Z [redacted]/vendor/bundle/ruby/3.2.0/gems/rake-13.0.6/lib/rake/task.rb:188:in `invoke'
2023-01-19T01:14:49.2947644Z [redacted]/vendor/bundle/ruby/3.2.0/gems/rake-13.0.6/lib/rake/application.rb:160:in `invoke_task'
2023-01-19T01:14:49.2948626Z [redacted]/vendor/bundle/ruby/3.2.0/gems/rake-13.0.6/lib/rake/application.rb:116:in `block (2 levels) in top_level'
2023-01-19T01:14:49.2949515Z [redacted]/vendor/bundle/ruby/3.2.0/gems/rake-13.0.6/lib/rake/application.rb:116:in `each'
2023-01-19T01:14:49.2950432Z [redacted]/vendor/bundle/ruby/3.2.0/gems/rake-13.0.6/lib/rake/application.rb:116:in `block in top_level'
2023-01-19T01:14:49.2951375Z [redacted]/vendor/bundle/ruby/3.2.0/gems/rake-13.0.6/lib/rake/application.rb:125:in `run_with_threads'
2023-01-19T01:14:49.2952261Z [redacted]/vendor/bundle/ruby/3.2.0/gems/rake-13.0.6/lib/rake/application.rb:110:in `top_level'
2023-01-19T01:14:49.2953348Z [redacted]/vendor/bundle/ruby/3.2.0/gems/railties-7.0.4.1/lib/rails/commands/rake/rake_command.rb:24:in `block (2 levels) in perform'
2023-01-19T01:14:49.2954376Z [redacted]/vendor/bundle/ruby/3.2.0/gems/rake-13.0.6/lib/rake/application.rb:186:in `standard_exception_handling'
2023-01-19T01:14:49.2955397Z [redacted]/vendor/bundle/ruby/3.2.0/gems/railties-7.0.4.1/lib/rails/commands/rake/rake_command.rb:24:in `block in perform'
2023-01-19T01:14:49.2956343Z [redacted]/vendor/bundle/ruby/3.2.0/gems/rake-13.0.6/lib/rake/rake_module.rb:59:in `with_application'
2023-01-19T01:14:49.2957318Z [redacted]/vendor/bundle/ruby/3.2.0/gems/railties-7.0.4.1/lib/rails/commands/rake/rake_command.rb:18:in `perform'
2023-01-19T01:14:49.2958225Z [redacted]/vendor/bundle/ruby/3.2.0/gems/railties-7.0.4.1/lib/rails/command.rb:51:in `invoke'
2023-01-19T01:14:49.2959096Z [redacted]/vendor/bundle/ruby/3.2.0/gems/railties-7.0.4.1/lib/rails/commands.rb:18:in `<main>'
2023-01-19T01:14:49.2960126Z [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'
2023-01-19T01:14:49.2961169Z [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'
2023-01-19T01:14:49.2961677Z bin/rails:9:in `<main>'
2023-01-19T01:14:49.2962032Z Tasks: TOP => environment

After many attempts though, I was able to log $LOADED_FEATURES and noticed that form_helper.rb is not in this list, however all other sibling helpers are present:

I see that form_helper.rb is marked for autoloading here, so I'm not sure why form_helper.rb is not in $LOADED_FEATURES like the other helpers.

I also see however that FormHelper is directly referenced here, so I wonder if that might have something to do with form_helper.rb being 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: rails/rails#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?

Answer 1 · 2023-01-19T05:12:44.000Z

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.

Answer 2 · 2023-01-19T10:17:50.000Z

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.

Answer 3 · 2023-01-19T10:34:54.000Z

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
end

This 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)
end

And 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.

Answer 4 · 2023-01-19T14:24:33.000Z

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:

Whenever 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?
The constants/features I've seen fail to load intermittently are all marked to be 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: ViewComponent/view_component#1471 (review)

Again, thank you for your help so far, I appreciate it a ton!

Answer 5 · 2023-01-19T14:40:31.000Z

@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).

Answer 6 · 2023-01-19T14:41:59.000Z

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!

Answer 7 · 2023-01-19T15:43:41.000Z

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?

Answer 8 · 2023-01-19T16:25:57.000Z

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.

Answer 9 · 2023-01-19T16:30:27.000Z

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.

Answer 10 · 2023-01-19T17:02:11.000Z

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.

Answer 11 · 2023-01-19T20:18:47.000Z

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?

Answer 12 · 2023-01-20T13:27:41.000Z

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
end

Important 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.

Answer 13 · 2023-01-20T14:00:59.000Z

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.

Answer 14 · 2023-01-20T16:10:22.000Z

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): 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 🤔

Answer 15 · 2023-01-21T01:39:56.000Z

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
end

I haven't been able to find a way to reliably reproduce NameError: uninitialized constant Formtastic::Helpers::FormHelper yet.

Answer 16 · 2023-01-21T08:14:18.000Z

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?

Answer 17 · 2023-01-21T10:19:26.000Z

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.

Answer 18 · 2023-01-21T14:02:30.000Z

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!

Answer 19 · 2023-01-21T14:39:37.000Z

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!

Answer 20 · 2023-01-21T22:13:11.000Z

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 :).

Answer 21 · 2023-01-22T13:47:23.000Z

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!

Answer 22 · 2023-01-22T13:53:15.000Z

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.

Answer 23 · 2023-01-22T15:17:24.000Z

(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
  ...
end

Our 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.

Answer 24 · 2023-01-22T15:44:17.000Z

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::CreateOne
ActionView::TemplatePath
InheritedResources::Actions
RailsSemanticLogger::ActionView::LogSubscriber
RailsSemanticLogger::ActiveJob::LogSubscriber
RailsSemanticLogger::ActiveRecord::LogSubscriber
ViewComponent::Compiler
ViewComponent::TestHelpers

Answer 25 · 2023-01-22T16:01:19.000Z

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.

Answer 26 · 2023-01-22T23:34:21.000Z

OK, here's my summary of the things that I find puzzling:

We cannot reproduce consistently

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.

The state of the constants in `Formtastic::Helpers`

We 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:

If FormHelper gets defined and nothing is raised, the symbol :FormHelper remains in constants, and autoload? returns nil.
If 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).
If 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/form_helper.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/form_helper.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.

Formtastic is defined in lib/formtastic/helpers.rb

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/active_admin.rb. The constant Formtastic is more than defined when you reach line 129.

The End for Today

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 :).

Answer 27 · 2023-01-23T00:56:08.000Z

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.

Answer 28 · 2023-01-23T00:58:52.000Z

@maximevaillancourt does your application run under Spring?

Answer 29 · 2023-01-23T01:32:17.000Z

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/form_helper.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.

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.

Answer 30 · 2023-01-23T07:57:29.000Z

OK, we got a new puzzling data point: The exception is not raised in the middle of the evaluation of lib/formtastic/helpers/form_helper.rb, it is evaluated on line 54 of your patched Formtastic which is (indentation removed):

module FormHelper

this 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
end

and this c.rb:

puts "AUTOLOADED!"
module M
  class C
  end
end

you'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.

Answer 31 · 2023-01-23T08:05:30.000Z

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.

Answer 32 · 2023-01-23T10:47:56.000Z

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).

Answer 33 · 2023-01-23T17:22:14.000Z

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.

Answer 34 · 2023-01-23T17:30:59.000Z

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.

Answer 35 · 2023-01-23T21:58:44.000Z

Could there be something funky related to the file system in CI?

Answer 36 · 2023-01-23T22:04:20.000Z

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:

Multiple Ruby versions: maybe there are multiple Ruby versions installed in the CI workers, and with the GitHub Actions caches, it could be that the gems are installed on one version, while the code uses another version, leading to those weird issues.
File permission issues: LoadError may raise when a file can't be read by the CI runner user (say because it doesn't have the read permission)

Answer 37 · 2023-01-23T22:45:32.000Z

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).

Answer 38 · 2023-01-23T22:53:15.000Z

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? 🤔

Answer 39 · 2023-01-23T23:11:41.000Z

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.

Answer 40 · 2023-01-23T23:58:29.000Z

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.

Answer 41 · 2023-01-24T01:27:08.000Z

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 ✅

Answer 42 · 2023-01-24T16:27:10.000Z

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?

Answer 43 · 2023-01-24T16:45:37.000Z

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:

When Bootsnap is enabled (thus 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)
When Bootsnap is disabled (thus LoadError is the exception class), I haven't found a pattern. It's a bit all over the place.

Answer 44 · 2023-01-24T19:13:29.000Z

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.

Answer 45 · 2023-01-24T23:12:55.000Z

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!

Answer 46 · 2023-01-24T23:13:59.000Z

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.

Okay, here's a bunch of fun stuff I captured.

Methodology:

SSH into a GitHub Actions CI runner
Run BUNDLE_WITHOUT=development:production bundle to install gems (without Spring)
Run DISABLE_BOOTSNAP=1 BUNDLE_WITHOUT=development:production RAILS_ENV=test bundle exec rspec spec/foo.rb

I was able to trigger the exceptions in 20% of rspec runs.

Comments incoming...

Answer 47 · 2023-01-24T23:15:50.000Z

I wrapped the entire contents of spec/rails_helper.rb in a begin/rescue block to catch LoadError exceptions.

The exception is LoadError: cannot load such file -- quux
Quux lives at app/lib/quux.rb
Somehow, app/lib/quux.rb is not present in $LOADED_FEATURES
app/lib is in $LOAD_PATH

Given 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"]

Answer 48 · 2023-01-24T23:19:10.000Z

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)
=> nil

And 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)
=> nil

I 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.rb

Answer 49 · 2023-01-24T23:20:27.000Z

I 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/lib

Not sure if that changes anything... likely a red herring.

Answer 50 · 2023-01-24T23:24:08.000Z

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 😄

Answer 51 · 2023-01-24T23:25:06.000Z

$LOADED_FEATURES is the collection of files that have been required. Since the file cannot be loaded, it does not end up in that collection.

There is something strange in your quux example. The directory app/lib is in the autoload paths of the Rails application and it is managed by the Rails main autoloader. Now, Zeitwerk exclusively sets absolute paths, there is no way you get a require for quux in an autoloaded Quux unless that require is manual or coming from some decoration that manipulates the argument.

Answer 52 · 2023-01-24T23:29:08.000Z

Hey, something I observe is that the executed command is rspec. Should be bundle exec rspec.

Answer 53 · 2023-01-24T23:31:32.000Z

$LOADED_FEATURES is the collection of files that have been required. Since the file cannot be loaded, it does not end up in that collection.

Ah, right, that makes sense. Seems obvious now written like that 🙈

unless that require is manual

It is a manual require indeed: we tried adding it to reduce the number of NameError / LoadError exceptions, but the result is the same with or without the manual require calls. Same with active_admin.

Should be bundle exec rspec.

We normally use bundle exec rspec, but figured I'd use rspec to eliminate bundler-related noise from the stack traces. The same intermittent exceptions happen either way.

Answer 54 · 2023-01-24T23:38:40.000Z

OK!

What is config/initializers/active_admin.rb:3?

Thanks for all the help so far, I appreciate it a ton (it's keeping me sane) and I really owe you one 😄

This is being super fun man, hope we meet some day and can celebrate our inexorable victory with a scotch or something :D.

Answer 55 · 2023-01-24T23:55:06.000Z

Another question, could you repeat that Pry session for Active Admin, reproduce the LoadError, and print

$LOAD_PATH.grep(/activeadmin/)

after it?

Answer 56 · 2023-01-25T00:14:39.000Z

Exact same output in both successful runs and failing runs:

[
  "/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/activeadmin-2.13.1/lib", 
  "/opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/activeadmin-2.13.1/vendor"
]

Answer 57 · 2023-01-25T07:55:51.000Z

I feel like we are getting closer.

When you get a LoadError during initialization in a vanilla Rails 7 application, lib/zeitwerk/kernel.rb:38 appears once, but in those stack traces for active_admin I see it twice:
```
lib/zeitwerk/kernel.rb:38:in `require'
lib/zeitwerk/kernel.rb:38:in `require'
```
If you issue require 'active_admin', you get a LoadError. That means, that (A) /opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/activeadmin-2.13.1/lib/active_admin.rb is not in $LOADED_FEATURES (otherwise we'd get false without checking the file system), and (B) Ruby is not able to find it, despite the directory being in $LOAD_PATH, as demonstrated in the last comment. This does not square.

Could you please add

p Kernel.method(:zeitwerk_original_require).source_location

before line 3 of config/initializers/active_admin.rb and boot? I suppose we'll see the output and then LoadError if that one on the original line 3 is consistent.

Answer 58 · 2023-01-25T08:29:08.000Z

Oh, I guess (1) is just how things are fomatted.

My current intuition is that there is a require logic somewhere that is not working as expected.

Answer 59 · 2023-01-25T08:37:39.000Z

To remove yet another variable, I'd suggest that we work with bundle exec always, because Bundler resets Kernel#require to whatever gem_original_require was, thus erasing any possible decoration that happened in between.

Since require is in our radar, let's do things the way they are supposed to be so that we are truly reproducing what CI does.

Answer 60 · 2023-01-25T13:41:57.000Z

Could you please add
p Kernel.method(:zeitwerk_original_require).source_location
before line 3 of config/initializers/active_admin.rb and boot? I suppose we'll see the output and then LoadError if that one on the original line 3 is consistent.

This prints nil in both successful and failure cases 🤔

runner@fv-az189-941:~/[redacted]$ DISABLE_BOOTSNAP=1 BUNDLE_WITHOUT=development:production RAILS_ENV=test bundle exec rspec spec/lib/foo_spec.rb 
nil

Randomized with seed 20659
......................................................................................................................

Finished in 0.5765 seconds (files took 9.87 seconds to load)
118 examples, 0 failures

Randomized with seed 20659

runner@fv-az189-941:~/[redacted]$ DISABLE_BOOTSNAP=1 BUNDLE_WITHOUT=development:production RAILS_ENV=test bundle exec rspec spec/lib/foo_spec.rb 
nil

An error occurred while loading rails_helper.
Failure/Error: require File.expand_path("../config/environment", __dir__)

LoadError:
  cannot load such file -- active_admin
# ./config/initializers/active_admin.rb:4:in `<top (required)>'
# ./config/environment.rb:7:in `<top (required)>'
# ./spec/rails_helper.rb:5:in `require'
# ./spec/rails_helper.rb:5:in `<top (required)>'
No examples found.


Finished in 0.00007 seconds (files took 6.11 seconds to load)
0 examples, 0 failures, 1 error occurred outside of examples

Oh, I guess (1) is just how things are fomatted.

I'm not sure it's just formatting, you may be onto something here

Answer 61 · 2023-01-25T14:53:44.000Z

This prints nil in both successful and failure cases

OK, this is the normal output, it means it is a method written in C.

Answer 62 · 2023-01-25T15:24:48.000Z

Could it be some kind of weird interaction between Ruby's Kernel#require when it tries to override rubygems' own Kernel#require? (see this)

Answer 63 · 2023-01-25T15:32:31.000Z

Could be, anything touching require is suspicious now. In the case of Zeitwerk, the wrapper cannot be more thin, it is calling the original method (line 38) and nothing else. There it raises, there is not a lot more to it.

This decoration is more elaborate and Bundler also does stuff, as we saw. However, these two run in virtually all modern Ruby projects routinely, and what your app is experiencing is exceptional.

So, I believe it is something with require, but we need to find what.

One possible direction would be to focus on what is special in the CI environment, since in development you cannot reproduce (except for that isolated case), and I suppose this application is in production just fine?

Answer 64 · 2023-01-25T16:17:35.000Z

what your app is experiencing is exceptional

Agreed, though we're not alone: rails/rails#45600 from another person points to the exact same symptoms (with a constant we're also seeing from time to time: ActiveStorage::Attached), so it's possible that we both have similar, yet uncommon, environments, leading to the same symptoms. I suppose there's some kind of interaction between host OS, installed gems, $PATH/$LOAD_PATH, and other environmental characteristics that make NameError/LoadError show up intermittently.

I suppose this application is in production just fine?

Correct, only happens in CI (except that one time in development).

Answer 65 · 2023-01-26T07:26:54.000Z

Agreed, though we're not alone: rails/rails#45600 from another person points to the exact same symptoms (with a constant we're also seeing from time to time: ActiveStorage::Attached), so it's possible that we both have similar, yet uncommon, environments, leading to the same symptoms. I suppose there's some kind of interaction between host OS, installed gems, $PATH/$LOAD_PATH, and other environmental characteristics that make NameError/LoadError show up intermittently.

Agreed.

Now, we have it quite cornered I believe, but still elusive! Let's try something to see if it sheds any lights (or shadows :)).

In config/application.rb, after Bundle.require and before the application class is defined, let's throw this:

module Kernel
  prepend Module.new {
    def require(...)
      if super(...)
        pp $LOADED_FEATURES.last
      end
    end
  }
end

I guess that is going to print a series of successfully required files, until we hit active_admin. Goal would be to see if there is anything different between what was successfully loaded and that particular file.

Answer 66 · 2023-01-26T14:12:33.000Z

I think we found it! I must say, this was an excellent snippet suggestion.

I took the liberty of tweaking the snippet a little bit to print a counter ($COUNT, incremented on each Kernel#require call) and Thread.current.object_id in addition to $LOADED_FEATURES.last:

# config/application.rb
...
Bundler.require(*Rails.groups)
...
$COUNT = 0
module Kernel
  prepend Module.new {
    def require(...)
      if super(...)
        puts "#{$COUNT}\t#{Thread.current.object_id}\t#{$LOADED_FEATURES.last}"
        $COUNT += 1
      end
    end
  }
end

module MyRailsApp
  class Application < Rails::Application
...

Here's what I found:

...
21      11440   /opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/semantic_logger-4.12.0/lib/semantic_logger/formatters/base.rb                                                                           
22      11440   /opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/semantic_logger-4.12.0/lib/semantic_logger/formatters/default.rb                                                                        
23      11440   /opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/semantic_logger-4.12.0/lib/semantic_logger/formatters/color.rb                                                                          
24      11440   /opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/semantic_logger-4.12.0/lib/semantic_logger/ansi_colors.rb                                                                               
25      11440   /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                                                                            
26      11440   /opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/semantic_logger-4.12.0/lib/semantic_logger/processor.rb                                     
27      11440   /opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/semantic_logger-4.12.0/lib/semantic_logger/appenders.rb                                        
28      11440   /opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/semantic_logger-4.12.0/lib/semantic_logger/loggable.rb                                        
29      71040   /opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/semantic_logger-4.12.0/lib/semantic_logger/log.rb                                        
30      11440   /opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/activesupport-7.0.4.1/lib/active_support/executor/test_helper.rb                           
31      11440   /opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/actionpack-7.0.4.1/lib/action_dispatch/request/utils.rb                               
32      11440   /opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/actionpack-7.0.4.1/lib/action_dispatch/middleware/exception_wrapper.rb                                                                  
33      11440   /opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/actionpack-7.0.4.1/lib/abstract_controller/helpers.rb                                 
34      11440   /opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/actionpack-7.0.4.1/lib/action_controller/metal/helpers.rb                                                                               
35      11440   /opt/hostedtoolcache/Ruby/3.2.0/x64/lib/ruby/gems/3.2.0/gems/railties-7.0.4.1/lib/rails/backtrace_cleaner.rb  
...

Notice how the 29th require call is done by another thread from within the semantic_logger gem. This ties into to this finding.

I tried removing the gem (and whatever calls associated to it in our app)... and I wasn't able to reproduce the bug anymore. 🤞

I've been suspecting a multi-threading-related root cause since the beginning because of the intermittent nature of the bug. Let me try some more to confirm, but I think a pull request is in order in https://github.com/reidmorrison/semantic_logger.

Answer 67 · 2023-01-26T14:25:33.000Z

Cool!

Off the top of my head, I can't see why multi-threading should prevent require from finding active_admin, but if you cannot reproduce with that gem out, we are even closer!!!

Answer 68 · 2023-01-27T17:44:36.000Z

Not sure if it's related at all, but after reading this and looking at semantic logger, there's reidmorrison/semantic_logger#261 and reidmorrison/semantic_logger#240

I'm not sure if it's related. I can't find a reproduction for the missing constant we experience in rails/rails#45600 in such a way to ever get the logging that maximevaillancourt is getting. The missing constant is very rare for us. But we are seeing it on Ubuntu and Amazon Linux sometimes. And we do use the semantic_logger gems mentioned here.

Answer 69 · 2023-01-30T12:37:07.000Z

@thekendalmiller When it happens in your app, does it happen while it is booting as well?

Answer 70 · 2023-01-30T14:08:04.000Z

@fxn yes - I've seen it when starting rails console and on CI test runs

Answer 71 · 2023-02-16T07:51:38.000Z

@maximevaillancourt Is the error still happening?

(Got the card, that was so classy and special, please thank all the team on my behalf ❤️.)

Answer 72 · 2023-02-16T14:04:37.000Z

Is the error still happening?

It hasn't happened a single time since removing the rails_semantic_logger gem. However, still no activity on reidmorrison/semantic_logger#263 at this point.

I'll close this issue as there's no further action item to do specific to Formtastic.

(Got the card, that was so classy and special, please thank all the team on my behalf ❤️.)

I'm personally very grateful for your help as it kept me sane throughout the investigation, and my colleagues were also happy to see our CI pipeline become healthy pretty much overnight. Massive thank you once again! 🙏

We cannot reproduce consistently

The state of the constants in Formtastic::Helpers

Formtastic is defined in lib/formtastic/helpers.rb

The End for Today

The state of the constants in `Formtastic::Helpers`