The console prevents Zeitwerk from autoloading certain constants

[fxn]

(Originally reported in rails/rails#43691).

The debug console prevents Zeitwerk from autoloading constants that are children of namespaces defined in a file. This script reproduces the issue:

require 'tmpdir'

Dir.mktmpdir do |dir|
  Dir.chdir(dir)

  FileUtils.mkdir_p('lib/git/ref')
  File.write('lib/git/ref.rb', 'module Git::Ref; end')
  File.write('lib/git/ref/collection.rb', 'module Git::Ref::Collection; end')

  File.write('test.rb', <<~EOS)
    require 'zeitwerk'

    loader = Zeitwerk::Loader.new
    loader.push_dir('lib')
    loader.setup

    p Git::Ref::Collection
  EOS

  system 'ruby test.rb'
  system 'rdbg test.rb'
end

1. ruby is able to autoload Git::Ref::Collection just fine.
2. If you type continue in the debug console, test.rb is also executed correctly.
3. If, instead, you next 4 and type eval Git::Ref::Collection you'll get a NameError.
4. Same if you use the irb debugger command and try to evaluate Git::Ref::Collection in that session.

In case it matters, when Zeitwerk finds a file like ref.rb that defines a namespace, it sets a trace point on the :class event, because if the file had this content:

module Git
  module Ref
    Collection
  end
end

it should be able to autoload Git::Ref::Collection on line 3. In order to provide that feature, Zeitwerk listens to :class events, and as soon as the one for Git::Ref is triggered, Zeitwerk lists the contents of all git/ref directories in the root paths, and sets autoloads for what it finds. In this case, it would set an autoload for Collection on the module object stored in Git::Ref.

Problem with byebug was that Ruby does not support nested trace points. Are we in the same situation perhaps?

[st0012]

Problem with byebug was that Ruby does not support nested trace points.

Yeah I think it's the same problem: when using stepping commands (e.g. step or next), the debugger will operate inside a tracepoint callback. And unless the callback leaves, other callbacks (like Zeitwerk's) would be blocked.

In this case, we can see that Zeitwerk's tracepoint_class_callback is disabled after next command is called. I used a slightly tweaked script for this:

require 'tmpdir'

Dir.mktmpdir do |dir|
  Dir.chdir(dir)
  FileUtils.mkdir_p('lib/git/ref/collection')

  File.write('lib/git/ref.rb', 'class Git::Ref; end')
  File.write('lib/git/ref/collection.rb', 'class Git::Ref::Collection; end')
  File.write('lib/git/ref/collection/pagination.rb', 'module Git::Ref::Collection::Pagination; end')

  File.write('test.rb', <<~EOS)
    require 'zeitwerk'

    loader = Zeitwerk::Loader.new
    loader.push_dir('lib')
    loader.setup

    p Git::Ref::Collection::Pagination
  EOS

  system 'rdbg -e "trace call /on_namespace_loaded/ ;; c" test.rb'
  puts "=" * 100
  system 'rdbg -e "trace call /on_namespace_loaded/ ;; next 4 ;; p Git::Ref::Collection ;; c" test.rb'
end

And here is the output:

You can see that without next, the tracer printed on_namespace_loaded calls and the constants were all loaded successfully. But with next 4, those calls disappeared.

I also noticed that if we don't eval the constant from debugger, the script can still find Git::Ref::Collection before exiting:

require 'tmpdir'

Dir.mktmpdir do |dir|
  Dir.chdir(dir)
  FileUtils.mkdir_p('lib/git/ref/collection')

  File.write('lib/git/ref.rb', 'class Git::Ref; end')
  File.write('lib/git/ref/collection.rb', 'class Git::Ref::Collection; end')
  File.write('lib/git/ref/collection/pagination.rb', 'module Git::Ref::Collection::Pagination; end')

  File.write('test.rb', <<~EOS)
    require 'zeitwerk'

    loader = Zeitwerk::Loader.new
    loader.push_dir('lib')
    loader.setup

    p Git::Ref::Collection::Pagination
  EOS

  system "rdbg -e 'next 4 ;; c' test.rb"
  p "=" * 100
  system "rdbg -e 'next 4 ;; p Git::Ref::Collection ;; c' test.rb"
end

I don't have an explanation for this behavior though, as the exception is internally rescued and shouldn't affect any callback to load the constants.

[fxn]

@st0012 that squares with the points (1)–(4) above, right?

The top-level Git namespace is not necessary to reproduce, I've written this simplification:

require 'tmpdir'

