search

fxn / zeitwerk

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

Modules don't get autovivified #159

Closed enthusiasmus closed 3 years ago

enthusiasmus commented 3 years ago

Dear maintainer,

I try to update our application to rails 6.0.3.3 which uses zeitwerk 2.4.2

I need to define

module Cache
end

additional to

module Cache
  class Base
  ...

to be able to execute the following spec

describe Cache::Base do
...

otherwise is raises an 

Zeitwerk::NameError:
  expected file /usr/src/app/app/lib/cache.rb to define constant Cache, but didn't

My settings are:

[12] pry(main)> Rails.configuration.autoloader
=> :zeitwerk
[13] pry(main)> Rails.configuration.autoload_paths
=> ["/usr/src/app/previews", "/usr/src/app/app/components"]

The module should get autovivified, but it doesn't. Any ideas? Thx! Best regards

fxn commented 3 years ago

Could you please inspect the autoloader to help me understand the setup? What does

bin/rails r 'pp Rails.autoloaders.main'

print?

enthusiasmus commented 3 years ago

It prints the following (I removed the irrelevant parts):

root@6b77cf5ce56f:/usr/src/app# bin/rails r 'pp Rails.autoloaders.main'

Running via Spring preloader in process 72
#<Zeitwerk::Loader:0x0000560635bd5c68
 @autoloaded_dirs=
  [
   ...,
   "/usr/src/app/app/lib/ability/roles/helpers",
   "/usr/src/app/app/lib/ability/roles/rules",
   "/usr/src/app/app/lib/dyn",
   "/usr/src/app/app/lib/cloudimage",
   ... 
  ],
 @autoloads=
  {
   ...
   "/usr/src/app/app/controllers/application_controller.rb"=>[Object, :ApplicationController],
   ...
   "/usr/src/app/app/helpers/nationwide_helper.rb"=>[Object, :NationwideHelper],
   ...
   "/usr/src/app/app/lib/cache"=>[Object, :Cache],
   ...
   "/usr/src/app/app/model/audit.rb"=>[Object, :Audit],
   ...
   "/usr/src/app/app/mailers/previews/mailer_preview.rb"=>
   ...
   "/usr/src/app/app/lib/brand/cache.rb"=>
    [Brand (call 'Brand.connection' to establish a connection), :Cache],
   ...
 @collapse_dirs=#<Set: {}>,
 @collapse_glob_patterns=#<Set: {}>,
 @eager_load_exclusions=
  #<Set: {
   "/usr/src/app/lib/core/lib",
   "/usr/src/app/app/mailers/previews"}>,
 @eager_loaded=false,
 @ignored_glob_patterns=#<Set: {}>,
 @ignored_paths=#<Set: {}>,
 @inflector=ActiveSupport::Dependencies::ZeitwerkIntegration::Inflector,
 @initialized_at="2021-04-23T10:37:16.826+02:00",
 @lazy_subdirs=
  {
    ...
    "Cache"=>["/usr/src/app/app/lib/cache"],
    ...
  },
 @logger=nil,
 @mutex=#<Thread::Mutex:0x0000560635bd52b8>,
 @mutex2=#<Thread::Mutex:0x0000560635bd5268>,
 @on_load_callbacks={},
 @preloads=[],
 @reloading_enabled=true,
 @root_dirs=
  {
    ...
   "/usr/src/app/app/lib"=>Object,
    ...
  }
 @setup=true,
 @tag="rails.main",
 @to_unload=
  {
    ...
  }

Maybe app/lib/cache shouldn't be listed in the lazy_subdirs?

fxn commented 3 years ago

I am mostly interested in the autoload paths, could you paste the whole collection please?

fxn commented 3 years ago

(They are the contents of @root_dirs in the inspection above.)

enthusiasmus commented 3 years ago

Of course! Here are the root_dirs

@root_dirs=
  {"/usr/src/app/app/components"=>Object,
   "/usr/src/app/app/concerns"=>Object,
   "/usr/src/app/app/controllers"=>Object,
   "/usr/src/app/app/decorators"=>Object,
   "/usr/src/app/app/flat_namespace"=>Object,
   "/usr/src/app/app/helpers"=>Object,
   "/usr/src/app/app/jobs"=>Object,
   "/usr/src/app/app/lib"=>Object,
   "/usr/src/app/app/mailers"=>Object,
   "/usr/src/app/app/model"=>Object,
   "/usr/src/app/app/models"=>Object,
   "/usr/src/app/app/validators"=>Object,
   "/usr/src/app/app/webpacker"=>Object,
   "/usr/src/app/app/workers"=>Object,
   "/usr/src/app/lib/spree_gem/core/lib"=>Object,
   "/usr/src/app/lib/spree_gem/core/app/models"=>Object,
   "/usr/local/bundle/gems/actiontext-6.0.3.3/app/helpers"=>Object,
   "/usr/local/bundle/gems/actiontext-6.0.3.3/app/models"=>Object,
   "/usr/local/bundle/gems/actionmailbox-6.0.3.3/app/controllers"=>Object,
   "/usr/local/bundle/gems/actionmailbox-6.0.3.3/app/jobs"=>Object,
   "/usr/local/bundle/gems/actionmailbox-6.0.3.3/app/models"=>Object,
   "/usr/local/bundle/gems/activestorage-6.0.3.3/app/controllers"=>Object,
   "/usr/local/bundle/gems/activestorage-6.0.3.3/app/controllers/concerns"=>
    Object,
   "/usr/local/bundle/gems/activestorage-6.0.3.3/app/jobs"=>Object,
   "/usr/local/bundle/gems/activestorage-6.0.3.3/app/models"=>Object,
   "/usr/src/app/app/mailers/previews"=>Object},
