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

Sporadically nil connection in SolidCache::Entry calls #235

Open
iJackUA opened this issue Oct 31, 2024 · 8 comments · May be fixed by #252
Open

Sporadically nil connection in SolidCache::Entry calls #235

iJackUA opened this issue Oct 31, 2024 · 8 comments · May be fixed by #252

Comments

@iJackUA
Copy link

iJackUA commented Oct 31, 2024

I've noticing couple likely connected issue, not regular and with not yet defined stable preconditions.
Also, it's happening inside the code that I run in ActiveJobs (that is managed by SolidQueue 1.0)

# `cache_key` is a string like "entity:f8ef8db0-8ba9-43d0-92c0-ee400986ed20" 
Rails.cache.exist?(cache_key)

sometimes gives an error

undefined method `select_all' for nil (NoMethodError)

          connection.select_all(query, "SolidCache::Entry Load").cast_values(attribute_types).to_h
                    ^^^^^^^^^^^

another call

Rails.cache.write(cache_key, 1, {})

sometimes gives

undefined method `supports_insert_conflict_target?' for nil (NoMethodError)

          connection.supports_insert_conflict_target? ? :key_hash : nil
                    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^

seems like the same root cause - connection became nil under some conditions (dot not know how to refine these conditions yet)

config/cache.yml

cache - uses separate database

was using using database: cache initially, tries also with connects_to - the same behavior

default: &default
  connects_to:
    database:
      writing: :cache
      reading: :cache
  store_options:
    max_age: <%= 30.days.to_i %>
    max_size: <%= 256.megabytes %>
    namespace: <%= Rails.env %>
...

Env
Ruby 3.3.0
Rails: 7.2.1.1
SolidCache: 1.0.6
MariaDB with master-master replication in Galera Cluster ()

Stack traces:

"/PATH_MASK/bundle/ruby/3.3.0/gems/solid_cache-1.0.6/app/models/solid_cache/entry.rb:38:in `block in read_multi'", 
"/PATH_MASK/bundle/ruby/3.3.0/gems/activerecord-7.2.1.1/lib/active_record/connection_adapters/abstract/query_cache.rb:143:in `disable_query_cache'", 
"/PATH_MASK/bundle/ruby/3.3.0/gems/activerecord-7.2.1.1/lib/active_record/query_cache.rb:30:in `uncached'", 
"/PATH_MASK/bundle/ruby/3.3.0/gems/solid_cache-1.0.6/app/models/solid_cache/entry.rb:131:in `without_query_cache'", 
"/PATH_MASK/bundle/ruby/3.3.0/gems/solid_cache-1.0.6/app/models/solid_cache/entry.rb:35:in `read_multi'", 
"/PATH_MASK/bundle/ruby/3.3.0/gems/solid_cache-1.0.6/app/models/solid_cache/entry.rb:31:in `read'", 
"/PATH_MASK/bundle/ruby/3.3.0/gems/solid_cache-1.0.6/lib/solid_cache/store/entries.rb:40:in `block in entry_read'", 
"/PATH_MASK/bundle/ruby/3.3.0/gems/solid_cache-1.0.6/lib/solid_cache/store/execution.rb:49:in `setup_instrumentation'", 
"/PATH_MASK/bundle/ruby/3.3.0/gems/solid_cache-1.0.6/lib/solid_cache/store/execution.rb:31:in `execute'", 
"/PATH_MASK/bundle/ruby/3.3.0/gems/solid_cache-1.0.6/lib/solid_cache/store/connections.rb:39:in `block in with_connection_for'", 
"/PATH_MASK/bundle/ruby/3.3.0/gems/solid_cache-1.0.6/lib/solid_cache/connections/unmanaged.rb:17:in `with_connection_for'", 
"/PATH_MASK/bundle/ruby/3.3.0/gems/solid_cache-1.0.6/lib/solid_cache/store/connections.rb:38:in `with_connection_for'", 
"/PATH_MASK/bundle/ruby/3.3.0/gems/solid_cache-1.0.6/lib/solid_cache/store/connections.rb:68:in `block in reading_key'", 
"/PATH_MASK/bundle/ruby/3.3.0/gems/solid_cache-1.0.6/lib/solid_cache/store/failsafe.rb:32:in `failsafe'", 
"/PATH_MASK/bundle/ruby/3.3.0/gems/solid_cache-1.0.6/lib/solid_cache/store/connections.rb:67:in `reading_key'", 
"/PATH_MASK/bundle/ruby/3.3.0/gems/solid_cache-1.0.6/lib/solid_cache/store/entries.rb:39:in `entry_read'", 
"/PATH_MASK/bundle/ruby/3.3.0/gems/solid_cache-1.0.6/lib/solid_cache/store/api.rb:49:in `read_serialized_entry'", 
"/PATH_MASK/bundle/ruby/3.3.0/gems/activesupport-7.2.1.1/lib/active_support/cache/strategy/local_cache.rb:130:in `read_serialized_entry'", 
"/PATH_MASK/bundle/ruby/3.3.0/gems/solid_cache-1.0.6/lib/solid_cache/store/api.rb:45:in `read_entry'", 
"/PATH_MASK/bundle/ruby/3.3.0/gems/activesupport-7.2.1.1/lib/active_support/cache.rb:706:in `block in exist?'", 
"/PATH_MASK/bundle/ruby/3.3.0/gems/activesupport-7.2.1.1/lib/active_support/cache.rb:1022:in `block in _instrument'", 
"/PATH_MASK/bundle/ruby/3.3.0/gems/activesupport-7.2.1.1/lib/active_support/notifications.rb:210:in `block in instrument'", 
"/PATH_MASK/bundle/ruby/3.3.0/gems/activesupport-7.2.1.1/lib/active_support/notifications/instrumenter.rb:58:in `instrument'", 
"/PATH_MASK/bundle/ruby/3.3.0/gems/sentry-rails-5.21.0/lib/sentry/rails/tracing.rb:56:in `instrument'", 
"/PATH_MASK/bundle/ruby/3.3.0/gems/activesupport-7.2.1.1/lib/active_support/notifications.rb:210:in `instrument'", 
"/PATH_MASK/bundle/ruby/3.3.0/gems/activesupport-7.2.1.1/lib/active_support/cache.rb:1021:in `_instrument'", 
"/PATH_MASK/bundle/ruby/3.3.0/gems/activesupport-7.2.1.1/lib/active_support/cache.rb:998:in `instrument'", 
"/PATH_MASK/bundle/ruby/3.3.0/gems/activesupport-7.2.1.1/lib/active_support/cache.rb:705:in `exist?'", 

