Zeitwerk not loading application_controller after a change in child controller.

[obromios]

Steps to reproduce

Upgrade from 5.2 to rails 6.0.2. Have app working with all the new_frame_work_defaults removed. This issue was first raised as a SO question, but there have been no answers.

Expected behavior

After making a change to controller and reloading a page belonging to that controller, it is expected that the web page should reload.

Actual behavior

In my application controller I define a filter called set_locale which I use in a number of child controllers. For example;

  # app/controllers/application_controller
  class ApplicationController < ActionController::Base
    
    def set_locale
      ...
    end
  end

Then in another controller I have

# app/controllers/clubs_controller
class ClubsController < ApplicationController
  before_action :set_locale

end

This arrangement works in rails 5, and works in rails 6 in the test and production environments. In development mode, the code works until I make a change to the code in the clubs_controller. When I reload the page, I see the following exception:

NoMethodError - undefined method `set_locale' for #<ClubsController:0x00007fd9ed227ad0>
Did you mean?  set_club_cookie:

If I add Rails.autoloaders.log! to config/application.rb, then when I start up the server, I see the following two entries

Zeitwerk@rails.main: autoload set for ApplicationController, to be loaded from /Users/Chris/Sites/some_app/app/controllers/application_controller.rb

and then

Zeitwerk@rails.main: constant ApplicationController loaded from file /Users/Chris/Sites/some_app/app/controllers/application_controller.rb
Started GET "/clubs/index"

as expected. But when I make a change and reload the page, I see

Zeitwerk@rails.main: ApplicationController unloaded

then later

Zeitwerk@rails.main: autoload set for ApplicationController, to be loaded from /Users/Chris/Sites/some_app/app/controllers/application_controller.rb

which looks hopeful, but then finally

    Zeitwerk@rails.main: constant ClubsController loaded from file /Users/Chris/Sites/some_app/app/controllers/clubs_controller.rb
    Processing by ClubsController#carry_distances as HTML
Related errors to 'undefined method `set_locale' for

i.e no sign of the ApplicationController being reloaded.

If I restart the server, then it runs properly again.

If I remove config.load_defaults '6.0' from my application.rb then everything works fine, but I am not seeing any output from autoloaders.log, so Zeitwerk is being disabled. This is a bit puzzling, if Zeitwerk is the default loader in Rails 6, why do I need to use config.load_defaults 6.0?

System configuration

Rails version: 6.0.2

Ruby version: 2.6.5

[fxn]

I created a new app with a filter like that and does not present this behavior, do you have a way to reproduce that you can share?

Linking this to #38365, I suspect your project has something suspicious that manifests in reloading, but I'd bet the autoloader is not the root cause, since the problems reported happen in extremely common use cases.

[fxn]

Could you please put

puts caller

in line 1 of app/controllers/application_controller.rb, trigger the error, and share the entire stdout of the whole session, including those caller traces and also Zeitwerk's?

[obromios]

Please find attached file as requested. Note that after puts caller, I added puts 'just called caller' to make it easier to find where it occurs.
temp_caller.txt

[fxn]

Is that the entire log? The first occurrence of "ApplicationController" is

Zeitwerk@rails.main: ApplicationController unloaded

but the log does not show it was autoloaded before, nor does it show a caller output.

[obromios]

I have done another trace, this time includes starting the server and the first successful page load, followed by a change to the child controller and then a reload. I cleared the terminal window at the start and then copied all into this file. The first three lines of app/controllers/application_controller.rb are

puts caller
puts 'just called caller'
class ApplicationController < ActionController::Base

temp_caller_full.txt

[obromios]

I also noticed in the development.log the following deprecation warning

DEPRECATION WARNING: Initialization autoloaded the constants ActionText::ContentHelper and ActionText::TagHelper.

Being able to do this is deprecated. Autoloading during initialization is going
to be an error condition in future versions of Rails.

Reloading does not reboot the application, and therefore code executed during
initialization does not run again. So, if you reload ActionText::ContentHelper, for example,
the expected changes won't be reflected in that stale Module object.

These autoloaded constants have been unloaded.

Please, check the "Autoloading and Reloading Constants" guide for solutions.
 (called from <top (required)> at /Users/Chris/Sites/golf_mentor/config/environment.rb:5)

[fxn]

Let's follow that hint. That means the application is autoloading constants during initialization. Could you revise config/initializers and see if you can spot anything relevant?

[obromios]

I found some constants in one of my initializers and commented them out, restarted server, but this did not fix the issue. However, the deprecation warning is still there. There is an issue concerning the deprecation warning.

[wlipa]

I experienced this and traced it down to a long-stale gem using bisection on the Gemfile.

[obromios]

