turbo-rails: Zeitwerk throws a LoadError of cannot load such file for turbo-rails-1.0.0/app/channels/turbo/streams when RAILS_ENV=production is set while using Sidekiq

Hi,

Edit: The scope of this issue has changed to affect every Active Job running through Sidekiq and it also affects all environments. The first reply to this issue has more details. I left the original issue here for extra context which is still worth reading.

I recently updated an example Rails app to use Rails 7 (from Rails 6). After doing that Sidekiq will no longer start successfully when RAILS_ENV=production is set but it starts successfully with RAILS_ENV=development.

This gem comes up as a potential culprit but it’s too soon to say if it’s a bug with this gem. I haven’t seen anything similar to this type of error previously (I wasn’t using zeitwerk with Rails 6.x).

Here’s the turbo-rails related stack trace:

worker_1    | 2021-12-18T15:43:09.829Z pid=1 tid=2ut INFO: Booting Sidekiq 6.3.1 with redis options {:url=>"redis://redis:6379/1"}
worker_1    | /usr/local/bundle/gems/zeitwerk-2.5.1/lib/zeitwerk/loader/helpers.rb:95:in `require': cannot load such file -- /usr/local/bundle/gems/turbo-rails-1.0.0/app/channels/turbo/streams (LoadError)
worker_1    |   from /usr/local/bundle/gems/zeitwerk-2.5.1/lib/zeitwerk/loader/helpers.rb:95:in `const_get'
worker_1    |   from /usr/local/bundle/gems/zeitwerk-2.5.1/lib/zeitwerk/loader/helpers.rb:95:in `cget'
worker_1    |   from /usr/local/bundle/gems/zeitwerk-2.5.1/lib/zeitwerk/loader.rb:239:in `block (2 levels) in eager_load'
worker_1    |   from /usr/local/bundle/gems/zeitwerk-2.5.1/lib/zeitwerk/loader/helpers.rb:26:in `block in ls'
worker_1    |   from /usr/local/bundle/gems/zeitwerk-2.5.1/lib/zeitwerk/loader/helpers.rb:18:in `each_child'
worker_1    |   from /usr/local/bundle/gems/zeitwerk-2.5.1/lib/zeitwerk/loader/helpers.rb:18:in `ls'
worker_1    |   from /usr/local/bundle/gems/zeitwerk-2.5.1/lib/zeitwerk/loader.rb:227:in `block in eager_load'
worker_1    |   from /usr/local/bundle/gems/zeitwerk-2.5.1/lib/zeitwerk/loader.rb:212:in `synchronize'
worker_1    |   from /usr/local/bundle/gems/zeitwerk-2.5.1/lib/zeitwerk/loader.rb:212:in `eager_load'
worker_1    |   from /usr/local/bundle/gems/zeitwerk-2.5.1/lib/zeitwerk/loader.rb:312:in `each'
worker_1    |   from /usr/local/bundle/gems/zeitwerk-2.5.1/lib/zeitwerk/loader.rb:312:in `eager_load_all'
worker_1    |   from /usr/local/bundle/gems/railties-7.0.0/lib/rails/application/finisher.rb:79:in `block in <module:Finisher>'
worker_1    |   from /usr/local/bundle/gems/railties-7.0.0/lib/rails/initializable.rb:32:in `instance_exec'
worker_1    |   from /usr/local/bundle/gems/railties-7.0.0/lib/rails/initializable.rb:32:in `run'
worker_1    |   from /usr/local/bundle/gems/railties-7.0.0/lib/rails/initializable.rb:61:in `block in run_initializers'
worker_1    |   from /usr/local/lib/ruby/3.0.0/tsort.rb:228:in `block in tsort_each'
worker_1    |   from /usr/local/lib/ruby/3.0.0/tsort.rb:350:in `block (2 levels) in each_strongly_connected_component'
worker_1    |   from /usr/local/lib/ruby/3.0.0/tsort.rb:431:in `each_strongly_connected_component_from'
worker_1    |   from /usr/local/lib/ruby/3.0.0/tsort.rb:349:in `block in each_strongly_connected_component'
worker_1    |   from /usr/local/lib/ruby/3.0.0/tsort.rb:347:in `each'
worker_1    |   from /usr/local/lib/ruby/3.0.0/tsort.rb:347:in `call'
worker_1    |   from /usr/local/lib/ruby/3.0.0/tsort.rb:347:in `each_strongly_connected_component'
worker_1    |   from /usr/local/lib/ruby/3.0.0/tsort.rb:226:in `tsort_each'
worker_1    |   from /usr/local/lib/ruby/3.0.0/tsort.rb:205:in `tsort_each'
worker_1    |   from /usr/local/bundle/gems/railties-7.0.0/lib/rails/initializable.rb:60:in `run_initializers'
worker_1    |   from /usr/local/bundle/gems/railties-7.0.0/lib/rails/application.rb:369:in `initialize!'
worker_1    |   from /app/config/environment.rb:5:in `<top (required)>'
worker_1    |   from <internal:/usr/local/lib/ruby/3.0.0/rubygems/core_ext/kernel_require.rb>:148:in `require'
worker_1    |   from <internal:/usr/local/lib/ruby/3.0.0/rubygems/core_ext/kernel_require.rb>:148:in `require'
worker_1    |   from /usr/local/bundle/gems/zeitwerk-2.5.1/lib/zeitwerk/kernel.rb:35:in `require'
worker_1    |   from /usr/local/bundle/gems/sidekiq-6.3.1/lib/sidekiq/cli.rb:273:in `boot_application'
worker_1    |   from /usr/local/bundle/gems/sidekiq-6.3.1/lib/sidekiq/cli.rb:37:in `run'
worker_1    |   from /usr/local/bundle/gems/sidekiq-6.3.1/bin/sidekiq:31:in `<top (required)>'
worker_1    |   from /usr/local/bundle/bin/sidekiq:25:in `load'
worker_1    |   from /usr/local/bundle/bin/sidekiq:25:in `<main>'
hellorails_worker_1 exited with code 1