"/PATH_MASK/bundle/ruby/3.3.0/gems/solid_cache-1.0.6/app/models/solid_cache/entry.rb:86:in `upsert_unique_by'", 
"/PATH_MASK/bundle/ruby/3.3.0/gems/solid_cache-1.0.6/app/models/solid_cache/entry.rb:26:in `block in write_multi'", 
"/PATH_MASK/bundle/ruby/3.3.0/gems/activerecord-7.2.1.1/lib/active_record/connection_adapters/abstract/query_cache.rb:143:in `disable_query_cache'", 
"/PATH_MASK/bundle/ruby/3.3.0/gems/activerecord-7.2.1.1/lib/active_record/query_cache.rb:30:in `uncached'", 
"/PATH_MASK/bundle/ruby/3.3.0/gems/solid_cache-1.0.6/app/models/solid_cache/entry.rb:131:in `without_query_cache'", 
"/PATH_MASK/bundle/ruby/3.3.0/gems/solid_cache-1.0.6/app/models/solid_cache/entry.rb:23:in `write_multi'", 
"/PATH_MASK/bundle/ruby/3.3.0/gems/solid_cache-1.0.6/app/models/solid_cache/entry.rb:19:in `write'", 
"/PATH_MASK/bundle/ruby/3.3.0/gems/solid_cache-1.0.6/lib/solid_cache/store/entries.rb:52:in `block in entry_write'", 
"/PATH_MASK/bundle/ruby/3.3.0/gems/solid_cache-1.0.6/lib/solid_cache/store/execution.rb:49:in `setup_instrumentation'", 
"/PATH_MASK/bundle/ruby/3.3.0/gems/solid_cache-1.0.6/lib/solid_cache/store/execution.rb:31:in `execute'", 
"/PATH_MASK/bundle/ruby/3.3.0/gems/solid_cache-1.0.6/lib/solid_cache/store/connections.rb:39:in `block in with_connection_for'", 
"/PATH_MASK/bundle/ruby/3.3.0/gems/solid_cache-1.0.6/lib/solid_cache/connections/unmanaged.rb:17:in `with_connection_for'", 
"/PATH_MASK/bundle/ruby/3.3.0/gems/solid_cache-1.0.6/lib/solid_cache/store/connections.rb:38:in `with_connection_for'", 
"/PATH_MASK/bundle/ruby/3.3.0/gems/solid_cache-1.0.6/lib/solid_cache/store/connections.rb:85:in `block in writing_key'", 
"/PATH_MASK/bundle/ruby/3.3.0/gems/solid_cache-1.0.6/lib/solid_cache/store/failsafe.rb:32:in `failsafe'", 
"/PATH_MASK/bundle/ruby/3.3.0/gems/solid_cache-1.0.6/lib/solid_cache/store/connections.rb:84:in `writing_key'", 
"/PATH_MASK/bundle/ruby/3.3.0/gems/solid_cache-1.0.6/lib/solid_cache/store/entries.rb:51:in `entry_write'", 
"/PATH_MASK/bundle/ruby/3.3.0/gems/solid_cache-1.0.6/lib/solid_cache/store/api.rb:64:in `write_entry'", 
"/PATH_MASK/bundle/ruby/3.3.0/gems/activesupport-7.2.1.1/lib/active_support/cache.rb:666:in `block in write'", 
"/PATH_MASK/bundle/ruby/3.3.0/gems/activesupport-7.2.1.1/lib/active_support/cache.rb:1022:in `block in _instrument'", 
"/PATH_MASK/bundle/ruby/3.3.0/gems/activesupport-7.2.1.1/lib/active_support/notifications.rb:210:in `block in instrument'", 
"/PATH_MASK/bundle/ruby/3.3.0/gems/activesupport-7.2.1.1/lib/active_support/notifications/instrumenter.rb:58:in `instrument'", 
"/PATH_MASK/bundle/ruby/3.3.0/gems/sentry-rails-5.21.0/lib/sentry/rails/tracing.rb:56:in `instrument'", 
"/PATH_MASK/bundle/ruby/3.3.0/gems/activesupport-7.2.1.1/lib/active_support/notifications.rb:210:in `instrument'", 
"/PATH_MASK/bundle/ruby/3.3.0/gems/activesupport-7.2.1.1/lib/active_support/cache.rb:1021:in `_instrument'", 
"/PATH_MASK/bundle/ruby/3.3.0/gems/activesupport-7.2.1.1/lib/active_support/cache.rb:998:in `instrument'", 
"/PATH_MASK/bundle/ruby/3.3.0/gems/activesupport-7.2.1.1/lib/active_support/cache.rb:664:in `write'"
@guizaols
Copy link