fxn commented 3 years ago

Thanks! Next step:

  1. Edit config/application.rb and add Rails.autoloaders.log! right after loading the framework defaults.
  2. Execute bin/rails r Cache.

What's the output?

enthusiasmus commented 3 years ago 
root@6b77cf5ce56f:/usr/src/app# bin/rails r Cache
Running via Spring preloader in process 251
Zeitwerk@rails.main: module Cache autovivified from directory /usr/src/app/app/lib/cache
Zeitwerk@rails.main: autoload set for Cache::Products, to be loaded from /usr/src/app/app/lib/cache/products.rb
Zeitwerk@rails.main: autoload set for Cache::Base, to be loaded from /usr/src/app/app/lib/cache/base.rb
Zeitwerk@rails.main: autoload set for Cache::Sales, to be loaded from /usr/src/app/app/lib/cache/sales.rb
enthusiasmus commented 3 years ago

when executing the spec above without defined module

root@6b77cf5ce56f:/usr/src/app# rspec spec/lib/cache/base_spec.rb 
Running via Spring preloader in process 257
....

An error occurred while loading ./spec/lib/cache/base_spec.rb. - Did you mean?
                    rspec ./spec/lib/cache/sales_spec.rb
                    rspec ./spec/lib/batch/task_spec.rb
                    rspec ./spec/lib/lab/base_spec.rb

Failure/Error:
  describe Cache::Base do
    describe "#initialize" do
      ...

LoadError:
  cannot load such file -- /usr/src/app/app/lib/cache
# /usr/local/bundle/gems/bootsnap-1.7.3/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:23:in `require'
# /usr/local/bundle/gems/bootsnap-1.7.3/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:23:in `block in require_with_bootsnap_lfi'
# /usr/local/bundle/gems/bootsnap-1.7.3/lib/bootsnap/load_path_cache/loaded_features_index.rb:92:in `register'
# /usr/local/bundle/gems/bootsnap-1.7.3/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:22:in `require_with_bootsnap_lfi'
# /usr/local/bundle/gems/bootsnap-1.7.3/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:31:in `require'
# /usr/local/bundle/gems/zeitwerk-2.4.2/lib/zeitwerk/kernel.rb:34:in `require'
# ./spec/lib/cache/base_spec.rb:5:in `<main>'
# /usr/local/bundle/gems/bootsnap-1.7.3/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:59:in `load'
# /usr/local/bundle/gems/bootsnap-1.7.3/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:59:in `load'
# /usr/local/bundle/gems/bootsnap-1.7.3/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:59:in `load'
# /usr/local/bundle/gems/bootsnap-1.7.3/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:59:in `load'
# /usr/local/bundle/gems/spring-commands-rspec-1.0.4/lib/spring/commands/rspec.rb:18:in `call'
# -e:1:in `<main>'
No examples found.
fxn commented 3 years ago

Does that mean that runner finds Cache::Base in development mode but the spec does not?

fxn commented 3 years ago

I'd like to see the log printed in a situation in which the constant is not found.

enthusiasmus commented 3 years ago

I executed the spec with following changes

root@6b77cf5ce56f:/usr/src/app# git diff
diff --git a/config/application.rb b/config/application.rb
index 3152bd84e..23ae73b30 100644
--- a/config/application.rb
+++ b/config/application.rb
@@ -11,6 +11,8 @@ module Atalanda
   class Application < Rails::Application
     config.load_defaults 6.0

+    Rails.autoloaders.log!
+
     # Require `belongs_to` associations by default. Previous versions had false.
     config.active_record.belongs_to_required_by_default = false

diff --git a/spec/lib/cache/base_spec.rb b/spec/lib/cache/base_spec.rb
index 092b2247f..cbe12d5de 100644
--- a/spec/lib/cache/base_spec.rb
+++ b/spec/lib/cache/base_spec.rb
@@ -2,6 +2,8 @@

 require "rails_helper"

