search

fxn / zeitwerk

Efficient and thread-safe code loader for Ruby
MIT License
1.99k stars 118 forks source link

Gem's loader is being setup multiple times #282

Closed sajan45 closed 9 months ago

sajan45 commented 9 months ago

I understand this is probably not an issue with Zeitwerk, so I would appreciate a confirmation that this is not a Zeitwerk issue or any other guidance that can help me track down the cause of this error.

I am trying to upgrade Gruf to the latest version, which is using Zeitwerk.

But whenever I do a require "gruf" or try to require another library that requires gruf, I get the below exception(removed some sensitive info from the file paths).

The application has a complex build process but from what I can see, the only change related to loading of files/gems is that instead of an auto require using bundler/setup and Bundler.require(*Rails.groups) in the application.rb, this requires all required gem explicitly in application.rb. There is no other change related to autoload or eagerload configs.

The same gem works fine with a new Rails app.

/home/external/bundle/lib/ruby/3.1.0/gems/zeitwerk-2.6.12/lib/zeitwerk/loader.rb:542:in `block (3 levels) in raise_if_conflicting_directory': loader (Zeitwerk::Error)

#<Zeitwerk::Loader:0x00007f87d7bbd328
 @autoloaded_dirs=[],
 @autoloads={},
 @collapse_dirs=#<Set: {}>,
 @collapse_glob_patterns=#<Set: {}>,
 @dirs_autoload_monitor=#<Monitor:0x00007f87d7bbcba8>,
 @eager_load_exclusions=#<Set: {}>,
 @eager_loaded=false,
 @ignored_glob_patterns=
  #<Set:
   {"/home/external/bundle/lib/ruby/3.1.0/gems/gruf-2.18.0/lib/gruf/integrations/rails/railtie.rb",
    "/home/external/bundle/lib/ruby/3.1.0/gems/gruf-2.18.0/lib/gruf/controllers/health_controller.rb"}>,
 @ignored_paths=
  #<Set:
   {"/home/external/bundle/lib/ruby/3.1.0/gems/gruf-2.18.0/lib/gruf/integrations/rails/railtie.rb",
    "/home/external/bundle/lib/ruby/3.1.0/gems/gruf-2.18.0/lib/gruf/controllers/health_controller.rb"}>,
 @inflector=
  #<Zeitwerk::GemInflector:0x00007f87d7bbcab8
   @version_file=
    "/home/external/bundle/lib/ruby/3.1.0/gems/gruf-2.18.0/lib/gruf/version.rb">,
 @initialized_at=2024-01-16 10:04:43.001758891 +0000,
 @logger=nil,
 @mutex=#<Thread::Mutex:0x00007f87d7bbcbf8>,
 @namespace_dirs={},
 @on_load_callbacks={},
 @on_setup_callbacks=[],
 @on_unload_callbacks={},
 @reloading_enabled=false,
 @roots={},
 @setup=false,
 @shadowed_files=#<Set: {}>,
 @tag="gruf",
 @to_unload={}>

wants to manage directory /home/ruby/3.1.0/gems/gruf-2.18.0/lib, which is already managed by

#<Zeitwerk::Loader:0x00007f87d7e9de30
 @autoloaded_dirs=[],
 @autoloads=
  {"/home/ruby/3.1.0/gems/gruf-2.18.0/lib/gruf.rb"=>
    [Object, :Gruf]},
 @collapse_dirs=#<Set: {}>,
 @collapse_glob_patterns=#<Set: {}>,
 @dirs_autoload_monitor=#<Monitor:0x00007f87d7e9c468>,
 @eager_load_exclusions=#<Set: {}>,
 @eager_loaded=false,
 @ignored_glob_patterns=
  #<Set:
   {"/home/ruby/3.1.0/gems/gruf-2.18.0/lib/gruf/integrations/rails/railtie.rb",
    "/home/ruby/3.1.0/gems/gruf-2.18.0/lib/gruf/controllers/health_controller.rb"}>,
 @ignored_paths=
  #<Set:
   {"/home/ruby/3.1.0/gems/gruf-2.18.0/lib/gruf/integrations/rails/railtie.rb",
    "/home/ruby/3.1.0/gems/gruf-2.18.0/lib/gruf/controllers/health_controller.rb"}>,
 @inflector=
  #<Zeitwerk::GemInflector:0x00007f87d7e9c210
   @overrides={},
   @version_file=
    "/home/ruby/3.1.0/gems/gruf-2.18.0/lib/gruf/version.rb">,
 @initialized_at=2024-01-16 10:04:42.976264795 +0000,
 @logger=nil,
 @mutex=#<Thread::Mutex:0x00007f87d7e9c4b8>,
 @namespace_dirs=
  {"Gruf"=>
    ["/home/external/bundle/lib/ruby/3.1.0/gems/gruf-2.18.0/lib/gruf"]},
 @on_load_callbacks={},
 @on_setup_callbacks=[],
 @on_unload_callbacks={},
 @reloading_enabled=false,
 @roots=
  {"/home/external/bundle/lib/ruby/3.1.0/gems/gruf-2.18.0/lib"=>
    Object},
 @setup=true,
 @shadowed_files=#<Set: {}>,
 @tag="gruf",
 @to_unload={}>

    from /home/external/bundle/lib/ruby/3.1.0/gems/zeitwerk-2.6.12/lib/zeitwerk/loader.rb:536:in `each_key'
    from /home/external/bundle/lib/ruby/3.1.0/gems/zeitwerk-2.6.12/lib/zeitwerk/loader.rb:536:in `block (2 levels) in raise_if_conflicting_directory'
    from /home/external/bundle/lib/ruby/3.1.0/gems/zeitwerk-2.6.12/lib/zeitwerk/loader.rb:532:in `each'
    from /home/external/bundle/lib/ruby/3.1.0/gems/zeitwerk-2.6.12/lib/zeitwerk/loader.rb:532:in `block in raise_if_conflicting_directory'
    from /home/external/bundle/lib/ruby/3.1.0/gems/zeitwerk-2.6.12/lib/zeitwerk/loader.rb:529:in `synchronize'
    from /home/external/bundle/lib/ruby/3.1.0/gems/zeitwerk-2.6.12/lib/zeitwerk/loader.rb:529:in `raise_if_conflicting_directory'
    from /home/external/bundle/lib/ruby/3.1.0/gems/zeitwerk-2.6.12/lib/zeitwerk/loader/config.rb:122:in `push_dir'
    from /home/external/bundle/lib/ruby/3.1.0/gems/gruf-2.18.0/lib/gruf.rb:32:in `<top (required)>'
    from <internal:/usr/local/lib/ruby/site_ruby/3.1.0/rubygems/core_ext/kernel_require.rb>:85:in `require'
    from <internal:/usr/local/lib/ruby/site_ruby/3.1.0/rubygems/core_ext/kernel_require.rb>:85:in `require'
    from /home/external/bundle/lib/ruby/3.1.0/gems/zeitwerk-2.6.12/lib/zeitwerk/kernel.rb:30:in `require'
    from /home/ruby/3.1.0/gems/activesupport-6.0.4.8/lib/active_support/dependencies.rb:324:in `block in require'
    from /home/ruby/3.1.0/gems/activesupport-6.0.4.8/lib/active_support/dependencies.rb:291:in `load_dependency'
    from /home/ruby/3.1.0/gems/activesupport-6.0.4.8/lib/active_support/dependencies.rb:324:in `require'
    from /home/external/bundle/lib/ruby/3.1.0/gems/gruf-2.18.0/lib/gruf/integrations/rails/railtie.rb:18:in `<top (required)>'
    from /home/ruby/3.1.0/gems/gruf-2.18.0/lib/gruf.rb:35:in `require_relative'
    from /home/ruby/3.1.0/gems/gruf-2.18.0/lib/gruf.rb:35:in `<top (required)>'
    from <internal:/usr/local/lib/ruby/site_ruby/3.1.0/rubygems/core_ext/kernel_require.rb>:85:in `require'
    from <internal:/usr/local/lib/ruby/site_ruby/3.1.0/rubygems/core_ext/kernel_require.rb>:85:in `require'
    from /home/ruby/3.1.0/gems/activesupport-6.0.4.8/lib/active_support/dependencies.rb:324:in `block in require'
    from /home/ruby/3.1.0/gems/activesupport-6.0.4.8/lib/active_support/dependencies.rb:291:in `load_dependency'
    from /home/ruby/3.1.0/gems/activesupport-6.0.4.8/lib/active_support/dependencies.rb:324:in `require'
    from /home/my_app/config/application.rb:44:in `<top (required)>'
    from <internal:/usr/local/lib/ruby/site_ruby/3.1.0/rubygems/core_ext/kernel_require.rb>:85:in `require'
    from <internal:/usr/local/lib/ruby/site_ruby/3.1.0/rubygems/core_ext/kernel_require.rb>:85:in `require'
    from /home/my_app/config/environment.rb:6:in `<top (required)>'
    from <internal:/usr/local/lib/ruby/site_ruby/3.1.0/rubygems/core_ext/kernel_require.rb>:85:in `require'
    from <internal:/usr/local/lib/ruby/site_ruby/3.1.0/rubygems/core_ext/kernel_require.rb>:85:in `require'
    from /home/my_app/bin/rails:3:in `<top (required)>'
    from /home/my_app/bin/rails_test:6:in `load'
    from /home/my_app/bin/rails_test:6:in `<main>'