Interesting. Do you happen to remember the name of the culprit gem? And just to be clear, are you referring to the problem that the ApplicationController is not being reloaded or the deprecation warning.

[wlipa]

In my case it was http_status_exceptions.

[wlipa]

I'm referring to the deprecation warning.

[obromios]

I will work on removing the deprecation warning and then see if that fixes the loading of the ApplicationController. I am travelling so may take a few weeks.

[obromios]

I have eliminated the deprecation warning by removing stack_rescue from the development section of the Gemfile. I am still seeing the same problem. Please find attached a copy of the server out output. My application_controller starts as follows:

puts 'TGM - Calling caller'
puts caller
class ApplicationController < ActionController::Base

The sequence of events traced in the attached file are

1. start server
2. load web clubs_controller#club_distances page using Chrome browser
3. Make an irrelevant change to the clubs_controller and save it.

4. reload the clubs_controller#club_distances page

temp_zeit1.txt

[fxn]

Hey, back to this one.

First, let me say that class hierarchies are routinely reloaded. I bet there is something in that ApplicationController class definition that prevents the file from being fully loaded the second time. Let me explain why I think that is the case.

The line numbers of the relevant traces in the log file you attached are:

Class	autoload	load	unload	autoload	load
ApplicationController	9	377	749	768	?
ClubsController	10	380	750	769	1078

Autoloads are set, files are loaded, then unloaded, then new autoloads are defined, and we see one reload. But we are missing a trace for the second load of ApplicationController, that is a point.

The key observations are the following:

1. app/controllers/application_controller.rb is loaded on reload. Your "TGM" trace demonstrates that without doubt.
2. The file evaluation manages to define the class ApplicationController, because otherwise ClubsController would raise NameError, since the superclass has to be present for the class body evaluation to happen. The class ApplicationController has been reloaded for sure.
3. However, we get a NoMethodError. That means the evaluation of that file does not reach the line in which set_locale is defined. It aborts before, and, misteriously, in a silent way.

Let me recall, just in case, that in Ruby a partial class definition is OK with the semantics of the language. Let's consider this example,

begin
  class C
    raise
    def foo; end
  end
rescue
end

p C

That runs without problem. It defines a class C that you can inspect. However, C does not have a foo instance method because interpretation of the class body has halted before. I am confident that is what is happenning to your ApplicationController.

Could you please verify my conclusions and see if you can understand why the evaluation is partial? Once the exact source of the issue is understood, we will be able to think about whether there's anything to improve in Zeitwerk or Rails.

[obromios]

Thank you for investigating this further.

Looking in my ApplicationController and my ApplicationHelper, most of the code is straightforwardly procedural e.g. retrieving and massaging data from the database. The only method that does anything 'fancy' is this method, which is in the ApplicationHelper:

def link_to(*args)
   if turbolinks_white_list.include? args[1]
     super
   elsif no_turbolinks_if_ads
     h = {data: {turbolinks: "false"}}
     args[2] = args[2].try(:deep_merge, h) || h
     super
   else
     super
   end
 end

Do you think that could be causing the problem?

I have tried sprinkling binding.pry statements in the ApplicationController and the ApplicationHelper, including one directly under the class ApplicationController < ActionController::Base statement. In all cases, on the first load all the binding.pry statements are triggered, but on the second load, none are. So if the Application Controller is being loaded, it appears only the very first line is reached i.e the class ApplicationController < ActionController::Base. Also, looking in the development log, I am not seeing any exceptions or logging statements indicating a problem loading the ApplicationController (or any exceptions for that matter).

Do you have any suggestions how to use binding.pry or some other means to trackdown the code that is causing the exception?

[fxn]

So, if you put

puts 'TGM - Calling caller'
puts caller
class ApplicationController < ActionController::Base
  puts "GOTCHA!"
  # ...
end

the second time you see "TGM", you don't see "GOTCHA!"?

[obromios]

It is strange, but that is correct.

[fxn]

OK, that is a hint. What does

rails runner 'p ActionController::Base.method(:inherited).source_location'

print?

[obromios]

The short answer is

$ rails runner 'p ActionController::Base.method(:inherited).source_location'
Running via Spring preloader in process 66997
["/Users/Chris/.rvm/gems/ruby-2.6.6@golf_mentor/gems/actionpack-6.0.2.2/lib/action_controller/railties/helpers.rb", 6]

If I stop spring, and issue the command again, I get a much longer trace, ending in the same place, with the immediately preceeding line is
Zeitwerk@rails.main: constant ActionText::TagHelper loaded from file /Users/Chris/.rvm/gems/ruby-2.6.6@golf_mentor/gems/actiontext-6.0.2.2/app/helpers/action_text/tag_helper.rb

[fxn]

Let's follow that lead, if you disable Spring

$ spring stop
$ export DISABLE_SPRING=1
$ rails s