Dir.mktmpdir do |dir|
  Dir.chdir(dir)

  FileUtils.mkdir_p('lib/foo')
  File.write('lib/foo.rb', 'module Foo; end')
  File.write('lib/foo/bar.rb', 'Foo::Bar = 1')

  File.write('test.rb', <<~EOS)
    require 'zeitwerk'

    loader = Zeitwerk::Loader.new
    loader.push_dir('lib')
    loader.setup

    p Foo::Bar
  EOS

  system 'ruby test.rb'
  system 'rdbg test.rb'
end

[st0012]

that squares with the points (1)–(4) above, right?

Yes. And thanks for the simplified script. Here are all the scenarios:

====================================================================================================
Pure Ruby execution
====================================================================================================
1
====================================================================================================
Execute with debugger but without any stepping
====================================================================================================
[1, 7] in test.rb
=>   1| require 'zeitwerk'
     2|
     3| loader = Zeitwerk::Loader.new
     4| loader.push_dir('lib')
     5| loader.setup
     6|
     7| p Foo::Bar
=>#0    <main> at test.rb:1
(rdbg:commands) c
1
====================================================================================================
Execute with debugger & stepping but don't eval the constant from REPL
====================================================================================================
[1, 7] in test.rb
=>   1| require 'zeitwerk'
     2|
     3| loader = Zeitwerk::Loader.new
     4| loader.push_dir('lib')
     5| loader.setup
     6|
     7| p Foo::Bar
=>#0    <main> at test.rb:1
(rdbg:commands) next 4
[2, 7] in test.rb
     2|
     3| loader = Zeitwerk::Loader.new
     4| loader.push_dir('lib')
     5| loader.setup
     6|
=>   7| p Foo::Bar
=>#0    <main> at test.rb:7
(rdbg:commands) c
1
====================================================================================================
Execute with debugger & stepping and eval the constant from REPL
====================================================================================================
[1, 7] in test.rb
=>   1| require 'zeitwerk'
     2|
     3| loader = Zeitwerk::Loader.new
     4| loader.push_dir('lib')
     5| loader.setup
     6|
     7| p Foo::Bar
=>#0    <main> at test.rb:1
(rdbg:commands) next 4
[2, 7] in test.rb
     2|
     3| loader = Zeitwerk::Loader.new
     4| loader.push_dir('lib')
     5| loader.setup
     6|
=>   7| p Foo::Bar
=>#0    <main> at test.rb:7
(rdbg:commands) p Foo::Bar
eval error: uninitialized constant Foo::Bar
  (rdbg)/test.rb:1:in `<main>'
=> nil
(rdbg:commands) c
test.rb:7:in `<main>': uninitialized constant Foo::Bar (NameError)

So to conclude: using stepping commands like next doesn't necessarily cause the issue. But using stepping commands and accessing the constant from REPL will fail and also block the program from accessing it.

[fxn]

If this seems like a fundamental incompatibility whose root cause is that limitation in Ruby, I would be happy to consider it so, document this gotcha in Zeitwerk docs, and close this issue.

What do you think?

[st0012]

@fxn I think there are 2 problems here: 1) the constant isn't accessible from the console and 2) the constant isn't accessible after 1) happened.

For 1), I think it's a Ruby limitation and there's much we can do, at least for current Ruby versions. @ko1 will this be addressed in the future?

Regarding 2), I'm not familiar with Ruby's constant loading but I guess it could be caused by constant missing result being cached? If that's the case, I guess we can still try invalidating that cache and let the program load the constant?

[fxn]

@st0012 to understand 2) you need to understand how Zeritwerk works for that kind of namespaces. Let me explain.

Zeitwerk first scans the top-level and sees there's a file foo.rb and also a directory foo. OK, it does the following:

1. Executes Object.autoload(:Foo, '/absolute/path/to/foo.rb').
2. Enables a tracepoint that will watch for Foo.

Now, if the user program hits Foo and gets autoloaded, the block of the tracepoint is triggered. In that callback, Zeitwerk scans folders called foo (in this case there is only one), and defines autoloads for what it finds. In this case, the callback will execute Foo.autoload(:Bar, '/absolute/path/to/foo/bar.rb').

Now, since that callback is not invoked because debug tracepoint shadows it, nobody is defining any autoload for Foo::Bar. Therefore, the constant won't be ever resolved successfully, there's no Module#autoload set for it. Zeitwerk could not run the code that would have defined it.

See?

[st0012]

Thanks for the explanation.

Now, since that callback is not invoked because debug tracepoint shadows it, nobody is defining any autoload for Foo::Bar.

