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

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

Closed
nimmolo opened this issue Jun 27, 2024 · 21 comments · Fixed by #203
Closed

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

nimmolo opened this issue Jun 27, 2024 · 21 comments · Fixed by #203

Comments

@nimmolo
Copy link

nimmolo commented Jun 27, 2024 •
edited
Loading

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

djmb commented Jul 22, 2024

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

nimmolo commented Jul 22, 2024 •
edited
Loading

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

djmb commented Jul 23, 2024 •
edited
Loading

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

nimmolo commented Jul 23, 2024 •
edited
Loading

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

djmb commented Jul 26, 2024

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

dhh commented Sep 2, 2024

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

@fxn
Copy link
Member

fxn commented Sep 2, 2024

✌️ Reading.

@djmb
Copy link
Collaborator

djmb commented Sep 2, 2024

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

@fxn
Copy link
Member

fxn commented Sep 2, 2024

Could you upgrade to Zeitwerk 2.6.18 and try to reproduce?

@djmb
Copy link
Collaborator

djmb commented Sep 2, 2024

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

djmb commented Sep 3, 2024

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

This gets swallowed here -

solid_cache/lib/solid_cache/store/failsafe.rb

Lines 23 to 27 in fc2e42a

rescue ActiveRecord::ActiveRecordError => error
ActiveSupport.error_reporter&.report(error, handled: true, severity: :warning)
error_handler&.call(method: method, exception: error, returning: returning)
returning
end
.

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

fxn commented Sep 3, 2024

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

@dhh
Copy link
Member

dhh commented Sep 3, 2024

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

@fxn
Copy link
Member

fxn commented Sep 3, 2024

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

djmb commented Sep 3, 2024

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

fxn commented Sep 3, 2024

@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 added a commit that referenced this issue Sep 3, 2024
@djmb
Only failsafe on transient database errors
e30afec 
Avoid rescuing all ActiveRecord errors in the failsafe block as we might
be hiding configuration errors.

Fixes: #182
@djmb djmb mentioned this issue Sep 3, 2024
Merged
@djmb
Copy link
Collaborator

djmb commented Sep 3, 2024

I've raised #203 to avoid hiding issues like this.

djmb added a commit that referenced this issue Sep 3, 2024
@djmb
Only failsafe on transient database errors
3e10ec4 
Avoid rescuing all ActiveRecord errors in the failsafe block as we might
be hiding configuration errors.

Fixes: #182
@djmb djmb closed this as completed in #203 Sep 3, 2024
@nimmolo
Copy link
Author

nimmolo commented Sep 3, 2024 •
edited
Loading

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

@djmb
Copy link
Collaborator

djmb commented Sep 3, 2024

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

@nimmolo
Copy link
Author

nimmolo commented Sep 3, 2024 •
edited
Loading

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

fxn commented Sep 6, 2024 •
edited
Loading

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.

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

Successfully merging a pull request may close this issue.

Only failsafe on transient database errors rails/solid_cache
4 participants
@dhh @fxn @djmb @nimmolo