+pp Rails.autoloaders.main
+
 describe Cache::Base do
   describe "#initialize" do

it prints the following:

#<Zeitwerk::Loader:0x000055c67514c418
 @autoloaded_dirs=
  ["/usr/src/app/app/lib/cloudimage",
   ...
   "/usr/src/app/app/lib/shipping_services",
   "/usr/src/app/app/lib/dyn",
 ],
 @autoloads=
  {...
   "/usr/src/app/app/lib/brand/cache.rb"=>
    [Brand(id: integer, name: string, logo_file_name: string, logo_content_type: string, logo_file_size: integer, logo_updated_at: datetime, detail_image_file_name: string, detail_image_content_type: string, detail_image_file_size: integer, detail_image_updated_at: datetime, created_at: datetime, updated_at: datetime, identifier: string, aliases: json),
     :Cache],
  },
 @collapse_dirs=#<Set: {}>,
 @collapse_glob_patterns=#<Set: {}>,
 @eager_load_exclusions=#<Set: {"/usr/src/app/lib/spree_gem/core/lib"}>,
 @eager_loaded=false,
 @ignored_glob_patterns=#<Set: {}>,
 @ignored_paths=#<Set: {}>,
 @inflector=ActiveSupport::Dependencies::ZeitwerkIntegration::Inflector,
 @initialized_at="2021-04-23T12:40:46.295+02:00",
 @lazy_subdirs=
  {...
   "Cache"=>["/usr/src/app/app/lib/cache"],
   ...
  },
 @logger=
  #<Proc:0x000055c6751a3e70@/usr/local/bundle/gems/zeitwerk-2.4.2/lib/zeitwerk/loader.rb:459 (lambda)>,
 @mutex=#<Thread::Mutex:0x000055c6751a3ee8>,
 @mutex2=#<Thread::Mutex:0x000055c6751a3ec0>,
 @on_load_callbacks={},
 @preloads=[],
 @reloading_enabled=false,
 @root_dirs=
  {"/usr/src/app/app/components"=>Object,
   "/usr/src/app/app/concerns"=>Object,
   "/usr/src/app/app/controllers"=>Object,
   "/usr/src/app/app/decorators"=>Object,
   "/usr/src/app/app/flat_namespace"=>Object,
   "/usr/src/app/app/helpers"=>Object,
   "/usr/src/app/app/jobs"=>Object,
   "/usr/src/app/app/lib"=>Object,
   "/usr/src/app/app/mailers"=>Object,
   "/usr/src/app/app/model"=>Object,
   "/usr/src/app/app/models"=>Object,
   "/usr/src/app/app/validators"=>Object,
   "/usr/src/app/app/webpacker"=>Object,
   "/usr/src/app/app/workers"=>Object,
   "/usr/src/app/lib/spree_gem/core/lib"=>Object,
   "/usr/src/app/lib/spree_gem/core/app/models"=>Object,
   "/usr/local/bundle/gems/actiontext-6.0.3.3/app/helpers"=>Object,
   "/usr/local/bundle/gems/actiontext-6.0.3.3/app/models"=>Object,
   "/usr/local/bundle/gems/actionmailbox-6.0.3.3/app/controllers"=>Object,
   "/usr/local/bundle/gems/actionmailbox-6.0.3.3/app/jobs"=>Object,
   "/usr/local/bundle/gems/actionmailbox-6.0.3.3/app/models"=>Object,
   "/usr/local/bundle/gems/activestorage-6.0.3.3/app/controllers"=>Object,
   "/usr/local/bundle/gems/activestorage-6.0.3.3/app/controllers/concerns"=>
    Object,
   "/usr/local/bundle/gems/activestorage-6.0.3.3/app/jobs"=>Object,
   "/usr/local/bundle/gems/activestorage-6.0.3.3/app/models"=>Object},
 @setup=true,
 @tag="rails.main",
 @to_unload={}>

and 

Zeitwerk@rails.main: autoload set for Graphql::Types::BaseAttachment, to be loaded from /usr/src/app/app/lib/graphql/types/base_attachment.rb
Zeitwerk@rails.main: autoload set for Graphql::Types::ActiveRecordObject, to be loaded from /usr/src/app/app/lib/graphql/types/active_record_object.rb
Zeitwerk@rails.main: autoload set for Graphql::Types::AttachmentWithId, to be loaded from /usr/src/app/app/lib/graphql/types/attachment_with_id.rb
...

without anything related to the cache module or the Cache::Base class

fxn commented 3 years ago

It is strange that @to_unload is empty in this call, and it was not in the first one. What is config.cache_classes and config.eager_load in your test environment?

We should see at least the same series of autoload calls. Please do not edit the log of the autoloader, I'd like to see it all to spot differences.

