trace autoloads, and document hints for troubleshooting

Closes #32885.

2 files changed, 70 insertions, 4 deletions

diff --git a/activesupport/lib/active_support/dependencies.rb b/activesupport/lib/active_support/dependencies.rb
index 9dc2c46880..238a9f0ee6 100644
--- a/activesupport/lib/active_support/dependencies.rb
+++ b/activesupport/lib/active_support/dependencies.rb
@@ -79,6 +79,12 @@ module ActiveSupport #:nodoc:
     # to allow arbitrary constants to be marked for unloading.
     mattr_accessor :explicitly_unloadable_constants, default: []
 
+    # The logger used when tracing autoloads.
+    mattr_accessor :logger
+
+    # If true, trace autoloads with +logger.debug+.
+    mattr_accessor :verbose, default: false
+
     # The WatchStack keeps a stack of the modules being watched as files are
     # loaded. If a file in the process of being loaded (parent.rb) triggers the
     # load of another file (child.rb) the stack will ensure that child.rb
@@ -416,7 +422,7 @@ module ActiveSupport #:nodoc:
 
     # Search for a file in autoload_paths matching the provided suffix.
     def search_for_file(path_suffix)
-      path_suffix = path_suffix.sub(/(\.rb)?$/, ".rb".freeze)
+      path_suffix += ".rb" unless path_suffix.ends_with?(".rb")
 
       autoload_paths.each do |root|
         path = File.join(root, path_suffix)
@@ -450,6 +456,7 @@ module ActiveSupport #:nodoc:
       return nil unless base_path = autoloadable_module?(path_suffix)
       mod = Module.new
       into.const_set const_name, mod
+      log("constant #{qualified_name} autoloaded (module autovivified from #{File.join(base_path, path_suffix)})")
       autoloaded_constants << qualified_name unless autoload_once_paths.include?(base_path)
       autoloaded_constants.uniq!
       mod
@@ -491,7 +498,7 @@ module ActiveSupport #:nodoc:
         raise ArgumentError, "A copy of #{from_mod} has been removed from the module tree but is still active!"
       end
 
-      qualified_name = qualified_name_for from_mod, const_name
+      qualified_name = qualified_name_for(from_mod, const_name)
       path_suffix = qualified_name.underscore
 
       file_path = search_for_file(path_suffix)
@@ -504,8 +511,13 @@ module ActiveSupport #:nodoc:
           raise "Circular dependency detected while autoloading constant #{qualified_name}"
         else
           require_or_load(expanded, qualified_name)
-          raise LoadError, "Unable to autoload constant #{qualified_name}, expected #{file_path} to define it" unless from_mod.const_defined?(const_name, false)
-          return from_mod.const_get(const_name)
+
+          if from_mod.const_defined?(const_name, false)
+            log("constant #{qualified_name} autoloaded from #{expanded}.rb")
+            return from_mod.const_get(const_name)
+          else
+            raise LoadError, "Unable to autoload constant #{qualified_name}, expected #{file_path} to define it"
+          end
         end
       elsif mod = autoload_module!(from_mod, const_name, qualified_name, path_suffix)
         return mod
@@ -554,6 +566,7 @@ module ActiveSupport #:nodoc:
     # as the environment will be in an inconsistent state, e.g. other constants
     # may have already been unloaded and not accessible.
     def remove_unloadable_constants!
+      log("removing unloadable constants")
       autoloaded_constants.each { |const| remove_constant const }
       autoloaded_constants.clear
       Reference.clear!
@@ -743,6 +756,10 @@ module ActiveSupport #:nodoc:
         # The constant is no longer reachable, just skip it.
       end
     end
+
+    def log(message)
+      logger.debug("autoloading: #{message}") if logger && verbose
+    end
   end
 end
 
diff --git a/activesupport/test/dependencies_test.rb b/activesupport/test/dependencies_test.rb
index 84cb64a7c2..a486ef5eac 100644
--- a/activesupport/test/dependencies_test.rb
+++ b/activesupport/test/dependencies_test.rb
@@ -1130,3 +1130,52 @@ class DependenciesTest < ActiveSupport::TestCase
     ActiveSupport::Dependencies.hook!
   end
 end
+
+class DependenciesLogging < ActiveSupport::TestCase
+  MESSAGE = "message"
+
+  def with_settings(logger, verbose)
+    original_logger = ActiveSupport::Dependencies.logger
+    original_verbose = ActiveSupport::Dependencies.verbose
+
+    ActiveSupport::Dependencies.logger = logger
+    ActiveSupport::Dependencies.verbose = verbose
+
+    yield
+  ensure
+    ActiveSupport::Dependencies.logger = original_logger
+    ActiveSupport::Dependencies.verbose = original_verbose
+  end
+
+  def fake_logger
+    Class.new do
+      def self.debug(message)
+        message
+      end
+    end
+  end
+
+  test "does not log if the logger is nil and verbose is false" do
+    with_settings(nil, false) do
+      assert_nil ActiveSupport::Dependencies.log(MESSAGE)
+    end
+  end
+
+  test "does not log if the logger is nil and verbose is true" do
+    with_settings(nil, true) do
+      assert_nil ActiveSupport::Dependencies.log(MESSAGE)
+    end
+  end
+
+  test "does not log if the logger is set and verbose is false" do
+    with_settings(fake_logger, false) do
+      assert_nil ActiveSupport::Dependencies.log(MESSAGE)
+    end
+  end
+
+  test "logs if the logger is set and verbose is true" do
+    with_settings(fake_logger, true) do
+      assert_equal "autoloading: #{MESSAGE}", ActiveSupport::Dependencies.log(MESSAGE)
+    end
+  end
+end