But that doesn't explain why this scenario would work:

====================================================================================================
Execute with debugger & stepping but don't eval the constant from REPL
====================================================================================================
[1, 7] in test.rb
=>   1| require 'zeitwerk'
     2|
     3| loader = Zeitwerk::Loader.new
     4| loader.push_dir('lib')
     5| loader.setup
     6|
     7| p Foo::Bar
=>#0    <main> at test.rb:1
(rdbg:commands) next 4
[2, 7] in test.rb
     2|
     3| loader = Zeitwerk::Loader.new
     4| loader.push_dir('lib')
     5| loader.setup
     6|
=>   7| p Foo::Bar
=>#0    <main> at test.rb:7
(rdbg:commands) c
1

I used both tracers and breakpoints to track the calls, and

[2, 8] in test.rb
     2|
     3| loader = Zeitwerk::Loader.new
     4| loader.push_dir('lib')
     5| loader.setup
     6|
=>   7| a = 1
     8| p Foo::Bar
=>#0    <main> at test.rb:7
(rdbg:commands) c
DEBUGGER (trace/call) #th:1 #depth:2 >  Kernel#require at /Users/st0012/.rbenv/versions/3.0.2/lib/ruby/gems/3.0.0/gems/zeitwerk-2.4.2/lib/zeitwerk/kernel.rb:23
DEBUGGER (trace/call) #th:1 #depth:3 >   Zeitwerk::Registry.loader_for at /Users/st0012/.rbenv/versions/3.0.2/lib/ruby/gems/3.0.0/gems/zeitwerk-2.4.2/lib/zeitwerk
/registry.rb:119

It looks like p Foo::Bar would call Kernel#require and then finish the constant loading in this scenario. But I have no idea how that could be possible. Here's the caller output from that require call:

[ 
  #...
 "/Users/st0012/.rbenv/versions/3.0.2/lib/ruby/gems/3.0.0/gems/zeitwerk-2.4.2/lib/zeitwerk/kernel.rb:24:in `require'",
 "test.rb:8:in `<main>'"] # <= the `p Foo::Bar` line

Do you know how that could happen?

[fxn]

@st0012 Guess I need to know more about the debugger to understand why is that one puzzling. Why is that different from your example "Execute with debugger but without any stepping"?

[fxn]

@st0012 Let me detail how that works when things load as expected:

1. When you execute loader.setup, Zeitwerk does a first-level scan of the root directories.
2. In that scan it finds foo.rb, and runs Object.autoload(:Foo, '/absolute/path/to/lib/foo.rb').
3. It also notices that there is a directory called foo and enables the tracepoint.

All that happens in the line loader.setup.

When we hit p Foo::Bar. This happens:

1. Ruby performs a relative constant lookup for Foo. It sees the defined autoload and executes a require for /absolute/path/to/lib/foo.rb.
2. Zeitwerk's thin wrapper around Kernel#require (source code) says: hey, I manage that file.
3. The original Kernel#require is invoked, and that defines the Foo module.
4. Therefore, right when module Foo has been interpreted, the tracepoint is triggered. We say, "Foo! That is a namespace I need to put autoloads for right now, before the rest of foo.rb is interpreted". The tracepoint callback scans the foo directory, and executes Foo.autoload(:Bar, '/absolute/path/to/lib/foo/bar.rb'). All done, continue.
5. When the original Kernel#require returns all that has already happened, Zeitwerk does some housekeeping related to foo.rb.

At this point, we have only evaluated Foo in Foo::Bar. Now is the time for Bar:

1. Since Foo returns a module, Ruby is able to do a constant lookup for Bar scoped by Foo.
2. Ruby notices there is an autoload for it, and executes a require call for the configured file.
3. The thin wrapper says again, hey, I manage that file.
4. Delegates to the original Kernel#require.
5. Performs housekeeping about /absolute/path/to/lib/foo/bar.rb.

Maybe that was super clear already, in that case please disregard all this :), but since there's something you consider to be odd, I wanted to link autoloading, the tracepoint, and the require calls to connect all the dots in case that helps.

[st0012]

Thanks for the very detailed explanation. I learned a lot from it ❤️

What confuses me is that I can't locate the exact debugger tracepoint that shadows Zeitwek's. I think the current suspect would be the tracepoint that's used by the next command, right? Which would be:

debug/lib/debug/thread_client.rb