fxn commented 9 months ago

Indeed, the loaders seem to be the same one (conceptually, they are two instances), and their @initialized_at are a fraction of a second apart. That timestamp is set extremely early, when the loader object itself is created, when initialize runs, so that difference in time is a hint.

I'll dig into it!

fxn commented 9 months ago

I don't quite square why the change in the way the require calls are done matters, but I believe I see what happens. Let me explain.

The way things are written introduces a circularity that agrees with what we are seeing.

Let's remove Zeitwerk from the equation for a moment and consider Gruf's entrypoint rewritten this way: 

# gruf.rb
autoload :Gruf, File.expand_path(__FILE__)

require_relative 'gruf/.../railtie'

module Gruf
  ...
end

That autoload call is automated by Zeitwerk, in this case we write it artificially by hand so that we see it.

On the other hand we have the file that defines the railtie, loaded above with require_relative:

# gruf/.../railtie.rb
module Gruf
  ...
end

This setup will make the entrypoint to be executed twice.

Why? The require_relative call loads a file that has module Gruf at the start. Since at that point the Gruf module has not been defined yet (it is defined below the require_relative), the autoload triggers loading gruf.rb again.

The solution to this is to move the require_relative call after the module definition in the entrypoint. That is, the entrypoint creates, and the railtie reopens, which is natural, isn't it? The call could be moved to the body of the module definition (this is my preferred style), or after the module definition, at the bottom of the entrypoint.

I believe you could open a ticket to ask for this change in Gruf. Meanwhile, you could temporarily write module Gruf; end before the require "gruf" call, to have the module defined before all that happens and avoid the circularity. I have not tested this, but if my understanding is correct, it would be a simple workaround.

fxn commented 9 months ago

Could it be the case that you upgraded Gruf at the same time? Previous versions did not use Zeitwerk.

sajan45 commented 9 months ago

Yes, the current version that I am using, does not use Zeitwerk, I am facing this issue if I upgrade to the latest version. I agree with with your finding, I suspected the same thing. I will try your solution about moving the require_relative call to after the module definition. If it helps, I will create a ticket or PR on Gruf. Thanks.

sajan45 commented 9 months ago

I tried to move the require_relative call to the bottom and then to inside the module definition like your preferred style but still got the same exception. However, adding a module Gruf; end helped, so I am using that as a workaround. Here is the entrypoint to my fork of Gruf for which I got the below exception.

Feel free to close this if there is nothing else we can do.