Could you share the full autoloader log both in success and failure use cases?

fxn commented 3 years ago

BTW, if there is sensitive information please feel free to email me at fxn@hashref.com.

enthusiasmus commented 3 years ago

When setting config.cache_classes also to false in test environment, the loading works perfectly and the spec passes! config.eager_load is also false in both environments. In production we have both settings set to true. Why has Zeitwerk problems with this settings?

Hope the autoloader logs now aren't necessary anymore (I am indeed not allowed to post the full log, because of sensitive information).

Thank you

fxn commented 3 years ago

Why has Zeitwerk problems with this settings?

I did not said Zeitwerk has an issue with these settings. I am trying to gather as much context as possible to help diagnose.

If you cannot share information, let's try some baby steps. Is there a file called /usr/src/app/app/lib/cache.rb? If yes, what constant does it define and how?

fxn commented 3 years ago

I am asking this because I see a discrepancy. The issue description says that you get

Zeitwerk::NameError:
  expected file /usr/src/app/app/lib/cache.rb to define constant Cache, but didn't

but autoload logs above say

Zeitwerk@rails.main: module Cache autovivified from directory /usr/src/app/app/lib/cache

This does not square. We need to understand where's the issue.

With autoloading logs it would be faster, but don't worry, we'll try to hunt it down going step by step.

enthusiasmus commented 3 years ago

The Zeitwerk::NameError gets raised in test environment with config.cache_classes = true the autoload logs Zeitwerk@rails.main: module Cache autovivified from directory /usr/src/app/app/lib/cache is a log line in development environment with config.cache_classes = false. This does square, doesn't it?

No, there is no /usr/src/app/app/lib/cache.rb.

Thank you for you patience!

fxn commented 3 years ago

It is really strange that we get this error message

Zeitwerk::NameError:
  expected file /usr/src/app/app/lib/cache.rb to define constant Cache, but didn't

and /usr/src/app/app/lib/cache.rb does not exist.

Does the application load Cache during the boot process? For example in an initializer? Not that it would explain that, but to keep gathering context.

fxn commented 3 years ago

Would it be possible to trigger

Zeitwerk::NameError:
  expected file /usr/src/app/app/lib/cache.rb to define constant Cache, but didn't

with autoloading logging enabled, and share only the log lines that mention "cache" case-insensitive?

Then do the same in development mode when things load correctly?

enthusiasmus commented 3 years ago

/usr/src/app/app/lib/cache.rb doesn't exist, that is true. The application doesn't load Cache during the boot process. Currently I can't reproduce the Zeitwerk::NameError.

With following diff 

diff --git a/config/application.rb b/config/application.rb
index 3152bd84e..3e3278814 100644
--- a/config/application.rb
+++ b/config/application.rb
@@ -10,6 +10,7 @@ require_relative("../app/lib/enumerable")
 module Atalanda
   class Application < Rails::Application
     config.load_defaults 6.0
+    Rails.autoloaders.log!

diff --git a/config/environments/test.rb b/config/environments/test.rb
index c4461a25c..17f6824fa 100644
--- a/config/environments/test.rb
+++ b/config/environments/test.rb
@@ -2,7 +2,7 @@

 Atalanda::Application.configure do
   config.eager_load = false
-  config.cache_classes = true
+  config.cache_classes = false

   # Configure static asset server for tests with Cache-Control for performance
   config.public_file_server.enabled = true
diff --git a/spec/lib/cache/base_spec.rb b/spec/lib/cache/base_spec.rb
index 092b2247f..cbe12d5de 100644
--- a/spec/lib/cache/base_spec.rb
+++ b/spec/lib/cache/base_spec.rb
@@ -2,6 +2,8 @@

 require "rails_helper"

+pp Rails.autoloaders.main
+
 describe Cache::Base do

I get the following output

