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

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.

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

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.

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.

@maximevaillancourt Is the error still happening?

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

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.

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.

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.

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:

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

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.

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

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

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!

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?

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.

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.

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.

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.

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.

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.