/home/ruby/3.1.0/gems/zeitwerk-2.6.12/lib/zeitwerk/loader.rb:542:in `block (3 levels) in raise_if_conflicting_directory': loader (Zeitwerk::Error)

#<Zeitwerk::Loader:0x00007f534d856f68
 @autoloaded_dirs=[],
 @autoloads={},
 @collapse_dirs=#<Set: {}>,
 @collapse_glob_patterns=#<Set: {}>,
 @dirs_autoload_monitor=#<Monitor:0x00007f534d856798>,
 @eager_load_exclusions=#<Set: {}>,
 @eager_loaded=false,
 @ignored_glob_patterns=
  #<Set:
   {"/home/ruby/3.1.0/bundler/gems/gruf-74961f34bf73/lib/gruf/integrations/rails/railtie.rb",
    "/home/ruby/3.1.0/bundler/gems/gruf-74961f34bf73/lib/gruf/controllers/health_controller.rb"}>,
 @ignored_paths=
  #<Set:
   {"/home/ruby/3.1.0/bundler/gems/gruf-74961f34bf73/lib/gruf/integrations/rails/railtie.rb",
    "/home/ruby/3.1.0/bundler/gems/gruf-74961f34bf73/lib/gruf/controllers/health_controller.rb"}>,
 @inflector=
  #<Zeitwerk::GemInflector:0x00007f534d8566a8
   @version_file=
    "/home/ruby/3.1.0/bundler/gems/gruf-74961f34bf73/lib/gruf/version.rb">,
 @initialized_at=2024-01-17 06:16:15.766924063 +0000,
 @logger=nil,
 @mutex=#<Thread::Mutex:0x00007f534d8567e8>,
 @namespace_dirs={},
 @on_load_callbacks={},
 @on_setup_callbacks=[],
 @on_unload_callbacks={},
 @reloading_enabled=false,
 @roots={},
 @setup=false,
 @shadowed_files=#<Set: {}>,
 @tag="gruf",
 @to_unload={}>

wants to manage directory /home/ruby/3.1.0/bundler/gems/gruf-74961f34bf73/lib, which is already managed by

#<Zeitwerk::Loader:0x00007f534db3e460
 @autoloaded_dirs=[],
 @autoloads=
  {"/home/ruby/3.1.0/bundler/gems/gruf-74961f34bf73/lib/gruf.rb"=>
    [Object, :Gruf]},
 @collapse_dirs=#<Set: {}>,
 @collapse_glob_patterns=#<Set: {}>,
 @dirs_autoload_monitor=#<Monitor:0x00007f534db47f10>,
 @eager_load_exclusions=#<Set: {}>,
 @eager_loaded=false,
 @ignored_glob_patterns=
  #<Set:
   {"/home/ruby/3.1.0/bundler/gems/gruf-74961f34bf73/lib/gruf/integrations/rails/railtie.rb",
    "/home/ruby/3.1.0/bundler/gems/gruf-74961f34bf73/lib/gruf/controllers/health_controller.rb"}>,
 @ignored_paths=
  #<Set:
   {"/home/ruby/3.1.0/bundler/gems/gruf-74961f34bf73/lib/gruf/integrations/rails/railtie.rb",
    "/home/ruby/3.1.0/bundler/gems/gruf-74961f34bf73/lib/gruf/controllers/health_controller.rb"}>,
 @inflector=
  #<Zeitwerk::GemInflector:0x00007f534db47b50
   @overrides={},
   @version_file=
    "/home/ruby/3.1.0/bundler/gems/gruf-74961f34bf73/lib/gruf/version.rb">,
 @initialized_at=2024-01-17 06:16:15.741529358 +0000,
 @logger=nil,
 @mutex=#<Thread::Mutex:0x00007f534db40058>,
 @namespace_dirs=
  {"Gruf"=>
    ["/home/ruby/3.1.0/bundler/gems/gruf-74961f34bf73/lib/gruf"]},
 @on_load_callbacks={},
 @on_setup_callbacks=[],
 @on_unload_callbacks={},
 @reloading_enabled=false,
 @roots=
  {"/home/ruby/3.1.0/bundler/gems/gruf-74961f34bf73/lib"=>
    Object},
 @setup=true,
 @shadowed_files=#<Set: {}>,
 @tag="gruf",
 @to_unload={}>

    from /home/ruby/3.1.0/gems/zeitwerk-2.6.12/lib/zeitwerk/loader.rb:536:in `each_key'
    from /home/ruby/3.1.0/gems/zeitwerk-2.6.12/lib/zeitwerk/loader.rb:536:in `block (2 levels) in raise_if_conflicting_directory'
    from /home/ruby/3.1.0/gems/zeitwerk-2.6.12/lib/zeitwerk/loader.rb:532:in `each'
    from /home/ruby/3.1.0/gems/zeitwerk-2.6.12/lib/zeitwerk/loader.rb:532:in `block in raise_if_conflicting_directory'
    from /home/ruby/3.1.0/gems/zeitwerk-2.6.12/lib/zeitwerk/loader.rb:529:in `synchronize'
    from /home/ruby/3.1.0/gems/zeitwerk-2.6.12/lib/zeitwerk/loader.rb:529:in `raise_if_conflicting_directory'
    from /home/ruby/3.1.0/gems/zeitwerk-2.6.12/lib/zeitwerk/loader/config.rb:122:in `push_dir'
    from /home/ruby/3.1.0/bundler/gems/gruf-74961f34bf73/lib/gruf.rb:32:in `<top (required)>'
    from <internal:/usr/local/lib/ruby/site_ruby/3.1.0/rubygems/core_ext/kernel_require.rb>:85:in `require'
    from <internal:/usr/local/lib/ruby/site_ruby/3.1.0/rubygems/core_ext/kernel_require.rb>:85:in `require'
    from /home/ruby/3.1.0/gems/zeitwerk-2.6.12/lib/zeitwerk/kernel.rb:30:in `require'
    from /home/ruby/3.1.0/gems/activesupport-6.0.4.8/lib/active_support/dependencies.rb:324:in `block in require'
    from /home/ruby/3.1.0/gems/activesupport-6.0.4.8/lib/active_support/dependencies.rb:291:in `load_dependency'
    from /home/ruby/3.1.0/gems/activesupport-6.0.4.8/lib/active_support/dependencies.rb:324:in `require'
    from /home/ruby/3.1.0/bundler/gems/gruf-74961f34bf73/lib/gruf.rb:38:in `<top (required)>'
    from <internal:/usr/local/lib/ruby/site_ruby/3.1.0/rubygems/core_ext/kernel_require.rb>:85:in `require'
    from <internal:/usr/local/lib/ruby/site_ruby/3.1.0/rubygems/core_ext/kernel_require.rb>:85:in `require'
    from /home/ruby/3.1.0/gems/activesupport-6.0.4.8/lib/active_support/dependencies.rb:324:in `block in require'
    from /home/ruby/3.1.0/gems/activesupport-6.0.4.8/lib/active_support/dependencies.rb:291:in `load_dependency'
    from /home/ruby/3.1.0/gems/activesupport-6.0.4.8/lib/active_support/dependencies.rb:324:in `require'
    from /home/my_app/config/application.rb:44:in `<top (required)>'
    from <internal:/usr/local/lib/ruby/site_ruby/3.1.0/rubygems/core_ext/kernel_require.rb>:85:in `require'
    from <internal:/usr/local/lib/ruby/site_ruby/3.1.0/rubygems/core_ext/kernel_require.rb>:85:in `require'
    from /home/my_app/config/environment.rb:6:in `<top (required)>'
    from <internal:/usr/local/lib/ruby/site_ruby/3.1.0/rubygems/core_ext/kernel_require.rb>:85:in `require'
    from <internal:/usr/local/lib/ruby/site_ruby/3.1.0/rubygems/core_ext/kernel_require.rb>:85:in `require'
    from /home/my_app/bin/rails:3:in `<top (required)>'
    from /home/my_app/bin/rails_test:6:in `load'
    from /home/my_app/bin/rails_test:6:in `<main>'