guizaols commented Dec 5, 2024

I'm facing this issue as well. Any updates on that?

@gurgeous
Copy link

We are seeing this as well on production. Our product is pre-release and lightly used, no load or concurrency. Maybe a stale connection/timeout?

@djmb
Copy link
Collaborator

djmb commented Dec 23, 2024

When you see the problem has it occurred continuously from the initial boot of the process?

If the process is initially ok, and it starts later does the process recover?

@gurgeous
Copy link

Definitely didn't happen at boot, occurred later. Not sure about recovery, we didn't dig that deep. I'll update if I find out more.

@guizaols
Copy link

Same here... it occurs during the application usage and not during the boot

@djmb
Copy link
Collaborator

djmb commented Dec 24, 2024

I wonder if there's an earlier error that is swallowed by the failsafe handling?

If you set the Store logger, then we might get something useful from it (I need to set this up by default to use the Rails logger).

Add something like this in an initializer and maybe we'll find something useful:

SolidCache::Store.logger = Rails.logger

@nkriege
Copy link

nkriege commented Jan 24, 2025

Enabled logging as suggested above, and now I see this in the logs immediately before the exception:

SolidCacheStore: read_entry failed, returned nil: ActiveRecord::ConnectionTimeoutError: could not obtain a connection from the pool within 5.000 seconds (waited 5.000 seconds); all pooled connections were in use

This was after the service had been running for quite awhile. It was under very light load at the time.

@djmb
Copy link
Collaborator

djmb commented Jan 24, 2025

Ah ok! So looks like you are running out of connections - either your connection pool is too small or you are leaking connections.

Things to check:

  • How many worker threads have you got?
  • Do you spawn threads anywhere in your app?
  • Do you use connections anywhere in code not wrapped in a Rails executor? That can leak connections.

I'll remove ActiveRecord::ConnectionTimeoutError from the list of transient errors as it causes errors anyway and the true issue is being masked. And I'll connect the logger to the Rails logger by default as well.

djmb added a commit that referenced this issue Jan 24, 2025
@djmb
Don't failsafe ActiveRecord::ConnectionTimeoutError
e3d5e66 
It hides the error and you end up with a different error anyway
as the connection is nil.

Fixes: #235
@djmb djmb linked a pull request Jan 24, 2025 that will close this issue
Open
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.

Don't failsafe ActiveRecord::ConnectionTimeoutError rails/solid_cache
5 participants
@gurgeous @nkriege @iJackUA @guizaols @djmb