root@6b77cf5ce56f:/usr/src/app# rspec spec/lib/cache/base_spec.rb 
DEPRECATION WARNING: Initialization autoloaded the constants Spree::Preferences, Spree::Preferences::Preferable, Spree::Preferences::PreferableClassMethods, Spree::Core::EnvironmentExtension, Spree::Core::Environment, Spree::Core::Environment::Calculators, Spree::Preferences::Configuration, Spree::AppConfiguration, Hashid, ApplicationRecord, Spree::ApplicationConfiguration, ApplicationConfiguration, EmailRecipientPunycodeHook, AirbrakeFilter, Spree::Audit, CheckPassword, Spree::OAuthProfile, Searcher::Pagination, Searcher, InternalMarkdownRenderer, LoginStrategies::Base, LoginStrategies::Guest, LoginStrategies::Credentials, LoginStrategies, Paperclip::CloudimagePatch, Paperclip::ClassMethodsPatch, Property, Property::Cache, Throttler, OperatorBrand, Warden::Strategies::ApiKey, Spree::Promo, Spree::Promo::Environment, Spree::Calculator, Spree::Calculator::FlatPercentItemTotal, Spree::Calculator::FlatRate, Spree::Calculator::FreeShipping, Spree::Calculator::OneVendorFreeShipping, Spree::Activator, Spree::Promotion, Spree::Promotion::Rules, Spree::PromotionRule, Spree::Promotion::Rules::ItemTotal, Spree::Promotion::Rules::Product, MultiLanguageHelper, ActsAsAutoTranslatable, Spree::AccountingItem, Spree::AccountingItems, Spree::AccountingItems::Product, Spree::AccountingItems::Shipment, Spree::AccountingItems::Service, Ability::Roles::Base, Spree::BillingIntegration, Spree::PaymentMethod, Spree::BillingIntegration::Ipayment, Spree::BillingIntegration::PaypalPlus, Spree::BillingIntegration::StripeGateway, Spree::BillingIntegration::Voucher, Ability::Roles::Default, Ability::Roles::Persisted, Ability::Roles::Anonymous, Ability::Roles::Admin, Ability::Roles::Helpers, Ability::Roles::Helpers::Vendorable, Ability::Roles::Rules, Ability::Roles::Rules::ShopManager, Ability::Roles::Rules::ShopManager::Orders, Ability::Roles::Rules::ShopManager::Products, Ability::Roles::Rules::ShopManager::Shared, Ability::Roles::Rules::ShopManager::VendorContext, Ability::Roles::ShopManager, Ability::Roles::CityManager, Ability::Roles::Seo, Ability::Roles::Courier, Ability::Roles::CallCenter, Ability::Roles::Developer, Ability::Roles::Accountant, Ability::Roles::VendorsChainManager, Ability::Roles::OrderManager, Ability::Roles::ProductManager, Ability::Roles, Ability, Spree::UserCityZone, Spree::UserVendor, Spree::UserVendorsChain, EmailValidator, Spree::User, Spree::Promotion::Rules::User, Spree::Promotion::Rules::FirstOrder, Spree::Promotion::Actions, Spree::PromotionAction, Spree::Promotion::Actions::CreateAdjustment, Spree::Calculator::PerVendor, Spree::Calculator::SelfCollect, Spree::Calculator::DefaultTax, ExceptionsApp, ActionText::ContentHelper, ActionText::TagHelper, MoneyHelper, ApplicationHelper, AdvantageBarHelper, CacheHelper, CartHelper, CheckoutHelper, ChristmasHelper, CityMapHelper, CustomPathHelper, DesignSystemHelper, DynUrlHelper, EventHelper, ImageHelper, ListHelper, LyticsHelper, NationwideHelper, NavigationHelper, NewsletterHelper, PaginationHelper, PathHelper, ProductHelper, ProductWidgetHelper, PromotedCampaignHelper, RansackerHelper, SearchFiltersHelper, ServiceHelper, Spree::Admin, Spree::Admin::Apps, Spree::Admin::Apps::Bonus, Spree::Admin::Apps::Bonus::AuthorizeHelper, Spree::Admin::AreasHelper, Spree::Admin::AuditsHelper, Spree::Admin::BaseHelper, Spree::Admin::CashbackHelper, Spree::Admin::CityZonesHelper, Spree::Admin::ConfirmationsHelper, Spree::Admin::CourierJobsHelper, Spree::Admin::CustomManifestHelper, Spree::Admin::EssentialHealthCheckHelper, Spree::Admin::EventsHelper, Spree::Admin::LanguageTabsHelper, Spree::Admin::LetzshopHelper, Spree::Admin::ListsHelper, Spree::Admin::NavigationHelper, Spree::Admin::OptionTypesHelper, Spree::Admin::ProductTaxonMappingsHelper, Spree::Admin::ProductsHelper, Spree::Admin::SeoContentHelper, Spree::Admin::ServicesHelper, Spree::Admin::ShipmentsHelper, Spree::Admin::ShippingMethodHelper, Spree::Admin::UserHelper, Spree::Admin::VoucherHelper, Spree::BaseHelper, Spree::CashbackHelper, Spree::CheckoutHelper, Spree::OrderHelper, Spree::PromotionRulesHelper, StrongParametersHelper, UrlHelper, TranslationHelper, VendorMapHelper, VendorRepresentorHelper, VendorsChainHelper, ViewqlHelper, VoucherVendorsHelper, WidgetHelper, FontAwesome::Rails::IconHelper, DeviseHelper, PrependActionsForProtectFromForgery, Recaptcha, SecureRedirectUrl, PrivacyAnonymizer, ApplicationController, CurrentOrder, Spree::Core::ControllerHelpers, LanguageDefaultRedirection, Spree::BaseController, Spree::NotFoundExceptionsController, ExceptionsController, I18n::Styling und DeepIterate.

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 Spree::Preferences, 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 /usr/src/app/config/environment.rb:7)
Zeitwerk@rails.main: autoload set for Cache, to be autovivified from /usr/src/app/app/lib/cache
Zeitwerk@rails.main: autoload set for Brand::Cache, to be loaded from /usr/src/app/app/lib/brand/cache.rb
Zeitwerk@rails.main: autoload set for Property::Cache, to be loaded from /usr/src/app/app/models/property/cache.rb
...
#<Zeitwerk::Loader:0x00005650e43f2628
 @autoloaded_dirs=