fxn commented 9 months ago

So, you moved the require_relative and added module Gruf; end in your project just before require "gruf"?

sajan45 commented 9 months ago

I moved require_relative but since that did not fix the error, now I am using the original gem with no change to it and added the Module Gruf; end before the require "gruf" and it is working.

fxn commented 9 months ago

Awesome. Glad that at least that workaround lets you move on.

I'll leave the issue open by now. If moving the require_relative still generates an error, there's something off somewhere I'd like to understand.

fxn commented 9 months ago

My analysis above is wrong. In normal circumstances the circularity does not happen.

I forgot an edge case: If you set an autoload on a file that is being required at that moment, the autoload is ignored by Ruby. For example, consider this foo.rb:

autoload :Foo, File.expand_path(__FILE__)
p Object.autoload?(:Foo)

If you load that script normally, you get the expected string:

% ruby foo.rb
"/Users/fxn/tmp/foo.rb"

but if you require the file, there is no autoload in place:

% ruby -I. -rfoo -e1
nil

I should remember, because while developing Zeitwerk I had a poltergeist related to this, and discovered this edge case while having dinner in Christmas Eve 2018. Guess who ended up in the sofa with the laptop :). That ended up with a notion of inception in the code base.

OK, so my theory was wrong, and that agrees with the observation that moving require_relative does not fix the issue. The current code works.

Now, the next problem is that the current code apparently works :D. That is, I cannot reproduce booting the app with bin/rails runner 1 using Ruby 3.1 and Gruf 2.18.0.

Could you comment out the workaround for a moment, add

pp caller_locations
pp Thread.current.object_id

at the top of lib/gruf.rb (bundle open gruf), and trigger the error? Does it show anything interesting?

Do you think you could reproduce the error with a minimal application?

sajan45 commented 9 months ago

I don't see anything different. Those were printed twice but we already know that the entry point is being executed twice. The second caller_locations is a continuation of the first one. I will try to dig a little more into the app and try to reproduce this in a minimal app. Give me a day or two.

["<internal:/usr/local/lib/ruby/site_ruby/3.1.0/rubygems/core_ext/kernel_require.rb>:85:in `require'",
 "<internal:/usr/local/lib/ruby/site_ruby/3.1.0/rubygems/core_ext/kernel_require.rb>:85:in `require'",
 "/home/ruby/3.1.0/gems/activesupport-6.0.4.8/lib/active_support/dependencies.rb:324:in `block in require'",
 "/home/ruby/3.1.0/gems/activesupport-6.0.4.8/lib/active_support/dependencies.rb:291:in `load_dependency'",
 "/home/ruby/3.1.0/gems/activesupport-6.0.4.8/lib/active_support/dependencies.rb:324:in `require'",
 "/home/my_app/config/application.rb:47:in `<top (required)>'",
 "<internal:/usr/local/lib/ruby/site_ruby/3.1.0/rubygems/core_ext/kernel_require.rb>:85:in `require'",
 "<internal:/usr/local/lib/ruby/site_ruby/3.1.0/rubygems/core_ext/kernel_require.rb>:85:in `require'",
 "/home/my_app/config/environment.rb:6:in `<top (required)>'",
 "<internal:/usr/local/lib/ruby/site_ruby/3.1.0/rubygems/core_ext/kernel_require.rb>:85:in `require'",
 "<internal:/usr/local/lib/ruby/site_ruby/3.1.0/rubygems/core_ext/kernel_require.rb>:85:in `require'",
 "/home/my_app/bin/rails:3:in `<top (required)>'",
 "/home/my_app/bin/rails_test:6:in `load'",
 "/home/my_app/bin/rails_test:6:in `<main>'"]
580

