Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Modules don't get autovivified #159

Closed
enthusiasmus opened this issue Apr 22, 2021 · 29 comments
Closed

Modules don't get autovivified #159

enthusiasmus opened this issue Apr 22, 2021 · 29 comments

Comments

@enthusiasmus
Copy link

enthusiasmus commented Apr 22, 2021 •
edited
Loading

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
Copy link
Owner

fxn commented Apr 22, 2021 •
edited
Loading

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

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

print?

@enthusiasmus
Copy link
Author

enthusiasmus commented Apr 23, 2021 •
edited
Loading

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
Copy link
Owner

fxn commented Apr 23, 2021

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

@fxn
Copy link
Owner

fxn commented Apr 23, 2021

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

@enthusiasmus
Copy link
Author

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
Copy link
Owner

fxn commented Apr 23, 2021

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
Copy link
Author 

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
Copy link
Author

enthusiasmus commented Apr 23, 2021 •
edited
Loading

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
Copy link
Owner

fxn commented Apr 23, 2021

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

@fxn
Copy link
Owner

fxn commented Apr 23, 2021

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

@enthusiasmus
Copy link
Author

enthusiasmus commented Apr 23, 2021 •
edited
Loading

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
Copy link
Owner

fxn commented Apr 23, 2021 •
edited
Loading

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
Copy link
Owner

fxn commented Apr 23, 2021

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

@enthusiasmus
Copy link
Author

enthusiasmus commented Apr 24, 2021 •
edited
Loading

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
Copy link
Owner

fxn commented Apr 24, 2021

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
Copy link
Owner

fxn commented Apr 24, 2021 •
edited
Loading

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
Copy link
Author

enthusiasmus commented Apr 25, 2021 •
edited
Loading

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
Copy link
Owner

fxn commented Apr 25, 2021

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
Copy link
Owner

fxn commented Apr 25, 2021 •
edited
Loading

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
Copy link
Author

enthusiasmus commented Apr 26, 2021 •
edited
Loading

/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
Copy link
Owner

fxn commented Apr 26, 2021

@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
Copy link
Owner

fxn commented Apr 26, 2021 •
edited
Loading

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
Copy link
Owner

fxn commented Apr 26, 2021

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

@fxn
Copy link
Owner

fxn commented Apr 30, 2021

Hi again! Wondering if we are in a deadlock, did you see the question in #159 (comment)? If yes no hurries, just wanted to double-check.

@enthusiasmus
Copy link
Author

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

@enthusiasmus
Copy link
Author

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
Copy link
Author

enthusiasmus commented May 5, 2021 •
edited
Loading

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

@fxn
Copy link
Owner

fxn commented May 5, 2021

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
Copy link
Author

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

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@fxn @enthusiasmus