search

rails / solid_cache

A database-backed ActiveSupport::Cache::Store
MIT License
865 stars 61 forks source link

Using Solid Cache for low-level caching produces `warning -- already initialized constant` #182

Closed nimmolo closed 1 month ago

nimmolo commented 4 months ago

I'm trying to cache some query data using Rails "low level caching" and Solid Cache - pretty simple stuff. I'm doing it by the book.

My caching method as a model class method:

class Location < ApplicationRecord
  def self.location_name_cache
    Rails.cache.fetch(:location_names, expires_in: 15.minutes) do
      (Location.pluck(:name) + Observation.pluck(:where)).uniq
    end
  end

  # Check if a given place name already exists, defined as a Location name string.
  def self.location_name_exists(name)
    location_name_cache.member?(name)
  end

When I unit-test my class method (using Minitest), although the tests pass, i'm getting these warnings:

warning: already initialized constant SolidCache::Record::NULL_INSTRUMENTER
warning: previous definition of NULL_INSTRUMENTER was here

I feel like this is likely a bug.

djmb commented 3 months ago

@nimmolo - this suggests that app/solid_cache/models/record.rb is being loaded twice. It should be handled for us by the Rails autoloader.

Could you see where it is be required from? You can add puts caller just before the definition of the constant to find out.

nimmolo commented 3 months ago

Thanks @djmb - yes, i would have assumed Zeitwerk was handling it.

Am I adding this the right place?

  def self.location_name_cache
    puts(caller)
    Rails.cache.fetch(:location_names, expires_in: 15.minutes) do
      (Location.pluck(:name) +
       Observation.where.not(where: nil).pluck(:where) +
       SpeciesList.where.not(where: nil).pluck(:where)).uniq
    end
  end
djmb commented 3 months ago

@nimmolo - we need to dump the stacktrace from within app/solid_cache/models/record.rb itself. bundle open solid_cache should open it in your editor for you.

We'd expect the backtrace to appear twice, with the second time being what causes the warning.

nimmolo commented 3 months ago

@djmb Got it, thank you.