["<internal:/usr/local/lib/ruby/site_ruby/3.1.0/rubygems/core_ext/kernel_require.rb>:85:in `require'",
 "<internal:/usr/local/lib/ruby/site_ruby/3.1.0/rubygems/core_ext/kernel_require.rb>:85:in `require'",
 "/home/ruby/3.1.0/gems/zeitwerk-2.6.12/lib/zeitwerk/kernel.rb:30:in `require'",
 "/home/ruby/3.1.0/gems/activesupport-6.0.4.8/lib/active_support/dependencies.rb:324:in `block in require'",
 "/home/ruby/3.1.0/gems/activesupport-6.0.4.8/lib/active_support/dependencies.rb:291:in `load_dependency'",
 "/home/ruby/3.1.0/gems/activesupport-6.0.4.8/lib/active_support/dependencies.rb:324:in `require'",
 "/home/ruby/3.1.0/bundler/gems/gruf-db5cadcf1940/lib/gruf/integrations/rails/railtie.rb:18:in `<top (required)>'",
 "/home/ruby/3.1.0/bundler/gems/gruf-db5cadcf1940/lib/gruf.rb:39:in `require_relative'",
 "/home/ruby/3.1.0/bundler/gems/gruf-db5cadcf1940/lib/gruf.rb:39:in `<top (required)>'",
 "<internal:/usr/local/lib/ruby/site_ruby/3.1.0/rubygems/core_ext/kernel_require.rb>:85:in `require'",
 "<internal:/usr/local/lib/ruby/site_ruby/3.1.0/rubygems/core_ext/kernel_require.rb>:85:in `require'",
 "/home/ruby/3.1.0/gems/activesupport-6.0.4.8/lib/active_support/dependencies.rb:324:in `block in require'",
 "/home/ruby/3.1.0/gems/activesupport-6.0.4.8/lib/active_support/dependencies.rb:291:in `load_dependency'",
 "/home/ruby/3.1.0/gems/activesupport-6.0.4.8/lib/active_support/dependencies.rb:324:in `require'",
 "/home/my_app/config/application.rb:47:in `<top (required)>'",
 "<internal:/usr/local/lib/ruby/site_ruby/3.1.0/rubygems/core_ext/kernel_require.rb>:85:in `require'",
 "<internal:/usr/local/lib/ruby/site_ruby/3.1.0/rubygems/core_ext/kernel_require.rb>:85:in `require'",
 "/home/my_app/config/environment.rb:6:in `<top (required)>'",
 "<internal:/usr/local/lib/ruby/site_ruby/3.1.0/rubygems/core_ext/kernel_require.rb>:85:in `require'",
 "<internal:/usr/local/lib/ruby/site_ruby/3.1.0/rubygems/core_ext/kernel_require.rb>:85:in `require'",
 "/home/my_app/bin/rails:3:in `<top (required)>'",
 "/home/my_app/bin/rails_test:6:in `load'",
 "/home/my_app/bin/rails_test:6:in `<main>'"]
580
fxn commented 9 months ago

The idea was to see the circularity in the backtraces, or in any case identify who is loading in each round. I'll read them later.

sajan45 commented 9 months ago

Sure. BTW I am not using bundle open, I used my fork of Gruf. Here is the entrypoint

fxn commented 9 months ago

The top locations reported here are different:

"/Users/fxn/.rbenv/versions/3.1.4/lib/ruby/gems/3.1.0/gems/bootsnap-1.17.1/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:30:in `require'",
 "/Users/fxn/.rbenv/versions/3.1.4/lib/ruby/gems/3.1.0/gems/bootsnap-1.17.1/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:30:in `require'",
 "/Users/fxn/.rbenv/versions/3.1.4/lib/ruby/gems/3.1.0/gems/activesupport-6.0.6.1/lib/active_support/dependencies.rb:324:in `block in require'",
 "/Users/fxn/.rbenv/versions/3.1.4/lib/ruby/gems/3.1.0/gems/activesupport-6.0.6.1/lib/active_support/dependencies.rb:291:in `load_dependency'",
 "/Users/fxn/.rbenv/versions/3.1.4/lib/ruby/gems/3.1.0/gems/activesupport-6.0.6.1/lib/active_support/dependencies.rb:324:in `require'",
 "/Users/fxn/tmp/del_gruf/config/application.rb:4:in `<main>'",

Do you have gruf in the Gemfile with require: false? If yes, is the require call in line 47 of your config/application.rb? I guess your app does not use Bootsnap? Your backtraces are generated using which command exactly?

fxn commented 9 months ago

Ah, that fork has the require_relative before the definition of the Gruf module. Could you move it to the bottom of the file, reproduce, and share both caller_locations? We do not know why your build system behaves like that, but under that assumption, moving require_relative should work. You saw it does not, so perhaps we see something in the new backtraces.

fxn commented 9 months ago

My hypothesis is that in that case, the very module Grub line in lib/grub.rb would be the one triggering the circularity.

The key observation is that lib/grub.rb is being loaded in a way that prevents the autoload call for Grub issued by the loader from being discarded. If we understand why, I think we'll have it.

sajan45 commented 9 months ago

We do not have require: false in the Gemfile but we have deleted the code related to bundler or bootsnap which load the Gems. Instead we require it explicitly and yes on line 47 of config/application.rb, we have require "gruf".

Anyway, after digging into the build system I have found the source of the problem. We use symlinks while bundling the gems and I think that is what causes require/require_relative to load the file twice. I see a couple of bug reports in the Ruby issue tracker related to this issue, but most of those are already fixed.

Here is how you can reproduce this. Clone the gruf repo (I cloned it to /Users/sajan/projects/gruf). Create a duplicate directory(I did it at /Users/sajan/projects/bug/gruf) for this repo which mirrors the tree structure but for individual files, create a symlink to the file in the original clone (at /Users/sajan/projects/gruf). Now If I start IRB with this duplicated repo in LOAD_PATH like RUBYLIB=/Users/sajan/projects/bug/gruf/lib irb and execute require 'gruf', I get the same exception that you can see below, it has caller_locations and object_id. I am also sharing the script at the bottom that I used to duplicate the directory.