...
 @autoloads=
   "/usr/src/app/app/lib/cache"=>[Object, :Cache],
   "/usr/src/app/app/lib/brand/cache.rb"=>
    [Brand(id: integer, name: string, logo_file_name: string, logo_content_type: string, logo_file_size: integer, logo_updated_at: datetime, detail_image_file_name: string, detail_image_content_type: string, detail_image_file_size: integer, detail_image_updated_at: datetime, created_at: datetime, updated_at: datetime, identifier: string, aliases: json),
     :Cache],
   "/usr/src/app/app/models/property/cache.rb"=>[Property, :Cache],
...
 @collapse_dirs=#<Set: {}>,
 @collapse_glob_patterns=#<Set: {}>,
 @eager_load_exclusions=#<Set: {"/usr/src/app/lib/spree_gem/core/lib"}>,
 @eager_loaded=false,
 @ignored_glob_patterns=#<Set: {}>,
 @ignored_paths=#<Set: {}>,
 @inflector=ActiveSupport::Dependencies::ZeitwerkIntegration::Inflector,
 @initialized_at="2021-04-26T15:36:05.218+02:00",
 @lazy_subdirs=
  ...
   "Cache"=>["/usr/src/app/app/lib/cache"],
  ...
 @logger=
  #<Proc:0x00005650e43f1e58@/usr/local/bundle/gems/zeitwerk-2.4.2/lib/zeitwerk/loader.rb:459 (lambda)>,
 @mutex=#<Thread::Mutex:0x00005650e43f1f48>,
 @mutex2=#<Thread::Mutex:0x00005650e43f1ef8>,
 @on_load_callbacks={},
 @preloads=[],
 @reloading_enabled=true,
 @root_dirs=
  {"/usr/src/app/app/components"=>Object,
   "/usr/src/app/app/concerns"=>Object,
   "/usr/src/app/app/controllers"=>Object,
   "/usr/src/app/app/decorators"=>Object,
   "/usr/src/app/app/flat_namespace"=>Object,
   "/usr/src/app/app/helpers"=>Object,
   "/usr/src/app/app/jobs"=>Object,
   "/usr/src/app/app/lib"=>Object,
   "/usr/src/app/app/mailers"=>Object,
   "/usr/src/app/app/model"=>Object,
   "/usr/src/app/app/models"=>Object,
   "/usr/src/app/app/validators"=>Object,
   "/usr/src/app/app/webpacker"=>Object,
   "/usr/src/app/app/workers"=>Object,
   "/usr/local/bundle/gems/actiontext-6.0.3.3/app/helpers"=>Object,
   "/usr/local/bundle/gems/actiontext-6.0.3.3/app/models"=>Object,
   "/usr/local/bundle/gems/actionmailbox-6.0.3.3/app/controllers"=>Object,
   "/usr/local/bundle/gems/actionmailbox-6.0.3.3/app/jobs"=>Object,
   "/usr/local/bundle/gems/actionmailbox-6.0.3.3/app/models"=>Object,
   "/usr/local/bundle/gems/activestorage-6.0.3.3/app/controllers"=>Object,
   "/usr/local/bundle/gems/activestorage-6.0.3.3/app/controllers/concerns"=>
    Object,
   "/usr/local/bundle/gems/activestorage-6.0.3.3/app/jobs"=>Object,
   "/usr/local/bundle/gems/activestorage-6.0.3.3/app/models"=>Object},
 @setup=true,
 @tag="rails.main",
 @to_unload=
...

Zeitwerk@rails.main: module Cache autovivified from directory /usr/src/app/app/lib/cache
Zeitwerk@rails.main: autoload set for Cache::Products, to be loaded from /usr/src/app/app/lib/cache/products.rb
Zeitwerk@rails.main: autoload set for Cache::Base, to be loaded from /usr/src/app/app/lib/cache/base.rb
Zeitwerk@rails.main: autoload set for Cache::Sales, to be loaded from /usr/src/app/app/lib/cache/sales.rb
Zeitwerk@rails.main: constant Cache::Base loaded from file /usr/src/app/app/lib/cache/base.rb