does the issue happen?

[obromios]

Yes, it still happens. And just to be sure, I ran the rails runner command after stopping the server and there was no mention of Spring and the full trace is printed out.

[fxn]

OK, could you edit

/Users/Chris/.rvm/gems/ruby-2.6.6@golf_mentor/gems/actionpack-6.0.2.2/lib/action_controller/railties/helpers.rb

add several traces in the inherited hook, stop Spring (so that your edit is loaded), and reproduce? Anything interesting there?

[obromios]

The railstie code became:

# frozen_string_literal: true

module ActionController
  module Railties
    module Helpers
puts 'TGM in railties helpers'
      def inherited(klass)
puts 'TGM in inherited'
        super
        return unless klass.respond_to?(:helpers_path=)
puts 'TGM - after 1st two lines of inherited'
        if namespace = klass.module_parents.detect { |m| m.respond_to?(:railtie_helpers_paths) }
          paths = namespace.railtie_helpers_paths
        else
          paths = ActionController::Helpers.helpers_path
        end

        klass.helpers_path = paths

        if klass.superclass == ActionController::Base && ActionController::Base.include_all_helpers
          klass.helper :all
        end
puts 'TGM - finished inherited'
      end
puts 'TGM  - finished rails Helper'
    end
puts 'Finished railties'
  end
puts 'Finished ActionController'
end

and the output of rails s | grep TGM was

TGM in railties helpers
TGM  - finished rails Helper
warning package.json: No license field                                                                                                  
warning No license field                                                                                                                
TGM calling
TGM in inherited
TGM - after 1st two lines of inherited
TGM - finished inherited
TGM Gotcha
TGM in inherited
TGM - after 1st two lines of inherited
TGM - finished inherited
TGM calling
TGM in inherited
TGM - after 1st two lines of inherited
TGM in inherited
TGM - after 1st two lines of inherited
TGM - finished inherited

[fxn]

That does not seem to square at first sight.

When did the reload happen? There was only one reload? Can you share the full log doing only one reload?

[fxn]

Ah, and where's the "calling" trace?

[fxn]

Can you inspect klass too please?

[obromios]

Here is the result of one succesful reload.
temp_zeitwerks.txt
and the further result if edit clubs_controller and do reload.
temp_zeitwerks_failed_reload.txt
I have put back the caller and inspected the klass.

[fxn]

Things that catch my attention:

1. While running the inherited hook, the service Advert is loaded. Is that service referenced at the top level of ApplicationHelper? There is nothing wrong with that in principle, just for my mental model of your app.
2. I don't see "finished inherited" for ApplicationController. Could you please add more traces to the inherited hook to see the exact line in which execution stops?
3. Could you also put "TGM #{klass} ..." in each trace of the hook to clearly identify what is running?

[obromios]

Advert is loaded at the top of the ApplicationHelper. By 'each trace of the hook' do you mean the put 'TGM' statements?

[fxn]

Yes! The idea would be to identify the exact line in which execution mysteriously halts. So from

TGM klass: ApplicationController

at the top, add "TGM #{klass} 1", "TGM #{klass} 2", "TGM #{klass} 3", ..., or something like that that allow us to say: there, something weird is going on in line N because we see "2" but not "3". You see the idea.

[obromios]

Here is the railties code with put statements throughout

module ActionController
  module Railties
    module Helpers
puts "TGM in railties helpers"
      def inherited(klass)
puts "TGM klass: #{klass.inspect}"
        super
        return unless klass.respond_to?(:helpers_path=)
puts "TGM - after 1st two lines of inherited, klass: #{klass.inspect}"
        if namespace = klass.module_parents.detect { |m| m.respond_to?(:railtie_helpers_paths) }
          paths = namespace.railtie_helpers_paths
        else
          paths = ActionController::Helpers.helpers_path
        end
puts "TGM - after if else end, klass: #{klass.inspect}"
        klass.helpers_path = paths
puts "TGM - after klass.helpers line, klass: #{klass.inspect}"
        if klass.superclass == ActionController::Base && ActionController::Base.include_all_helpers
          klass.helper :all
        end
puts "TGM - after if end line, klass: #{klass.inspect}"
puts "TGM - finished inherited, klass: #{klass.inspect}"
      end
puts "TGM  - finished rails Helper"
    end
puts "Finished railties"
  end
puts "Finished ActionController"
end

The klass object appears to be only defined in the inherited method. Here is the complete trace of a start server - load page - edit page - unsucessfully load page sequence.

temp_zeitwerks_1.txt

[fxn]

Yes, klass is the argument of inherited, not available elsewhere. I asked for it to be 100% sure while reading the traces for which class is the hook running.

We need one trace more, to see if we enter in