➜  projects RUBYLIB=/Users/sajan/projects/bug/gruf/lib irb
3.1.4 :001 > require 'gruf'
["<internal:/Users/sajan/.rvm/rubies/ruby-3.1.4/lib/ruby/3.1.0/rubygems/core_ext/kernel_require.rb>:85:in `require'",
 "<internal:/Users/sajan/.rvm/rubies/ruby-3.1.4/lib/ruby/3.1.0/rubygems/core_ext/kernel_require.rb>:85:in `require'",
 "(irb):1:in `<top (required)>'",                                                           
 "/Users/sajan/.rvm/rubies/ruby-3.1.4/lib/ruby/3.1.0/irb/workspace.rb:119:in `eval'",       
 "/Users/sajan/.rvm/rubies/ruby-3.1.4/lib/ruby/3.1.0/irb/workspace.rb:119:in `evaluate'",   
 "/Users/sajan/.rvm/rubies/ruby-3.1.4/lib/ruby/3.1.0/irb/context.rb:476:in `evaluate'",     
 "/Users/sajan/.rvm/rubies/ruby-3.1.4/lib/ruby/3.1.0/irb.rb:577:in `block (2 levels) in eval_input'",
 "/Users/sajan/.rvm/rubies/ruby-3.1.4/lib/ruby/3.1.0/irb.rb:770:in `signal_status'",        
 "/Users/sajan/.rvm/rubies/ruby-3.1.4/lib/ruby/3.1.0/irb.rb:558:in `block in eval_input'",  
 "/Users/sajan/.rvm/rubies/ruby-3.1.4/lib/ruby/3.1.0/irb/ruby-lex.rb:268:in `block (2 levels) in each_top_level_statement'",
 "/Users/sajan/.rvm/rubies/ruby-3.1.4/lib/ruby/3.1.0/irb/ruby-lex.rb:250:in `loop'",        
 "/Users/sajan/.rvm/rubies/ruby-3.1.4/lib/ruby/3.1.0/irb/ruby-lex.rb:250:in `block in each_top_level_statement'",
 "/Users/sajan/.rvm/rubies/ruby-3.1.4/lib/ruby/3.1.0/irb/ruby-lex.rb:249:in `catch'",       
 "/Users/sajan/.rvm/rubies/ruby-3.1.4/lib/ruby/3.1.0/irb/ruby-lex.rb:249:in `each_top_level_statement'",
 "/Users/sajan/.rvm/rubies/ruby-3.1.4/lib/ruby/3.1.0/irb.rb:557:in `eval_input'",           
 "/Users/sajan/.rvm/rubies/ruby-3.1.4/lib/ruby/3.1.0/irb.rb:491:in `block in run'",
 "/Users/sajan/.rvm/rubies/ruby-3.1.4/lib/ruby/3.1.0/irb.rb:490:in `catch'",
 "/Users/sajan/.rvm/rubies/ruby-3.1.4/lib/ruby/3.1.0/irb.rb:490:in `run'",
 "/Users/sajan/.rvm/rubies/ruby-3.1.4/lib/ruby/3.1.0/irb.rb:419:in `start'",
 "/Users/sajan/.rvm/rubies/ruby-3.1.4/lib/ruby/gems/3.1.0/gems/irb-1.4.1/exe/irb:11:in `<top (required)>'",
 "/Users/sajan/.rvm/rubies/ruby-3.1.4/bin/irb:25:in `load'",
 "/Users/sajan/.rvm/rubies/ruby-3.1.4/bin/irb:25:in `<main>'"]
"<<<<<<<<<<<"
29700
"==========="
["<internal:/Users/sajan/.rvm/rubies/ruby-3.1.4/lib/ruby/3.1.0/rubygems/core_ext/kernel_require.rb>:85:in `require'",
 "<internal:/Users/sajan/.rvm/rubies/ruby-3.1.4/lib/ruby/3.1.0/rubygems/core_ext/kernel_require.rb>:85:in `require'",
 "/Users/sajan/.rvm/gems/ruby-3.1.4/gems/zeitwerk-2.6.12/lib/zeitwerk/kernel.rb:30:in `require'",
 "/Users/sajan/projects/bug/gruf/lib/gruf.rb:43:in `<top (required)>'",
 "<internal:/Users/sajan/.rvm/rubies/ruby-3.1.4/lib/ruby/3.1.0/rubygems/core_ext/kernel_require.rb>:85:in `require'",
 "<internal:/Users/sajan/.rvm/rubies/ruby-3.1.4/lib/ruby/3.1.0/rubygems/core_ext/kernel_require.rb>:85:in `require'",
 "(irb):1:in `<top (required)>'",
 "/Users/sajan/.rvm/rubies/ruby-3.1.4/lib/ruby/3.1.0/irb/workspace.rb:119:in `eval'",
 "/Users/sajan/.rvm/rubies/ruby-3.1.4/lib/ruby/3.1.0/irb/workspace.rb:119:in `evaluate'",
 "/Users/sajan/.rvm/rubies/ruby-3.1.4/lib/ruby/3.1.0/irb/context.rb:476:in `evaluate'",
 "/Users/sajan/.rvm/rubies/ruby-3.1.4/lib/ruby/3.1.0/irb.rb:577:in `block (2 levels) in eval_input'",
 "/Users/sajan/.rvm/rubies/ruby-3.1.4/lib/ruby/3.1.0/irb.rb:770:in `signal_status'",
 "/Users/sajan/.rvm/rubies/ruby-3.1.4/lib/ruby/3.1.0/irb.rb:558:in `block in eval_input'",
 "/Users/sajan/.rvm/rubies/ruby-3.1.4/lib/ruby/3.1.0/irb/ruby-lex.rb:268:in `block (2 levels) in each_top_level_statement'",
 "/Users/sajan/.rvm/rubies/ruby-3.1.4/lib/ruby/3.1.0/irb/ruby-lex.rb:250:in `loop'",
 "/Users/sajan/.rvm/rubies/ruby-3.1.4/lib/ruby/3.1.0/irb/ruby-lex.rb:250:in `block in each_top_level_statement'",
 "/Users/sajan/.rvm/rubies/ruby-3.1.4/lib/ruby/3.1.0/irb/ruby-lex.rb:249:in `catch'",
 "/Users/sajan/.rvm/rubies/ruby-3.1.4/lib/ruby/3.1.0/irb/ruby-lex.rb:249:in `each_top_level_statement'",
 "/Users/sajan/.rvm/rubies/ruby-3.1.4/lib/ruby/3.1.0/irb.rb:557:in `eval_input'",
 "/Users/sajan/.rvm/rubies/ruby-3.1.4/lib/ruby/3.1.0/irb.rb:491:in `block in run'",
 "/Users/sajan/.rvm/rubies/ruby-3.1.4/lib/ruby/3.1.0/irb.rb:490:in `catch'",
 "/Users/sajan/.rvm/rubies/ruby-3.1.4/lib/ruby/3.1.0/irb.rb:490:in `run'",
 "/Users/sajan/.rvm/rubies/ruby-3.1.4/lib/ruby/3.1.0/irb.rb:419:in `start'",
 "/Users/sajan/.rvm/rubies/ruby-3.1.4/lib/ruby/gems/3.1.0/gems/irb-1.4.1/exe/irb:11:in `<top (required)>'",
 "/Users/sajan/.rvm/rubies/ruby-3.1.4/bin/irb:25:in `load'",
 "/Users/sajan/.rvm/rubies/ruby-3.1.4/bin/irb:25:in `<main>'"]