Randomized with seed 55304
Zeitwerk@rails.main: constant Brand::Cache loaded from file /usr/src/app/app/lib/brand/cache.rb
...

......

Finished in 2.91 seconds (files took 12.61 seconds to load)
6 examples, 0 failures

when switching to config.cache_classes = true I get the following output:

root@6b77cf5ce56f:/usr/src/app# rspec spec/lib/cache/base_spec.rb 
Zeitwerk@rails.main: autoload set for Cache, to be autovivified from /usr/src/app/app/lib/cache
Zeitwerk@rails.main: autoload set for Property::Cache, to be loaded from /usr/src/app/app/models/property/cache.rb
Zeitwerk@rails.main: autoload set for Brand::Cache, to be loaded from /usr/src/app/app/lib/brand/cache.rb
...
#<Zeitwerk::Loader:0x0000564e6cf53460
 @autoloaded_dirs=
...
 @autoloads=
   "/usr/src/app/app/models/property/cache.rb"=>[Property, :Cache],
   "/usr/src/app/app/lib/brand/cache.rb"=>
    [Brand(id: integer, name: string, logo_file_name: string, logo_content_type: string, logo_file_size: integer, logo_updated_at: datetime, detail_image_file_name: string, detail_image_content_type: string, detail_image_file_size: integer, detail_image_updated_at: datetime, created_at: datetime, updated_at: datetime, identifier: string, aliases: json),
     :Cache],
  ...
 @collapse_dirs=#<Set: {}>,
 @collapse_glob_patterns=#<Set: {}>,
 @eager_load_exclusions=#<Set: {"/usr/src/app/lib/spree_gem/core/lib"}>,
 @eager_loaded=false,
 @ignored_glob_patterns=#<Set: {}>,
 @ignored_paths=#<Set: {}>,
 @inflector=ActiveSupport::Dependencies::ZeitwerkIntegration::Inflector,
 @initialized_at="2021-04-26T16:04:33.173+02:00",
 @lazy_subdirs=
   "Cache"=>["/usr/src/app/app/lib/cache"],
   ...
 @logger=
  #<Proc:0x0000564e6cf52cb8@/usr/local/bundle/gems/zeitwerk-2.4.2/lib/zeitwerk/loader.rb:459 (lambda)>,
 @mutex=#<Thread::Mutex:0x0000564e6cf52d80>,
 @mutex2=#<Thread::Mutex:0x0000564e6cf52d58>,
 @on_load_callbacks={},
 @preloads=[],
 @reloading_enabled=false,
 @root_dirs=
  {"/usr/src/app/app/components"=>Object,
   "/usr/src/app/app/concerns"=>Object,
   "/usr/src/app/app/controllers"=>Object,
   "/usr/src/app/app/decorators"=>Object,
   "/usr/src/app/app/flat_namespace"=>Object,
   "/usr/src/app/app/helpers"=>Object,
   "/usr/src/app/app/jobs"=>Object,
   "/usr/src/app/app/lib"=>Object,
   "/usr/src/app/app/mailers"=>Object,
   "/usr/src/app/app/model"=>Object,
   "/usr/src/app/app/models"=>Object,
   "/usr/src/app/app/validators"=>Object,
   "/usr/src/app/app/webpacker"=>Object,
   "/usr/src/app/app/workers"=>Object,
   "/usr/local/bundle/gems/actiontext-6.0.3.3/app/helpers"=>Object,
   "/usr/local/bundle/gems/actiontext-6.0.3.3/app/models"=>Object,
   "/usr/local/bundle/gems/actionmailbox-6.0.3.3/app/controllers"=>Object,
   "/usr/local/bundle/gems/actionmailbox-6.0.3.3/app/jobs"=>Object,
   "/usr/local/bundle/gems/actionmailbox-6.0.3.3/app/models"=>Object,
   "/usr/local/bundle/gems/activestorage-6.0.3.3/app/controllers"=>Object,
   "/usr/local/bundle/gems/activestorage-6.0.3.3/app/controllers/concerns"=>
    Object,
   "/usr/local/bundle/gems/activestorage-6.0.3.3/app/jobs"=>Object,
   "/usr/local/bundle/gems/activestorage-6.0.3.3/app/models"=>Object},
 @setup=true,
 @tag="rails.main",
 @to_unload={}>

An error occurred while loading ./spec/lib/cache/base_spec.rb. - Did you mean?
                    rspec ./spec/lib/cache/sales_spec.rb
                    rspec ./spec/lib/batch/task_spec.rb
                    rspec ./spec/lib/lab/base_spec.rb

Failure/Error:
  describe Cache::Base do
    describe "#initialize" do
      it "raises an argument error if city_zone is missing" do
        expect { described_class.new }.to raise_error ArgumentError
      end

      it "returns a key error if current_city is given but option is missing key value" do
        expect { described_class.new({}) }.to raise_error KeyError
      end