Lines 303 to 315 in 8619be2

	@step_tp = TracePoint.new(*events){|tp|
	next if SESSION.break_at? tp.path, tp.lineno
	next if !yield(tp.event)
	next if tp.path.start_with?(__dir__)
	next if tp.path.start_with?('<internal:trace_point>')
	next unless File.exist?(tp.path) if CONFIG[:skip_nosrc]
	loc = caller_locations(1, 1).first
	next if skip_location?(loc)
	next if iter && (iter -= 1) > 0
	tp.disable
	suspend tp.event, tp
	}

But from my testing, it should already be disabled before Foo is evaluated:

[1, 7] in test.rb
=>   1| require 'zeitwerk'
     2|
     3| loader = Zeitwerk::Loader.new
     4| loader.push_dir('lib')
     5| loader.setup
     6|
     7| p Foo::Bar
=>#0    <main> at test.rb:1
(rdbg:commands) next 4
"==================== skip line test.rb:3:in `<main>' ====================="
"==================== skip line test.rb:4:in `<main>' ====================="
"==================== skip line test.rb:5:in `<main>' ====================="
"==================== skip line test.rb:7:in `<main>' ====================="
"==================== tp disabled ====================="
[2, 7] in test.rb
     2|
     3| loader = Zeitwerk::Loader.new
     4| loader.push_dir('lib')
     5| loader.setup
     6|
=>   7| p Foo::Bar
=>#0    <main> at test.rb:7
(rdbg:commands) p Foo::Bar
eval error: uninitialized constant Foo::Bar
  (rdbg)/test.rb:1:in `<main>'
=> nil
(rdbg:commands) c
test.rb:7:in `<main>': uninitialized constant Foo::Bar (NameError)

Script change:

          next if skip_location?(loc)
+          pp("==================== skip line #{loc} =====================")
          next if iter && (iter -= 1) > 0

          tp.disable
+          pp("==================== tp disabled =====================")

To confirm that this tracepoint isn't the cause of the issue, we can see another example (the one I posted in the prev question):

[1, 7] in test.rb
=>   1| require 'zeitwerk'
     2|
     3| loader = Zeitwerk::Loader.new
     4| loader.push_dir('lib')
     5| loader.setup
     6|
     7| p Foo::Bar
=>#0    <main> at test.rb:1
(rdbg:commands) next 4
"==================== skip line test.rb:3:in `<main>' ====================="
"==================== skip line test.rb:4:in `<main>' ====================="
"==================== skip line test.rb:5:in `<main>' ====================="
"==================== skip line test.rb:7:in `<main>' ====================="
"==================== tp disabled ====================="
[2, 7] in test.rb
     2|
     3| loader = Zeitwerk::Loader.new
     4| loader.push_dir('lib')
     5| loader.setup
     6|
=>   7| p Foo::Bar
=>#0    <main> at test.rb:7
(rdbg:commands) c
1 # <= the constant is resolved

But if that tracepoint isn't the one that shadows Zeitwerk's, I don't think there's any other tracepoint would do that.

What seems to make a difference here is the p Foo::Bar evaluation instead. I hope this clarifies my concern here.

[st0012]

@fxn Ah! Sorry that my previous comment was incorrect. The tracepoint is disabled but the session haven't left its block, which stays at the suspend call here:

https://github.com/ruby/debug/blob/master/lib/debug/thread_client.rb#L314

Yeah so I can confirm that it's purely an tracepoint shadowing issue. Sorry for taking your extra time on explaining things repeatedly 🙇

[fxn]

Fantastic! Super that it was understood, please count on me for anything ❤️.

[st0012]

@fxn do you think we should document this gotcha in the debugger readme as well? or this issue will be enough as the future reference for other TracePoint-powered libraries?

[fxn]

@st0012 it's an edge case, but if users should know about it in case it affects them, I personally believe the README should proactively warn about it. Maybe just a brief discrete section down the bottom. Zeitwerk has a section about debuggers too.

[brasic]

👋 from the original reporter of this issue!

Perhaps I've misread the thread but it seems to me that this is a fairly fundamental conflict between the two gems that might be difficult to resolve without changes to the semantics of tracepoints.

Given that this issue significantly reduces the utility of the debug gem with rails dev environments¹, perhaps it would be worth reconsidering the use of the proposed Module#const_added callback for zeitwerk.

@fxn If you are supportive I'd be happy to advocate for this change in ruby and to volunteer to implement the necessary change in Zeitwerk to use the const_added callback rather than tracepoint when available.

Footnotes

1. For example, the github monolith is not usable in dev mode with debug or byebug because it uses zeitwerk and encounters this issue with nearly any nontrivial expression. I believe that this is not unique to github/github: most real world rails apps that use zeitwerk will not be able to use debug in dev mode. ↩