"<<<<<<<<<<<"
29700
"==========="
/Users/sajan/.rvm/gems/ruby-3.1.4/gems/zeitwerk-2.6.12/lib/zeitwerk/loader.rb:542:in `block (3 levels) in raise_if_conflicting_directory': loader (Zeitwerk::Error)

#<Zeitwerk::Loader:0x000000010894dc58
 @autoloaded_dirs=[],
 @autoloads={},
 @collapse_dirs=#<Set: {}>,
 @collapse_glob_patterns=#<Set: {}>,
 @dirs_autoload_monitor=#<Monitor:0x000000010894d500>,
 @eager_load_exclusions=#<Set: {}>,
 @eager_loaded=false,
 @ignored_glob_patterns=
  #<Set:
   {"/Users/sajan/projects/gruf/lib/gruf/integrations/rails/railtie.rb",
    "/Users/sajan/projects/gruf/lib/gruf/controllers/health_controller.rb"}>,
 @ignored_paths=
  #<Set:
   {"/Users/sajan/projects/gruf/lib/gruf/integrations/rails/railtie.rb",
    "/Users/sajan/projects/gruf/lib/gruf/controllers/health_controller.rb"}>,
 @inflector=
  #<Zeitwerk::GemInflector:0x000000010894d3e8
   @version_file="/Users/sajan/projects/gruf/lib/gruf/version.rb">,
 @initialized_at=2024-01-20 15:25:20.304969 +0530,
 @logger=nil,
 @mutex=#<Thread::Mutex:0x000000010894d550>,
 @namespace_dirs={},
 @on_load_callbacks={},
 @on_setup_callbacks=[],
 @on_unload_callbacks={},
 @reloading_enabled=false,
 @roots={},
 @setup=false,
 @shadowed_files=#<Set: {}>,
 @tag="gruf",
 @to_unload={}>

wants to manage directory /Users/sajan/projects/gruf/lib, which is already managed by

#<Zeitwerk::Loader:0x00000001088cd1e8
 @autoloaded_dirs=[],
 @autoloads={"/Users/sajan/projects/gruf/lib/gruf.rb"=>[Object, :Gruf]},
 @collapse_dirs=#<Set: {}>,
 @collapse_glob_patterns=#<Set: {}>,
 @dirs_autoload_monitor=#<Monitor:0x00000001088cc810>,
 @eager_load_exclusions=#<Set: {}>,
 @eager_loaded=false,
 @ignored_glob_patterns=
  #<Set:
   {"/Users/sajan/projects/gruf/lib/gruf/integrations/rails/railtie.rb",
    "/Users/sajan/projects/gruf/lib/gruf/controllers/health_controller.rb"}>,
 @ignored_paths=
  #<Set:
   {"/Users/sajan/projects/gruf/lib/gruf/integrations/rails/railtie.rb",
    "/Users/sajan/projects/gruf/lib/gruf/controllers/health_controller.rb"}>,
 @inflector=
  #<Zeitwerk::GemInflector:0x00000001088cc608
   @overrides={},
   @version_file="/Users/sajan/projects/bug/gruf/lib/gruf/version.rb">,
 @initialized_at=2024-01-20 15:25:20.297649 +0530,
 @logger=nil,
 @mutex=#<Thread::Mutex:0x00000001088cc888>,
 @namespace_dirs={"Gruf"=>["/Users/sajan/projects/gruf/lib/gruf"]},
 @on_load_callbacks={},
 @on_setup_callbacks=[],
 @on_unload_callbacks={},
 @reloading_enabled=false,
 @roots={"/Users/sajan/projects/gruf/lib"=>Object},
 @setup=true,
 @shadowed_files=#<Set: {}>,
 @tag="gruf",
 @to_unload={}>

    from /Users/sajan/.rvm/gems/ruby-3.1.4/gems/zeitwerk-2.6.12/lib/zeitwerk/loader.rb:536:in `each_key'
    from /Users/sajan/.rvm/gems/ruby-3.1.4/gems/zeitwerk-2.6.12/lib/zeitwerk/loader.rb:536:in `block (2 levels) in raise_if_conflicting_directory'
    from /Users/sajan/.rvm/gems/ruby-3.1.4/gems/zeitwerk-2.6.12/lib/zeitwerk/loader.rb:532:in `each'
    from /Users/sajan/.rvm/gems/ruby-3.1.4/gems/zeitwerk-2.6.12/lib/zeitwerk/loader.rb:532:in `block in raise_if_conflicting_directory'
    from /Users/sajan/.rvm/gems/ruby-3.1.4/gems/zeitwerk-2.6.12/lib/zeitwerk/loader.rb:529:in `synchronize'
    from /Users/sajan/.rvm/gems/ruby-3.1.4/gems/zeitwerk-2.6.12/lib/zeitwerk/loader.rb:529:in `raise_if_conflicting_directory'
    from /Users/sajan/.rvm/gems/ruby-3.1.4/gems/zeitwerk-2.6.12/lib/zeitwerk/loader/config.rb:122:in `push_dir'
    from /Users/sajan/projects/gruf/lib/gruf.rb:36:in `<top (required)>'
    from <internal:/Users/sajan/.rvm/rubies/ruby-3.1.4/lib/ruby/3.1.0/rubygems/core_ext/kernel_require.rb>:85:in `require'
    from <internal:/Users/sajan/.rvm/rubies/ruby-3.1.4/lib/ruby/3.1.0/rubygems/core_ext/kernel_require.rb>:85:in `require'
    from /Users/sajan/.rvm/gems/ruby-3.1.4/gems/zeitwerk-2.6.12/lib/zeitwerk/kernel.rb:30:in `require'
    from /Users/sajan/projects/bug/gruf/lib/gruf.rb:43:in `<top (required)>'
    from <internal:/Users/sajan/.rvm/rubies/ruby-3.1.4/lib/ruby/3.1.0/rubygems/core_ext/kernel_require.rb>:85:in `require'
    from <internal:/Users/sajan/.rvm/rubies/ruby-3.1.4/lib/ruby/3.1.0/rubygems/core_ext/kernel_require.rb>:85:in `require'
    from (irb):1:in `<main>'
    from /Users/sajan/.rvm/rubies/ruby-3.1.4/lib/ruby/gems/3.1.0/gems/irb-1.4.1/exe/irb:11:in `<top (required)>'
    ... 2 levels...

script:

require 'fileutils'

def duplicate_directory(source_dir, destination_dir)
  FileUtils.mkdir_p(destination_dir)

  Dir.foreach(source_dir) do |entry|
    next if entry == '.' || entry == '..'

    source_path = File.join(source_dir, entry)
    destination_path = File.join(destination_dir, entry)

    if File.directory?(source_path)
      # If entry is a directory, recursively duplicate it
      duplicate_directory(source_path, destination_path)
    else
      # If entry is a file, create a symlink to the original file
      FileUtils.ln_s(File.realpath(source_path), destination_path)
    end
  end
end

source_directory = '/Users/sajan/projects/gruf'
destination_directory = '/Users/sajan/projects/bug/gruf'

duplicate_directory(source_directory, destination_directory)
fxn commented 9 months ago

Good finding!

So, let me summarize:

  1. The project requires "gruf", which, according to $LOAD_PATH, is found at bug/gruf/lib/gruf.rb.
  2. That file is a symlink to the real gruf/lib/gruf.rb.
  3. The entry point correctly sets things up relative to __dir__.
  4. Therefore, Zeitwerk sets autoload calls with absolute paths starting with __dir__.
  5. For Ruby, the autoload target for Gruf (real) and the file being required (symlink) are different.
  6. Hence, Ruby does not discard the autoload.

I have reduced it to this self-contained reproduction script (DELETES a tmp directory relative to the current directory):

require 'fileutils'

FileUtils.rm_rf('tmp')

real_lib = File.expand_path('tmp/gruf/lib')
dupl_lib = File.expand_path('tmp/bug/gruf/lib')

FileUtils.mkdir_p(real_lib)
FileUtils.mkdir_p(dupl_lib)

File.write("#{real_lib}/gruf.rb", <<~'RUBY')
  autoload :Gruf, "#{__dir__}/gruf.rb"
  p autoload?(:Gruf)
RUBY

FileUtils.ln_s("#{real_lib}/gruf.rb", "#{dupl_lib}/gruf.rb")

$LOAD_PATH.unshift(dupl_lib)
require 'gruf'

That prints a string, and if you instead put real_lib in the $LOAD_PATH, it prints the expected nil.

Yes, this does not really seem like an issue with Zeitwerk, because Zeitwerk is operating according to its configuration.

On the other hand, if instead of soft links, you create hard links, then the issue disappears. Can you perhaps explain a bit the purpose of that soft linking?

sajan45 commented 9 months ago

This makes sense. We use Bazel and a few other things to package the gems with the app code to generate a build, so these soft links are created by the Bazel rule. I am still new to this, I will have to check if we can change these to hard links. But do you think there is anything else I can do to make it work, if hard links are not possible due to some reason?

fxn commented 9 months ago

Is that system in place to be able to override files in the duplicated project?

sajan45 commented 9 months ago

Not sure. I will check. I think the problem is __dir__ returns the canonicalized absolute path. But __FILE__ resolves to the path of symlink. So if instead of __dir__ if we use something like loader.push_dir(File.dirname(File.absolute_path(__FILE__))) in the entry point, do you think it will work? Though this works for the reproduction steps with the duplicate directory in the LOAD_PATH, I will have to try this with app actual app tomorrow.

fxn commented 9 months ago

If you can work with a fork, I believe one simple change that could work is to define the Gruf module before the loader is defined. That way, the autoloader will understand Gruf is a namespace, but won't attempt to set an autoload for gruf.rb. This is basically the workaround you have in place moved to the gem.

Alternatively, KISS this and leave things as you have them, depend on the original gem for simplicity, and link to this issue in a comment.

fxn commented 9 months ago

BTW, Ruby makes an effort to match files in some cases. For example, if you require or require_relative files that differ in symlinks, I believe (have not tested this throughly) idempotence will work. None of this is documented, but I guess it is public interface.

In that sense, it could be the case that autoload not recognizing the same file in this situation could be considered to be a bug.

sajan45 commented 9 months ago

Although it's the same file we are not creating a symlink for the directory. I don't know if I understand it correctly but in one of the Ruby issues, I saw a comment "If you symlink the file itself and not the include directory, Ruby will attempt to require it as a separate feature." I am not sure if it will be accepted as a bug. Anyway, I will try to move ahead with the workaround. You can close this now. I appreciate the time you have taken to help me. Thank you.

fxn commented 9 months ago

Yeah, if there are exceptions... This is all a bit brittle, because these features are well-defined if they are string-based, but the moment you want to be clever, ..., it's tricky.

It is a lesson learned, anyway. I appreciate that you stayed and found the root cause of the double load.