LoadError:
  cannot load such file -- /usr/src/app/app/lib/cache
# /usr/local/bundle/gems/zeitwerk-2.4.2/lib/zeitwerk/kernel.rb:34:in `require'
# /usr/local/bundle/gems/zeitwerk-2.4.2/lib/zeitwerk/kernel.rb:34:in `require'
# ./spec/lib/cache/base_spec.rb:7:in `<top (required)>'
No examples found.

Top 0 slowest examples (0 seconds, 0.0% of total time):

Finished in 0.00004 seconds (files took 12.48 seconds to load)
0 examples, 0 failures, 1 error occurred outside of examples

I removed bootsnap and spring to be sure, that they don't have problems with zeitwerk. I can't explain why there is suddenly no Zeitwerk::NameError error any more. config.cache_classes seems to be the problem.

fxn commented 3 years ago

@enthusiasmus There's something really funky going on. For that to be possible, Zeitwerk needs to think no loader is managing /usr/src/app/app/lib/cache, which is really strange.

Could you please add pp Zeitwerk::Registry.autoloads after the current pp call in the spec and repeat both scenarios?

fxn commented 3 years ago

I have seen more things off.

According to the logs, the application loads Property and Property::Cache during initialization (*). When config.cache_classes is true the warning is not issued because reloading is disabled. However, I see

Zeitwerk@rails.main: autoload set for Property::Cache, to be loaded from /usr/src/app/app/models/property/cache.rb

which should not happen, the loader would detect both Property and Property::Cache were already loaded before its own setup, and would print a warning saying that file is ignored.

Also, in the second run @autoloads does not contain the directory for Cache.

This is all very strange, but without logs, it is difficult to understand.

(*) This should be fixed at some point, it is going to be an error condition in Rails 7.0.

fxn commented 3 years ago

And of course, we have the mystery of the phantom /usr/src/app/app/lib/cache.rb file.

fxn commented 3 years ago

Hi again! Wondering if we are in a deadlock, did you see the question in https://github.com/fxn/zeitwerk/issues/159#issuecomment-826918514? If yes no hurries, just wanted to double-check.

enthusiasmus commented 3 years ago

Dear fxn! No deadlock, I will post the next logs tomorrow! Thank you

enthusiasmus commented 3 years ago

I tried to get the output of pp Zeitwerk::Registry.autoloads but it is sooo big, that busts my terminal and it automatically scrolls for about 2 minutes. But in the end its prints the following with config.cache_classes = true:

Zeitwerk@rails.main: module Cache autovivified from directory /usr/src/app/app/lib/cache
Zeitwerk@rails.main: autoload set for Cache::Base, to be loaded from /usr/src/app/app/lib/cache/base.rb
Zeitwerk@rails.main: constant Cache::Base loaded from file /usr/src/app/app/lib/cache/base.rb

Randomized with seed 38169
...
Zeitwerk@rails.main: constant Brand::Cache loaded from file /usr/src/app/app/lib/brand/cache.rb

and with config.cache_classes = false:

Zeitwerk@rails.main: module Cache autovivified from directory /usr/src/app/app/lib/cache
Zeitwerk@rails.main: autoload set for Cache::Base, to be loaded from /usr/src/app/app/lib/cache/base.rb
Zeitwerk@rails.main: constant Cache::Base loaded from file /usr/src/app/app/lib/cache/base.rb

Randomized with seed 40193
...
Zeitwerk@rails.main: constant Brand::Cache loaded from file /usr/src/app/app/lib/brand/cache.rb

both runs are successful! independently from the configuration of the cache_classes. Now I am confused, because the only thing I did was restarting the container and execute once again a bundle install. Maybe the Problem is gone?

enthusiasmus commented 3 years ago

Even with spring and bootsnap reactivated - the tests are passing with both configuration states.

fxn commented 3 years ago

Interesting!!!

I can tell you that, if memory does not fail me, module autovivification has worked correctly since the beginning. The only thing that needed polishing was autovification + multi-threading, fixed in March 2019. Any project with an implicit namespace is doing this (that is, many projects).

Of course, you never know, maybe you hit some weird edge case that is new, but the reproduction seemed so simple (just run a spec), that... I was a bit skeptical. In any case, you never know, and we had to understand.

I wonder if this could be some kind of combination of things that involve shared file systems or something. That is, not exactly a problem in Zeitwerk, but something in the execution context external to the library. Again, nowadays a lot of people use Docker, but who knows!

So... what would you like to do? Do we close and reopen if it happens again?

enthusiasmus commented 3 years ago

Yes, that could be! Yeah, lets do this. Thank you very much for your time and your support!