/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/solid_cache-0.6.0/app/models/solid_cache/record.rb:4:in `<module:SolidCache>'e: 00:00:09,  ETA: 00:00:20
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/solid_cache-0.6.0/app/models/solid_cache/record.rb:3:in `<top (required)>'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/zeitwerk-2.6.16/lib/zeitwerk/kernel.rb:26:in `require'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/zeitwerk-2.6.16/lib/zeitwerk/kernel.rb:26:in `require'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/solid_cache-0.6.0/app/models/solid_cache/entry.rb:4:in `<module:SolidCache>'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/solid_cache-0.6.0/app/models/solid_cache/entry.rb:3:in `<top (required)>'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/zeitwerk-2.6.16/lib/zeitwerk/kernel.rb:26:in `require'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/zeitwerk-2.6.16/lib/zeitwerk/kernel.rb:26:in `require'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/solid_cache-0.6.0/lib/solid_cache/store/entries.rb:38:in `block in entry_read'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/solid_cache-0.6.0/lib/solid_cache/cluster/execution.rb:49:in `instrument'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/solid_cache-0.6.0/lib/solid_cache/cluster/execution.rb:31:in `execute'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/solid_cache-0.6.0/lib/solid_cache/cluster/connections.rb:27:in `block in with_connection_for'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/solid_cache-0.6.0/lib/solid_cache/connections/unmanaged.rb:17:in `with_connection_for'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/solid_cache-0.6.0/lib/solid_cache/cluster/connections.rb:26:in `with_connection_for'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/solid_cache-0.6.0/lib/solid_cache/store/clusters.rb:27:in `block in reading_key'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/solid_cache-0.6.0/lib/solid_cache/store/failsafe.rb:22:in `failsafe'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/solid_cache-0.6.0/lib/solid_cache/store/clusters.rb:26:in `reading_key'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/solid_cache-0.6.0/lib/solid_cache/store/entries.rb:37:in `entry_read'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/solid_cache-0.6.0/lib/solid_cache/store/api.rb:39:in `read_serialized_entry'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/activesupport-7.1.3.4/lib/active_support/cache/strategy/local_cache.rb:130:in `read_serialized_entry'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/solid_cache-0.6.0/lib/solid_cache/store/api.rb:35:in `read_entry'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/activesupport-7.1.3.4/lib/active_support/cache.rb:460:in `block in fetch'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/activesupport-7.1.3.4/lib/active_support/cache.rb:1030:in `block in _instrument'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/activesupport-7.1.3.4/lib/active_support/notifications.rb:208:in `instrument'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/activesupport-7.1.3.4/lib/active_support/cache.rb:1029:in `_instrument'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/activesupport-7.1.3.4/lib/active_support/cache.rb:1006:in `instrument'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/activesupport-7.1.3.4/lib/active_support/cache.rb:459:in `fetch'
/Users/nimmo/Documents/GitHub/my-repo/app/models/location.rb:581:in `location_name_cache'
/Users/nimmo/Documents/GitHub/my-repo/app/models/location.rb:593:in `location_name_exists'
/Users/nimmo/Documents/GitHub/my-repo/app/models/location.rb:599:in `dubious_name?'
/Users/nimmo/Documents/GitHub/my-repo/app/controllers/observations_controller/validators.rb:72:in `validate_place_name'
/Users/nimmo/Documents/GitHub/my-repo/app/controllers/observations_controller/edit_and_update.rb:120:in `validate_edit_place_name'
/Users/nimmo/Documents/GitHub/my-repo/app/controllers/observations_controller/edit_and_update.rb:89:in `update'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/actionpack-7.1.3.4/lib/action_controller/metal/basic_implicit_render.rb:6:in `send_action'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/actionpack-7.1.3.4/lib/abstract_controller/base.rb:224:in `process_action'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/actionpack-7.1.3.4/lib/action_controller/metal/rendering.rb:165:in `process_action'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/actionpack-7.1.3.4/lib/abstract_controller/callbacks.rb:259:in `block in process_action'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/activesupport-7.1.3.4/lib/active_support/callbacks.rb:121:in `block in run_callbacks'
/Users/nimmo/Documents/GitHub/my-repo/app/controllers/application_controller.rb:226:in `catch_errors_and_log_request_stats'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/activesupport-7.1.3.4/lib/active_support/callbacks.rb:130:in `block in run_callbacks'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/turbo-rails-2.0.5/lib/turbo-rails.rb:24:in `with_request_id'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/turbo-rails-2.0.5/app/controllers/concerns/turbo/request_id_tracking.rb:10:in `turbo_tracking_request_id'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/activesupport-7.1.3.4/lib/active_support/callbacks.rb:130:in `block in run_callbacks'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/activesupport-7.1.3.4/lib/active_support/callbacks.rb:141:in `run_callbacks'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/actionpack-7.1.3.4/lib/abstract_controller/callbacks.rb:258:in `process_action'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/actionpack-7.1.3.4/lib/action_controller/metal/rescue.rb:25:in `process_action'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/actionpack-7.1.3.4/lib/action_controller/metal/instrumentation.rb:74:in `block in process_action'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/activesupport-7.1.3.4/lib/active_support/notifications.rb:208:in `instrument'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/actionpack-7.1.3.4/lib/action_controller/metal/instrumentation.rb:73:in `process_action'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/actionpack-7.1.3.4/lib/action_controller/metal/params_wrapper.rb:261:in `process_action'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/activerecord-7.1.3.4/lib/active_record/railties/controller_runtime.rb:32:in `process_action'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/actionpack-7.1.3.4/lib/abstract_controller/base.rb:160:in `process'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/actionview-7.1.3.4/lib/action_view/rendering.rb:40:in `process'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/actionpack-7.1.3.4/lib/action_controller/metal.rb:227:in `dispatch'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/actionpack-7.1.3.4/lib/action_controller/test_case.rb:611:in `block in process_controller_response'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/activesupport-7.1.3.4/lib/active_support/execution_wrapper.rb:92:in `wrap'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/actionpack-7.1.3.4/lib/action_controller/test_case.rb:601:in `wrap_execution'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/actionpack-7.1.3.4/lib/action_controller/test_case.rb:611:in `process_controller_response'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/actionpack-7.1.3.4/lib/action_controller/test_case.rb:521:in `process'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/rails-controller-testing-1.0.5/lib/rails/controller/testing/template_assertions.rb:62:in `process'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/actionpack-7.1.3.4/lib/action_controller/test_case.rb:434:in `put'
/Users/nimmo/Documents/GitHub/my-repo/test/functional_test_case.rb:33:in `put'
/Users/nimmo/Documents/GitHub/my-repo/test/controllers/observations_controller/observations_controller_project_list_test.rb:271:in `test_list_checkboxes_in_update_observation'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/minitest-5.24.1/lib/minitest/test.rb:95:in `block (3 levels) in run'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/minitest-5.24.1/lib/minitest/test.rb:192:in `capture_exceptions'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/minitest-5.24.1/lib/minitest/test.rb:90:in `block (2 levels) in run'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/minitest-5.24.1/lib/minitest.rb:368:in `time_it'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/minitest-5.24.1/lib/minitest/test.rb:89:in `block in run'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/minitest-5.24.1/lib/minitest.rb:467:in `on_signal'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/minitest-5.24.1/lib/minitest/test.rb:240:in `with_info_handler'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/minitest-5.24.1/lib/minitest/test.rb:88:in `run'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/minitest-reporters-1.7.1/lib/minitest/reporters.rb:48:in `run_with_hooks'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/activesupport-7.1.3.4/lib/active_support/executor/test_helper.rb:5:in `block in run'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/activesupport-7.1.3.4/lib/active_support/execution_wrapper.rb:105:in `perform'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/activesupport-7.1.3.4/lib/active_support/executor/test_helper.rb:5:in `run'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/minitest-5.24.1/lib/minitest.rb:1200:in `run_one_method'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/minitest-5.24.1/lib/minitest.rb:433:in `run_one_method'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/minitest-5.24.1/lib/minitest.rb:420:in `block (2 levels) in run'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/minitest-5.24.1/lib/minitest.rb:419:in `each'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/minitest-5.24.1/lib/minitest.rb:419:in `block in run'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/minitest-5.24.1/lib/minitest.rb:467:in `on_signal'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/minitest-5.24.1/lib/minitest.rb:454:in `with_info_handler'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/minitest-5.24.1/lib/minitest.rb:418:in `run'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/railties-7.1.3.4/lib/rails/test_unit/line_filtering.rb:10:in `run'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/minitest-5.24.1/lib/minitest.rb:332:in `block in __run'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/minitest-5.24.1/lib/minitest.rb:332:in `map'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/minitest-5.24.1/lib/minitest.rb:332:in `__run'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/minitest-5.24.1/lib/minitest.rb:288:in `run'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/minitest-5.24.1/lib/minitest.rb:86:in `block in autorun'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/solid_cache-0.6.0/app/models/solid_cache/record.rb:4:in `<module:SolidCache>'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/solid_cache-0.6.0/app/models/solid_cache/record.rb:3:in `<top (required)>'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/zeitwerk-2.6.16/lib/zeitwerk/kernel.rb:26:in `require'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/zeitwerk-2.6.16/lib/zeitwerk/kernel.rb:26:in `require'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/solid_cache-0.6.0/app/models/solid_cache/entry.rb:4:in `<module:SolidCache>'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/solid_cache-0.6.0/app/models/solid_cache/entry.rb:3:in `<top (required)>'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/zeitwerk-2.6.16/lib/zeitwerk/kernel.rb:26:in `require'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/zeitwerk-2.6.16/lib/zeitwerk/kernel.rb:26:in `require'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/solid_cache-0.6.0/lib/solid_cache/store/entries.rb:50:in `block in entry_write'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/solid_cache-0.6.0/lib/solid_cache/store/clusters.rb:48:in `block (3 levels) in writing_key'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/solid_cache-0.6.0/lib/solid_cache/cluster/execution.rb:49:in `instrument'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/solid_cache-0.6.0/lib/solid_cache/cluster/execution.rb:31:in `execute'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/solid_cache-0.6.0/lib/solid_cache/cluster/connections.rb:27:in `block in with_connection_for'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/solid_cache-0.6.0/lib/solid_cache/connections/unmanaged.rb:17:in `with_connection_for'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/solid_cache-0.6.0/lib/solid_cache/cluster/connections.rb:26:in `with_connection_for'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/solid_cache-0.6.0/lib/solid_cache/store/clusters.rb:47:in `block (2 levels) in writing_key'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/solid_cache-0.6.0/lib/solid_cache/store/failsafe.rb:22:in `failsafe'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/solid_cache-0.6.0/lib/solid_cache/store/clusters.rb:46:in `block in writing_key'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/solid_cache-0.6.0/lib/solid_cache/store/clusters.rb:79:in `block in first_cluster_sync_rest_async'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/solid_cache-0.6.0/lib/solid_cache/store/clusters.rb:79:in `map'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/solid_cache-0.6.0/lib/solid_cache/store/clusters.rb:79:in `with_index'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/solid_cache-0.6.0/lib/solid_cache/store/clusters.rb:79:in `first_cluster_sync_rest_async'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/solid_cache-0.6.0/lib/solid_cache/store/clusters.rb:45:in `writing_key'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/solid_cache-0.6.0/lib/solid_cache/store/entries.rb:49:in `entry_write'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/solid_cache-0.6.0/lib/solid_cache/store/api.rb:47:in `write_entry'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/activesupport-7.1.3.4/lib/active_support/cache.rb:668:in `block in write'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/activesupport-7.1.3.4/lib/active_support/cache.rb:1030:in `block in _instrument'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/activesupport-7.1.3.4/lib/active_support/notifications.rb:208:in `instrument'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/activesupport-7.1.3.4/lib/active_support/cache.rb:1029:in `_instrument'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/activesupport-7.1.3.4/lib/active_support/cache.rb:1006:in `instrument'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/activesupport-7.1.3.4/lib/active_support/cache.rb:666:in `write'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/activesupport-7.1.3.4/lib/active_support/cache.rb:1062:in `save_block_result_to_cache'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/activesupport-7.1.3.4/lib/active_support/cache.rb:481:in `fetch'
/Users/nimmo/Documents/GitHub/my-repo/app/models/location.rb:581:in `location_name_cache'
/Users/nimmo/Documents/GitHub/my-repo/app/models/location.rb:593:in `location_name_exists'
/Users/nimmo/Documents/GitHub/my-repo/app/models/location.rb:599:in `dubious_name?'
/Users/nimmo/Documents/GitHub/my-repo/app/controllers/observations_controller/validators.rb:72:in `validate_place_name'
/Users/nimmo/Documents/GitHub/my-repo/app/controllers/observations_controller/edit_and_update.rb:120:in `validate_edit_place_name'
/Users/nimmo/Documents/GitHub/my-repo/app/controllers/observations_controller/edit_and_update.rb:89:in `update'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/actionpack-7.1.3.4/lib/action_controller/metal/basic_implicit_render.rb:6:in `send_action'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/actionpack-7.1.3.4/lib/abstract_controller/base.rb:224:in `process_action'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/actionpack-7.1.3.4/lib/action_controller/metal/rendering.rb:165:in `process_action'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/actionpack-7.1.3.4/lib/abstract_controller/callbacks.rb:259:in `block in process_action'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/activesupport-7.1.3.4/lib/active_support/callbacks.rb:121:in `block in run_callbacks'
/Users/nimmo/Documents/GitHub/my-repo/app/controllers/application_controller.rb:226:in `catch_errors_and_log_request_stats'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/activesupport-7.1.3.4/lib/active_support/callbacks.rb:130:in `block in run_callbacks'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/turbo-rails-2.0.5/lib/turbo-rails.rb:24:in `with_request_id'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/turbo-rails-2.0.5/app/controllers/concerns/turbo/request_id_tracking.rb:10:in `turbo_tracking_request_id'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/activesupport-7.1.3.4/lib/active_support/callbacks.rb:130:in `block in run_callbacks'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/activesupport-7.1.3.4/lib/active_support/callbacks.rb:141:in `run_callbacks'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/actionpack-7.1.3.4/lib/abstract_controller/callbacks.rb:258:in `process_action'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/actionpack-7.1.3.4/lib/action_controller/metal/rescue.rb:25:in `process_action'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/actionpack-7.1.3.4/lib/action_controller/metal/instrumentation.rb:74:in `block in process_action'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/activesupport-7.1.3.4/lib/active_support/notifications.rb:208:in `instrument'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/actionpack-7.1.3.4/lib/action_controller/metal/instrumentation.rb:73:in `process_action'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/actionpack-7.1.3.4/lib/action_controller/metal/params_wrapper.rb:261:in `process_action'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/activerecord-7.1.3.4/lib/active_record/railties/controller_runtime.rb:32:in `process_action'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/actionpack-7.1.3.4/lib/abstract_controller/base.rb:160:in `process'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/actionview-7.1.3.4/lib/action_view/rendering.rb:40:in `process'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/actionpack-7.1.3.4/lib/action_controller/metal.rb:227:in `dispatch'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/actionpack-7.1.3.4/lib/action_controller/test_case.rb:611:in `block in process_controller_response'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/activesupport-7.1.3.4/lib/active_support/execution_wrapper.rb:92:in `wrap'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/actionpack-7.1.3.4/lib/action_controller/test_case.rb:601:in `wrap_execution'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/actionpack-7.1.3.4/lib/action_controller/test_case.rb:611:in `process_controller_response'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/actionpack-7.1.3.4/lib/action_controller/test_case.rb:521:in `process'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/rails-controller-testing-1.0.5/lib/rails/controller/testing/template_assertions.rb:62:in `process'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/actionpack-7.1.3.4/lib/action_controller/test_case.rb:434:in `put'
/Users/nimmo/Documents/GitHub/my-repo/test/functional_test_case.rb:33:in `put'
/Users/nimmo/Documents/GitHub/my-repo/test/controllers/observations_controller/observations_controller_project_list_test.rb:271:in `test_list_checkboxes_in_update_observation'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/minitest-5.24.1/lib/minitest/test.rb:95:in `block (3 levels) in run'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/minitest-5.24.1/lib/minitest/test.rb:192:in `capture_exceptions'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/minitest-5.24.1/lib/minitest/test.rb:90:in `block (2 levels) in run'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/minitest-5.24.1/lib/minitest.rb:368:in `time_it'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/minitest-5.24.1/lib/minitest/test.rb:89:in `block in run'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/minitest-5.24.1/lib/minitest.rb:467:in `on_signal'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/minitest-5.24.1/lib/minitest/test.rb:240:in `with_info_handler'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/minitest-5.24.1/lib/minitest/test.rb:88:in `run'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/minitest-reporters-1.7.1/lib/minitest/reporters.rb:48:in `run_with_hooks'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/activesupport-7.1.3.4/lib/active_support/executor/test_helper.rb:5:in `block in run'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/activesupport-7.1.3.4/lib/active_support/execution_wrapper.rb:105:in `perform'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/activesupport-7.1.3.4/lib/active_support/executor/test_helper.rb:5:in `run'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/minitest-5.24.1/lib/minitest.rb:1200:in `run_one_method'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/minitest-5.24.1/lib/minitest.rb:433:in `run_one_method'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/minitest-5.24.1/lib/minitest.rb:420:in `block (2 levels) in run'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/minitest-5.24.1/lib/minitest.rb:419:in `each'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/minitest-5.24.1/lib/minitest.rb:419:in `block in run'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/minitest-5.24.1/lib/minitest.rb:467:in `on_signal'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/minitest-5.24.1/lib/minitest.rb:454:in `with_info_handler'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/minitest-5.24.1/lib/minitest.rb:418:in `run'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/railties-7.1.3.4/lib/rails/test_unit/line_filtering.rb:10:in `run'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/minitest-5.24.1/lib/minitest.rb:332:in `block in __run'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/minitest-5.24.1/lib/minitest.rb:332:in `map'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/minitest-5.24.1/lib/minitest.rb:332:in `__run'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/minitest-5.24.1/lib/minitest.rb:288:in `run'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/minitest-5.24.1/lib/minitest.rb:86:in `block in autorun'
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/solid_cache-0.6.0/app/models/solid_cache/record.rb:6: warning: already initialized constant SolidCache::Record::NULL_INSTRUMENTER
/Users/nimmo/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/solid_cache-0.6.0/app/models/solid_cache/record.rb:6: warning: previous definition of NULL_INSTRUMENTER was here
djmb commented 3 months ago

Hmm, both stacktraces look identical, so its not clear to me what's going on. It would require debugging to see why zeitwerk requires the file again the second time round.

dhh commented 1 month ago

I'm hitting the same issue. Maybe our resident Zeitwerk export @fxn can help us diagnose the issue 😄

fxn commented 1 month ago

✌️ Reading.

djmb commented 1 month ago

I think it must be failing to load the class and something is swallowing the exception (possibly the failsafe handling?)

fxn commented 1 month ago

Could you upgrade to Zeitwerk 2.6.18 and try to reproduce?

djmb commented 1 month ago

@fxn - I’ll try that tomorrow 👍

I suspect it’s an exception being swallowed by the cache’s failsafe handling - possibly for when the migrations have not been run?

djmb commented 1 month ago

I can reproduce this by adding raise ActiveRecord::ActiveRecordError inside the class definition for SolidCache::Record.

This gets swallowed here - https://github.com/rails/solid_cache/blob/fc2e42a8675adc94960ee644aa2a54169120ab47/lib/solid_cache/store/failsafe.rb#L23-L27.

So it might be better to be a bit more selective about what we are catching there.

@dhh, @nimmolo - if you could set a logger on the cache store - SolidCache::Store.logger = Logger.new($stdout) or similar, then it should output the exception there. Could you try that and post it here?

fxn commented 1 month ago

@djmb I am no familiar with the details. From that observation, how do you arrive at the double execution of the file?

dhh commented 1 month ago

Add Solid Cache to the project. Start a console. Do Rails.cache.write "1", "hello". On the second invocation, you get the warning.

fxn commented 1 month ago

@dhh I don't see it in a just generated app + solid_cache:

% bin/rails c
Loading development environment (Rails 7.2.1)
>> Rails.cache.write "1", "hello"
  SolidCache::Entry Upsert (0.6ms)  INSERT INTO "solid_cache_entries" ("key","value","key_hash","byte_size","created_at") VALUES (x'646576656c6f706d656e743a31', x'001102000000000000f0bfffffffff68656c6c6f', 8359783457928492833, 173, STRFTIME('%Y-%m-%d %H:%M:%f', 'NOW')) ON CONFLICT ("key_hash") DO UPDATE SET "key"=excluded."key","value"=excluded."value","byte_size"=excluded."byte_size" RETURNING "id"
=> true
>> Rails.cache.write "1", "hello"
  SolidCache::Entry Upsert (0.2ms)  INSERT INTO "solid_cache_entries" ("key","value","key_hash","byte_size","created_at") VALUES (x'646576656c6f706d656e743a31', x'001102000000000000f0bfffffffff68656c6c6f', 8359783457928492833, 173, STRFTIME('%Y-%m-%d %H:%M:%f', 'NOW')) ON CONFLICT ("key_hash") DO UPDATE SET "key"=excluded."key","value"=excluded."value","byte_size"=excluded."byte_size" RETURNING "id"
=> true

Do you do something different?

djmb commented 1 month ago

Ok, I've reproduced with:

rails new -f ~/src/sctest --main
cd ~/src/sctest
bundle add solid_cache
bin/rails solid_cache:install
# Then change the cache to :solid_cache_store in config/environments/development.rb
$ bin/rails c

I then get:

Loading development environment (Rails 8.0.0.alpha)
>> SolidCache::Store.logger = Logger.new($stdout)
=>
#<Logger:0x00000001289f9330
...
>> Rails.cache.write "1", "hello"
D, [2024-09-03T15:35:24.357756 #49361] DEBUG -- : Cache write: development:1 ({:max_size=>268435456, :namespace=>"development", :compress=>true, :compress_threshold=>1024})
E, [2024-09-03T15:35:24.375215 #49361] ERROR -- : SolidCacheStore: write_entry failed, returned nil: ActiveRecord::AdapterNotSpecified: The `cache` database is not configured for the `development` environment.

  Available database configurations are:

  default
development
test
production

=> nil
>> Rails.cache.write "1", "hello"
D, [2024-09-03T15:35:25.014624 #49361] DEBUG -- : Cache write: development:1 ({:max_size=>268435456, :namespace=>"development", :compress=>true, :compress_threshold=>1024})
/Users/dmcbreen/.local/share/mise/installs/ruby/3.3.4/lib/ruby/gems/3.3.0/gems/solid_cache-1.0.2/app/models/solid_cache/record.rb:5: warning: already initialized constant SolidCache::Record::NULL_INSTRUMENTER
/Users/dmcbreen/.local/share/mise/installs/ruby/3.3.4/lib/ruby/gems/3.3.0/gems/solid_cache-1.0.2/app/models/solid_cache/record.rb:5: warning: previous definition of NULL_INSTRUMENTER was here
E, [2024-09-03T15:35:25.019247 #49361] ERROR -- : SolidCacheStore: write_entry failed, returned nil: ActiveRecord::AdapterNotSpecified: The `cache` database is not configured for the `development` environment.

  Available database configurations are:

  default
development
test
production

So in this case the issue at least in this case is that the database configuration is incorrect, so an ActiveRecord::AdapterNotSpecified exception is raised while trying to require solid_cache/record.rb, but we swallow the exception so all you normally see is the warning that the constant was re-defined.

fxn commented 1 month ago

@djmb That squares.

If you set an autoload for a constant, and evaluating the file raises, Ruby interprets something went wrong and does not discard the autoload, so a new reference to the same constant interprets the file again.

djmb commented 1 month ago

I've raised https://github.com/rails/solid_cache/pull/203 to avoid hiding issues like this.

nimmolo commented 1 month ago

@djmb - Adding the logger to SolidCache::Store confirmed the same lack of db config in my case. Thank you everybody!

djmb commented 1 month ago

I’ll update the engine to hook that up to the Rails logger

nimmolo commented 1 month ago

@djmb incidentally could the SC docs be amended with an example of how to set up a cache db for the test environment?

I'll be happy to add a PR once i've got something working.

fxn commented 1 month ago

This issue got me thinking.

In general, Zeitwerk tries to stay out of the way as much as possible and match Ruby semantics with fidelity. You know that when a Ruby file raises while loaded, any side-effect remains. If a class was half-defined, the class still exists, and if you happen to catch the exception, it will be half-defined with all its unpredictable consequences. If you did not reach the point that defined the class, the class is not defined. You know.

Zeitwerk departs in one way: Module#autoload does not require that the target file defines the constant in the receiver. It does not even require that you define any constant. Zeitwerk does require that: if the constant is not defined in the receiver an exception is raised. Because at that level, Zeitwerk is your loader and it has a contract. The fact that it is implemented via Module#autoload is irrelevant for that contract.

So, after the confusion this warning generated (which is the way Ruby works), I am wondering if I could make that condition stronger and say: Raising is an error condition, it would trigger Zeitwerk::Error, wrapping the original exception, and delete the constant if it was defined. With this requirement, I believe understanding what was happening here would be easier.