The application is running within Docker and it’s open source at https://github.com/nickjj/docker-rails-example which should provide a reproduceable test case based on the latest main branch. There’s a quick getting started guide for the app at https://github.com/nickjj/docker-rails-example#running-this-app which ultimately comes down to running a few commands.

If I exec into the worker container I’m able to stat /usr/local/bundle/gems/turbo-rails-1.0.0/app/channels/turbo/streams which returns back that the directory does exist as seen below:

ruby@97b98bc1dd6b:/app$ stat /usr/local/bundle/gems/turbo-rails-1.0.0/app/channels/turbo/streams
  File: /usr/local/bundle/gems/turbo-rails-1.0.0/app/channels/turbo/streams
  Size: 4096            Blocks: 8          IO Block: 4096   directory
Device: bdh/189d        Inode: 290588      Links: 2
Access: (0755/drwxr-xr-x)  Uid: ( 1000/    ruby)   Gid: ( 1000/    ruby)
Access: 2021-12-18 15:26:58.040000000 +0000
Modify: 2021-12-18 15:26:29.950000000 +0000
Change: 2021-12-18 15:26:55.900000000 +0000
 Birth: 2021-12-18 15:26:55.900000000 +0000

What’s weird is the error mentions cannot load such file but that path it not a file, it’s a directory on disk.

What’s also interesting is the web, worker and cable containers that are a part of the project all use an identical Dockerfile and the only difference is the command that gets run (such as puma or sidekiq). Both the web and cable containers come up fine. It’s only worker that fails.

Running the same stat command in the web and cable containers produce the same output.

I’m tracking the issue in my repo at https://github.com/nickjj/docker-rails-example/issues/30.

I’m not sure where else to post this. I’m also not sure how autoloading works under the hood. If paths are loaded alphabetically I’m taking a guess here that other gem paths were successfully loaded and it failed when it got to turbo-rails?

About this issue

Original URL
State: closed
Created 3 years ago
Reactions: 1
Comments: 28 (14 by maintainers)

Commits related to this issue

Fix Zeitwerk load error with Sidekiq This was reported as a potential fixed based on: https://github.com/hotwired/turbo-rails/issues/285#issuecomment-1004395809 The root cause isn't known at the t... — committed to nickjj/docker-rails-example by nickjj 2 years ago

Most upvoted comments

I had this exact problem, and resolved it by using bundle exec sidekiq (instead of just sidekiq) to start that process. It looks like you’re using the latter form as your Docker Compose command. HTH!

rwrrll on Jan 3, 2022

I have inspected a sample of gems that load with Zeitwerk:

The vast majority of them instantiate their loader with for_gem.
Some have extra Ruby files or directories under lib. Examples: generators, tasks, or core_extensions.
From those, some properly ignore them, but some overlooked doing this.

This, and our thread, tell me that checking for these extras is worthwhile. I have implemented this feature in https://github.com/fxn/zeitwerk/commit/f1c1b59d7a1338c5b50505770dd6f6c248990950. You get a warning if there are extra non-ignored Ruby files or directories under lib, and the warning itself tells you the options you have to address it.

This issue was already closed, and after this it is double closed 😀.

fxn on May 1, 2022

Hey!

we also excluded the generators for the same reason

Excluding from eager loading is not enough. You have to ignore the directory.

If you exclude, you are still telling the loader that it is managing the directory, that the directory is a namespace, and that it should define a constant Generators. The only detail is that you don’t want to have it eager loaded. If you inspect Object.constants you’ll see Generators there, and it should not be because that directory does not represent a namespace.

On the other hand, ignoring means: you are not managing this at all, ignore it for all purposes. This is what you want.

there would be a way to display a warning on the console, because the error is completely unrelated and makes it very hard to tackle down.

It is unfortunate and difficult to understand, yes. Very rare to hit it also, though. I can’t think of a reasonable way to warn that does not imply monkey-patching Bundler, which I think would be a bad idea. Someone else is removing my methods! What we really need is this to be fixed upstream.

should the generators folder always be excluded for gems?

This is a good question.

Take into account that Zeitwerk knows nothing about Rails, generators is not special. All you got is a generic gem. Look at your gem, it is not even defining the conventional namespace. What can you assume? Little.

However, it could be the case that extra directories in lib are not mean to be namespaces most of the time in gems. That would justify documentation/warnings. But then you need interface that fits well to be able to silence the warning if the directory is legit.

I’ll think about it.

fxn on Apr 25, 2022

Followup.

As discussed, in a project managed by Bundler you need to bundle exec executables, since the operating system could have a different Sidekiq, or a different Rails, than the one in the Gemfile (the require "rails" in Sidekiq could load a different Rails version than the one present in the Gemfile, you know).

However, being pragmatic, I have patched Rails (https://github.com/rails/rails/commit/9b61af817911849d92aa5d3c7d9e0eabe651a47c) to delay loading Zeitwerk just a tad, so that a mere require "rails" does not load the gem. You need to instantiate an application. It’s all internal, public interface stays the same. That will ship with 7.0.1.

fxn on Jan 5, 2022

OK, I am closer to the root cause, and I have been able to reproduce with a minimal Ruby script that does not depend on Rails.

The command sidekiq loads rails here. That happens before the application boots, and therefore before Bundler is setup in config/boot.rb.

With that loading order, the Kernel#require wrapper installed by Zeitwerk is no longer invoked. Ever. We saw it with this error, but it is not invoked for autoloaded files either. It is either removed by Bundler or totally hijacked.

Why wasn’t this happening before? Because in Rails 7 rails.rb loads zeitwerk, since it defines the method Rails.autoloaders. In Rails 6.x loading was artificially delayed as much as possible because if you opted for classic, absolutely everything should be like in Rails 5.

So, the problem is loading zeitwerk before you setup Bundler, and this can be seen in this script:

require 'fileutils'
require 'tmpdir'

# UNCOMMENT THE FOLLOWING LINE TO REPRODUCE.
# require 'zeitwerk'

require 'bundler/inline'
gemfile do
  source 'https://rubygems.org'
  gem 'zeitwerk'
end

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

  FileUtils.mkdir_p('lib/admin')
  File.write('lib/foo.rb', 'Foo = 1')

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

  p Foo
  p Admin
end

If you run the script as is, you’ll see:

Foo is loaded and you see the loader activity logged.
Admin is loaded and you see the loader activity logged.

If you uncomment the require in line 5 (therefore, installing Zeitwerk’s require decorator before Bundler enters the game):

Foo is loaded and you DO NOT see the loader activity logged.
Admin is not loaded.

Both (1) and (2) are telling us the decorator is not invoked.

In the case of (1), we see it because the traces are missing. If the application had callbacks, for example, they would not be called.

(2) is what this issue detected, but it could have been (1) as well.

Next step now is to understand who hijacks the require wrapper and why.

fxn on Jan 5, 2022