if klass.superclass == ActionController::Base && ActionController::Base.include_all_helpers
  # ADD A NEW TRACE HERE.
  klass.helper :all
end

We are close!

[obromios]

Excellent. Here is the same sequence with that line instrumented. It does look like it enters the if statement.
temp_zeitwerks_2.txt

Looking at that line reminds me that this is a very old app (rails 2 onwards) and I think it might be somewhere configured to allow all helpers to be accessible from all controllers.

[fxn]

Can you wrap that line in a begin/rescue like this?

begin
  klass.helper :all
rescue Exception => e
  puts e.full_message
  raise
end

[obromios]

Here it is.

temp_zeitwerks_3.txt
It looks like it might be a namespaced helper admin/professional_contacts_helper.rb.
module Admin::ProfessionalContactsHelper
By the way, I recall there is a command to put back a gem to its original state of editing it, do you know off hand what it is?

[fxn]

Cool!

So we have two things here. The more urgent one is that you know where's the problem.

Would be cool to make sure also that

rails zeitwerk:check

passes.

The command is gem pristine actionpack.

Please let me know if you manage to fix it and can work normally.

Then, I'll try to understand how is it possible that the exception is silenced.

[obromios]

Ok, will work on it tomorrow (it is evening here in Australia). Thanks for your help, and hope you are keeping safe in these strange times.

[fxn]

Likewise! That was a good hunting session :), good night!

[obromios]

I have now fixed it. I had quite a few namespaced helpers, so after the second one caused the same problem, I ended up moving them all into the main helpers directory, using the pattern that Name::SomeHelper became NameSomeHelper in a file app/helpers/name_some_helper.rb. It is a bit of a shame, because most of them matched namespaced controllers, but the pattern should make them easy to find.

[fxn]

This should not be necessary, helpers can be namespaced. If it is necessary in your app, there's something to be understood. I'll see if I can reproduce any of this with helper :all in a dummy app.

[obromios]

Here is the output from rails zeitwerk:check
$ rails zeitwerk:check

warning package.json: No license field                                                                                                  
warning No license field                                                                                                                
Hold on, I am eager loading the application.
rails aborted!
NoMethodError: undefined method `eager_load_paths' for #<I18n::Config:0x00007fb5cb0b4c20>
/Users/Chris/.rvm/gems/ruby-2.6.6@my_app/gems/railties-6.0.2.2/lib/rails/tasks/zeitwerk.rake:57:in `block (3 levels) in <top (required)>'
/Users/Chris/.rvm/gems/ruby-2.6.6@my_app/gems/railties-6.0.2.2/lib/rails/tasks/zeitwerk.rake:56:in `map'
/Users/Chris/.rvm/gems/ruby-2.6.6@my_app/gems/railties-6.0.2.2/lib/rails/tasks/zeitwerk.rake:56:in `block (2 levels) in <top (required)>'
/Users/Chris/.rvm/gems/ruby-2.6.6@my_app/gems/railties-6.0.2.2/lib/rails/commands/rake/rake_command.rb:23:in `block in perform'
/Users/Chris/.rvm/gems/ruby-2.6.6@my_app/gems/railties-6.0.2.2/lib/rails/commands/rake/rake_command.rb:20:in `perform'
/Users/Chris/.rvm/gems/ruby-2.6.6@my_app/gems/railties-6.0.2.2/lib/rails/command.rb:48:in `invoke'
/Users/Chris/.rvm/gems/ruby-2.6.6@my_app/gems/railties-6.0.2.2/lib/rails/commands.rb:18:in `<top (required)>'
/Users/Chris/Sites/my_app/bin/rails:9:in `require'
/Users/Chris/Sites/my_app/bin/rails:9:in `<main>'
Tasks: TOP => zeitwerk:check
(See full trace by running task with --trace)

[fxn]

Precisely I am tonight trying to reproduce by including all helpers, and failing miserabily.

The fix for that error you found (it is a bug in the Rake task itself) is going to ship with 6.0.3, there's a RC1 out. If you'd like to give it a try, depend on rails 6.0.3.rc1 in Gemfile and try again.

[obromios]

Here is the output after upgrading to the release candidate.
Hold on, I am eager loading the application.

WARNING: The following directories will only be checked if you configure
them to be eager loaded:

  /Users/Chris/Sites/golf_mentor/mailers_previews

You may verify them manually, or add them to config.eager_load_paths
in config/application.rb and run zeitwerk:check again.

Otherwise, all is good!

[fxn]

Excellent @obromios, so it passes the checks 👍.

I have failed to reproduce. Namespaces working for eager loaded helpers, deliberate errors in helpers not silenced, reloads reloading without issues... I'd love to understand what happened in your app before the renames, but without a way to reproduce, it is hard.

I believe the best action is to close then. But please let's reopen if anything shows up again.