can't add a new key into hash during iteration lib/active_record/connection_adapters/abstract/query_cache.rb #40608

kvokka · 2020-11-12T05:27:51Z

Steps to reproduce

Since it is caching problem, it is tricky to reproduce

Expected behavior

No error

Actual behavior

backlog from the first case:

gems/activerecord-6.1.0.rc1/lib/active_record/connection_adapters/abstract/query_cache.rb:54:in `block in initialize': can't add a new key into hash during iteration (RuntimeError)
    from gems/activerecord-6.1.0.rc1/lib/active_record/connection_adapters/abstract/query_cache.rb:111:in `block in cache_sql'
    from gems/activesupport-6.1.0.rc1/lib/active_support/concurrency/load_interlock_aware_monitor.rb:26:in `block (2 levels) in synchronize'
    from gems/activesupport-6.1.0.rc1/lib/active_support/concurrency/load_interlock_aware_monitor.rb:25:in `handle_interrupt'
    from gems/activesupport-6.1.0.rc1/lib/active_support/concurrency/load_interlock_aware_monitor.rb:25:in `block in synchronize'
    from gems/activesupport-6.1.0.rc1/lib/active_support/concurrency/load_interlock_aware_monitor.rb:21:in `handle_interrupt'
    from gems/activesupport-6.1.0.rc1/lib/active_support/concurrency/load_interlock_aware_monitor.rb:21:in `synchronize'
    from gems/activerecord-6.1.0.rc1/lib/active_record/connection_adapters/abstract/query_cache.rb:109:in `cache_sql'
    from gems/activerecord-6.1.0.rc1/lib/active_record/connection_adapters/abstract/query_cache.rb:101:in `select_all'
    from gems/activerecord-6.1.0.rc1/lib/active_record/connection_adapters/mysql/database_statements.rb:12:in `select_all'
    from gems/activerecord-6.1.0.rc1/lib/active_record/relation/calculations.rb:200:in `block in pluck'
    from gems/activerecord-6.1.0.rc1/lib/active_record/relation.rb:868:in `skip_query_cache_if_necessary'
    from gems/activerecord-6.1.0.rc1/lib/active_record/relation/calculations.rb:196:in `pluck'

yet another one:

gems/activerecord-6.1.0.rc1/lib/active_record/connection_adapters/abstract/query_cache.rb:54:in `block in initialize': can't add a new key into hash during iteration (RuntimeError)
    from gems/activerecord-6.1.0.rc1/lib/active_record/connection_adapters/abstract/query_cache.rb:111:in `block in cache_sql'
    from gems/activesupport-6.1.0.rc1/lib/active_support/concurrency/load_interlock_aware_monitor.rb:26:in `block (2 levels) in synchronize'
    from gems/activesupport-6.1.0.rc1/lib/active_support/concurrency/load_interlock_aware_monitor.rb:25:in `handle_interrupt'
    from gems/activesupport-6.1.0.rc1/lib/active_support/concurrency/load_interlock_aware_monitor.rb:25:in `block in synchronize'
    from gems/activesupport-6.1.0.rc1/lib/active_support/concurrency/load_interlock_aware_monitor.rb:21:in `handle_interrupt'
    from gems/activesupport-6.1.0.rc1/lib/active_support/concurrency/load_interlock_aware_monitor.rb:21:in `synchronize'
    from gems/activerecord-6.1.0.rc1/lib/active_record/connection_adapters/abstract/query_cache.rb:109:in `cache_sql'
    from gems/activerecord-6.1.0.rc1/lib/active_record/connection_adapters/abstract/query_cache.rb:101:in `select_all'
    from gems/activerecord-6.1.0.rc1/lib/active_record/connection_adapters/mysql/database_statements.rb:12:in `select_all'
    from gems/activerecord-6.1.0.rc1/lib/active_record/querying.rb:47:in `find_by_sql'
    from gems/activerecord-6.1.0.rc1/lib/active_record/statement_cache.rb:150:in `execute'
    from gems/activerecord-6.1.0.rc1/lib/active_record/associations/association.rb:227:in `find_target'
    from gems/activerecord-6.1.0.rc1/lib/active_record/associations/collection_association.rb:274:in `load_target'
    from gems/activerecord-6.1.0.rc1/lib/active_record/associations/collection_proxy.rb:43:in `load_target'
    from gems/activerecord-6.1.0.rc1/lib/active_record/associations/collection_proxy.rb:1002:in `records'
    from gems/activerecord-6.1.0.rc1/lib/active_record/relation/delegation.rb:88:in `each'

System configuration

Rails version: 6.1.0.rc1

Ruby version: 2.5.8

Connect replaygaming/replaypoker#4860
Connect #24627

The text was updated successfully, but these errors were encountered:

kvokka · 2020-11-12T05:44:18Z

Can it be because Hash.new { |h, sql| h[sql] = {} } is not Thread safe.
If you look in Concurrent ruby gem (which is already used in here) it just reuse CRuby Hash for this case. (And in one of the issues you may find interesign comment about it ruby-concurrency/concurrent-ruby#594 (comment))

it seems like this default proc needs it's own mutex

pauc · 2021-01-28T15:29:51Z

We are experiencing the same behavior when upgrading to 6.1.1 in a preproduction environment, the error appears randomly, similar backtrace... Could be related somehow to these changes 8589e8c#diff-058ae7dda657cf52fe6046918ff3dc3e1f556588b9b81e5a9204eb768ac8063e? (long shot)

kvokka · 2021-01-28T16:50:18Z

@pauc Trying to fix it, i upgraded Ruby from 2.5.8 to 2.7.2 on production, but it did not solve the problem (but saved a few Mbs of RAM anyway), so i do not feel like it's Ruby version related

jchatel · 2021-04-15T10:21:12Z

We are experiencing this issue since we upgraded Rails to 6.1.3.1. Any insight on this issue? Did you manage to resolve it @kvokka ?

kvokka · 2021-04-15T11:34:30Z

Hey @jchatel
I still using monkey patch from PR #40609
The suggested fix for activerecordimport did not solve the problem. I understand that it should be because of some dependency, but the project where i experience it is huge and now i have working solution, so it's not a priority for me personally atm.

But i'm happy to help you with it as much as i can. If you are willing to dig it, i can share Gemfile.lock content, so you'll be able to check for intersections with your project and hope that you will be more successful with this issue than me.

gsmetal · 2021-07-22T12:54:10Z

We have same problem (randomly happened time to time) on 6.1.3.2 and ruby 2.7.3 with such trace:

RuntimeError: can't add a new key into hash during iteration
  from activerecord (6.1.3.2) lib/active_record/connection_adapters/abstract/query_cache.rb:54:in `block in initialize'
  from activerecord (6.1.3.2) lib/active_record/connection_adapters/abstract/query_cache.rb:111:in `block in cache_sql'
  from activesupport (6.1.3.2) lib/active_support/concurrency/load_interlock_aware_monitor.rb:26:in `block (2 levels) in synchronize'
  from activesupport (6.1.3.2) lib/active_support/concurrency/load_interlock_aware_monitor.rb:25:in `handle_interrupt'
  from activesupport (6.1.3.2) lib/active_support/concurrency/load_interlock_aware_monitor.rb:25:in `block in synchronize'
  from activesupport (6.1.3.2) lib/active_support/concurrency/load_interlock_aware_monitor.rb:21:in `handle_interrupt'
  from activesupport (6.1.3.2) lib/active_support/concurrency/load_interlock_aware_monitor.rb:21:in `synchronize'
  from activerecord (6.1.3.2) lib/active_record/connection_adapters/abstract/query_cache.rb:109:in `cache_sql'
  from activerecord (6.1.3.2) lib/active_record/connection_adapters/abstract/query_cache.rb:101:in `select_all'
  from activerecord (6.1.3.2) lib/active_record/connection_adapters/mysql/database_statements.rb:12:in `select_all'
  from activerecord (6.1.3.2) lib/active_record/querying.rb:47:in `find_by_sql'
  from activerecord (6.1.3.2) lib/active_record/relation.rb:849:in `block in exec_queries'
  from activerecord (6.1.3.2) lib/active_record/relation.rb:867:in `skip_query_cache_if_necessary'
  from activerecord (6.1.3.2) lib/active_record/relation.rb:834:in `exec_queries'
  from activerecord (6.1.3.2) lib/active_record/relation.rb:638:in `load'
  from activerecord (6.1.3.2) lib/active_record/associations/preloader/association.rb:118:in `records_for'
  from activerecord (6.1.3.2) lib/active_record/associations/preloader/association.rb:45:in `load_records'
  from activerecord (6.1.3.2) lib/active_record/associations/preloader/association.rb:27:in `records_by_owner'
  from activerecord (6.1.3.2) lib/active_record/associations/preloader/association.rb:17:in `run'
  from activerecord (6.1.3.2) lib/active_record/associations/preloader.rb:151:in `block in preloaders_for_reflection'
  from activerecord (6.1.3.2) lib/active_record/associations/preloader.rb:150:in `each'
  from activerecord (6.1.3.2) lib/active_record/associations/preloader.rb:150:in `map'
  from activerecord (6.1.3.2) lib/active_record/associations/preloader.rb:150:in `preloaders_for_reflection'
  from activerecord (6.1.3.2) lib/active_record/associations/preloader.rb:119:in `block (2 levels) in preloaders_for_hash'
  from activerecord (6.1.3.2) lib/active_record/associations/preloader.rb:118:in `each'
  from activerecord (6.1.3.2) lib/active_record/associations/preloader.rb:118:in `flat_map'
  from activerecord (6.1.3.2) lib/active_record/associations/preloader.rb:118:in `block in preloaders_for_hash'
  from activerecord (6.1.3.2) lib/active_record/associations/preloader.rb:117:in `each'
  from activerecord (6.1.3.2) lib/active_record/associations/preloader.rb:117:in `flat_map'
  from activerecord (6.1.3.2) lib/active_record/associations/preloader.rb:117:in `preloaders_for_hash'
  from activerecord (6.1.3.2) lib/active_record/associations/preloader.rb:108:in `preloaders_on'
  from activerecord (6.1.3.2) lib/active_record/associations/preloader.rb:94:in `block in preload'
  from activerecord (6.1.3.2) lib/active_record/associations/preloader.rb:93:in `each'
  from activerecord (6.1.3.2) lib/active_record/associations/preloader.rb:93:in `flat_map'
  from activerecord (6.1.3.2) lib/active_record/associations/preloader.rb:93:in `preload'
  from activerecord (6.1.3.2) lib/active_record/relation.rb:769:in `block in preload_associations'
  from activerecord (6.1.3.2) lib/active_record/relation.rb:767:in `each'
  from activerecord (6.1.3.2) lib/active_record/relation.rb:767:in `preload_associations'
  from activerecord (6.1.3.2) lib/active_record/relation.rb:852:in `block in exec_queries'
  from activerecord (6.1.3.2) lib/active_record/relation.rb:867:in `skip_query_cache_if_necessary'
  from activerecord (6.1.3.2) lib/active_record/relation.rb:834:in `exec_queries'
  from activerecord (6.1.3.2) lib/active_record/relation.rb:638:in `load'
  from activerecord (6.1.3.2) lib/active_record/relation.rb:249:in `records'
  from activerecord (6.1.3.2) lib/active_record/relation/delegation.rb:88:in `each'

The application code is just do group_by on activerecord's relation.

gsmetal · 2021-07-22T12:58:16Z

Another randomly error has this trace while trying to achieve an association in application code:

RuntimeError: can't add a new key into hash during iteration
  from activerecord (6.1.3.2) lib/active_record/connection_adapters/abstract/query_cache.rb:54:in `block in initialize'
  from activerecord (6.1.3.2) lib/active_record/connection_adapters/abstract/query_cache.rb:111:in `block in cache_sql'
  from activesupport (6.1.3.2) lib/active_support/concurrency/load_interlock_aware_monitor.rb:26:in `block (2 levels) in synchronize'
  from activesupport (6.1.3.2) lib/active_support/concurrency/load_interlock_aware_monitor.rb:25:in `handle_interrupt'
  from activesupport (6.1.3.2) lib/active_support/concurrency/load_interlock_aware_monitor.rb:25:in `block in synchronize'
  from activesupport (6.1.3.2) lib/active_support/concurrency/load_interlock_aware_monitor.rb:21:in `handle_interrupt'
  from activesupport (6.1.3.2) lib/active_support/concurrency/load_interlock_aware_monitor.rb:21:in `synchronize'
  from activerecord (6.1.3.2) lib/active_record/connection_adapters/abstract/query_cache.rb:109:in `cache_sql'
  from activerecord (6.1.3.2) lib/active_record/connection_adapters/abstract/query_cache.rb:101:in `select_all'
  from activerecord (6.1.3.2) lib/active_record/connection_adapters/mysql/database_statements.rb:12:in `select_all'
  from activerecord (6.1.3.2) lib/active_record/querying.rb:47:in `find_by_sql'
  from activerecord (6.1.3.2) lib/active_record/statement_cache.rb:150:in `execute'
  from activerecord (6.1.3.2) lib/active_record/associations/association.rb:227:in `find_target'
  from activerecord (6.1.3.2) lib/active_record/associations/singular_association.rb:39:in `find_target'
  from activerecord (6.1.3.2) lib/active_record/associations/association.rb:174:in `load_target'
  from activerecord (6.1.3.2) lib/active_record/associations/association.rb:67:in `reload'
  from activerecord (6.1.3.2) lib/active_record/associations/singular_association.rb:9:in `reader'
  from activerecord (6.1.3.2) lib/active_record/associations/builder/association.rb:103:in `client'

All this does not look like "third party issue". Tried to grep query_cache manipulations in gemset with no luck.

boof · 2021-08-31T12:10:25Z

Is any of the participants using sentry-ruby here? We experienced this issue since we moved from sentry-raven to sentry-ruby and now have rolled back to sentry-raven.

My hunch here is having two concurrent threads accessing the cache hash, in our case the sql_cache, schema_cache, in our case:
Sentry-Ruby does a deep-dup on the hash itself, iterating over some keys while the cache itself add's a new key after it loaded the result from the DB raising this error.

st0012 · 2021-08-31T13:04:35Z

@boof hey I'm the maintainer of sentry-ruby. would you mind opening an issue in the SDK repo with more details and I'll help you investigate the problem?

boof · 2021-08-31T13:10:28Z

@st0012 I'd reference getsentry/sentry-ruby#1183 even though it is closed it seems highly related. I can also confirm that since we rolled back to sentry-raven those errors don't appear anymore. Would you mind reopening it?

gsmetal · 2021-08-31T13:17:38Z

We use sentry-raven and didn't try sentry-ruby but still have this random errors.

boof · 2021-08-31T13:32:21Z

@gsmetal do you report to sentry asynchronously?

gsmetal · 2021-08-31T13:39:44Z

@gsmetal do you report to sentry asynchronously?

@boof No, we use default configuration, no async is configured.

boof · 2021-09-02T08:42:56Z

I can confirm that after we downgraded sentry-ruby to sentry-raven the error disappeared.

@gsmetal Maybe some ActiveJob or other thread iterating over a caching hash in parallel?

gsmetal · 2021-09-02T08:53:58Z

@boof Nope, it's just pure iterating over ActiveRecord's collection on list rendering. And I think this errors appeared after updating rails 6.0 -> 6.1.

Just now found that we also have this error in separate sidekiq process on simple some_has_many_relation.some_scope.blank?:

RuntimeError: can't add a new key into hash during iteration
  from activerecord (6.1.3.2) lib/active_record/connection_adapters/abstract/query_cache.rb:54:in `block in initialize'
  from activerecord (6.1.3.2) lib/active_record/connection_adapters/abstract/query_cache.rb:111:in `block in cache_sql'
  from activesupport (6.1.3.2) lib/active_support/concurrency/load_interlock_aware_monitor.rb:26:in `block (2 levels) in synchronize'
  from activesupport (6.1.3.2) lib/active_support/concurrency/load_interlock_aware_monitor.rb:25:in `handle_interrupt'
  from activesupport (6.1.3.2) lib/active_support/concurrency/load_interlock_aware_monitor.rb:25:in `block in synchronize'
  from activesupport (6.1.3.2) lib/active_support/concurrency/load_interlock_aware_monitor.rb:21:in `handle_interrupt'
  from activesupport (6.1.3.2) lib/active_support/concurrency/load_interlock_aware_monitor.rb:21:in `synchronize'
  from activerecord (6.1.3.2) lib/active_record/connection_adapters/abstract/query_cache.rb:109:in `cache_sql'
  from activerecord (6.1.3.2) lib/active_record/connection_adapters/abstract/query_cache.rb:101:in `select_all'
  from activerecord (6.1.3.2) lib/active_record/connection_adapters/mysql/database_statements.rb:12:in `select_all'
  from activerecord (6.1.3.2) lib/active_record/querying.rb:47:in `find_by_sql'
  from activerecord (6.1.3.2) lib/active_record/relation.rb:849:in `block in exec_queries'
  from activerecord (6.1.3.2) lib/active_record/relation.rb:867:in `skip_query_cache_if_necessary'
  from activerecord (6.1.3.2) lib/active_record/relation.rb:834:in `exec_queries'
  from activerecord (6.1.3.2) lib/active_record/association_relation.rb:54:in `exec_queries'
  from activerecord (6.1.3.2) lib/active_record/relation.rb:638:in `load'
  from activerecord (6.1.3.2) lib/active_record/relation.rb:249:in `records'
  from activerecord (6.1.3.2) lib/active_record/relation.rb:724:in `blank?'

WIll try to investigate this case deeper.

boof · 2021-09-02T09:33:23Z

@gsmetal Sidekiq itself uses worker threads to run jobs IMHO, so whenever another library to for example deep copy an object in parallel (see Hash#deep_dup implementations for example) while a new key/value pair is being written to the cache this can raise randomly.

Maybe check for these kind of methods and debug from there.

gsmetal · 2021-09-09T08:46:17Z

It seems that I found my problem. I realized that one of the possible cause could be prometheus_exporter which starts in separate Thread in puma and in sidekiq. Digging into this I found that it had issue with rails 6.1 on our version (0.5.4) so I've updated gem to latest (0.8.1) and we have no new occurrences in about a day for now.

AFAIS this gem does not work with query cache directly, it works with connection pool and just raised error on 0.5.4. I didn't understand deeply what was causing the SUBJ error.

boof · 2021-09-09T11:16:12Z

There are different caches that can raise (schema, query, I think there is also one for views...). You can usually see which one looking at where the exception was raised.
Maybe it's totally unrelated to the third party gem but instead a problem of accessing some classes/connections from different threads.

rails-bot · 2021-12-08T11:37:01Z

This issue has been automatically marked as stale because it has not been commented on for at least three months.
The resources of the Rails team are limited, and so we are asking for your help.
If you can still reproduce this error on the 6-1-stable branch or on main, please reply with all of the information you have about it in order to keep the issue open.
Thank you for all your contributions.

ixti · 2022-01-06T03:54:49Z

The issue is still highly reproducible. :((

UPDATE: We're using outdated version (known to have issue) of activerecord-import. Will update this comment whenever upgrade solved this for us or not.
UPDATE2: We're seeing those even after upgrading activerecord-import :((

mjy · 2023-01-07T21:50:41Z

Probably unrelated, but sharing. Rails 6. Ruby 3.1.2p20 . M1. Big Sur. Development. Hit the error when doing complex param merging/permitting.

h = ActionController::Parameters.new

# ... do stuff

# h.permit!.to_h.deep_symbolize_keys  # -> 
# RuntimeError Exception: can't add a new key into hash during iteration

h.permit!.to_hash.deep_symbolize_keys # works!

k-kumawat · 2024-01-30T18:40:03Z

We are facing the same issue after upgrade from rails 5.2.8 to rails 6.0.6.1 only on production environment, ruby 2.6. doing simple operation
ABC.where(id: id, enabled: false).pluck(:id)
only can see the issue in sentry logs.

This was referenced Nov 12, 2020

Fix QueryCache concurrent issue #40609

Closed

RuntimeError - can't add a new key into hash during iteration rails/sprockets#242

Open

byroot added the third party issue label May 6, 2021

rails-bot bot added the stale label Dec 8, 2021

rails-bot bot closed this as completed Dec 15, 2021

sobrinho mentioned this issue Jun 7, 2022

RuntimeError: can't add a new key into hash during iteration on lib/active_record/connection_adapters/abstract/query_cache.rb #45287

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

can't add a new key into hash during iteration lib/active_record/connection_adapters/abstract/query_cache.rb #40608

can't add a new key into hash during iteration lib/active_record/connection_adapters/abstract/query_cache.rb #40608

kvokka commented Nov 12, 2020 •

edited

Loading

kvokka commented Nov 12, 2020

pauc commented Jan 28, 2021 •

edited

Loading

kvokka commented Jan 28, 2021

jchatel commented Apr 15, 2021

kvokka commented Apr 15, 2021

gsmetal commented Jul 22, 2021

gsmetal commented Jul 22, 2021 •

edited

Loading

boof commented Aug 31, 2021

st0012 commented Aug 31, 2021

boof commented Aug 31, 2021 •

edited

Loading

gsmetal commented Aug 31, 2021

boof commented Aug 31, 2021

gsmetal commented Aug 31, 2021

boof commented Sep 2, 2021 •

edited

Loading

gsmetal commented Sep 2, 2021

boof commented Sep 2, 2021

gsmetal commented Sep 9, 2021

boof commented Sep 9, 2021

rails-bot bot commented Dec 8, 2021

ixti commented Jan 6, 2022 •

edited

Loading

mjy commented Jan 7, 2023

k-kumawat commented Jan 30, 2024

can't add a new key into hash during iteration lib/active_record/connection_adapters/abstract/query_cache.rb #40608

can't add a new key into hash during iteration lib/active_record/connection_adapters/abstract/query_cache.rb #40608

Comments

kvokka commented Nov 12, 2020 • edited Loading

Steps to reproduce

Expected behavior

Actual behavior

System configuration

kvokka commented Nov 12, 2020

pauc commented Jan 28, 2021 • edited Loading

kvokka commented Jan 28, 2021

jchatel commented Apr 15, 2021

kvokka commented Apr 15, 2021

gsmetal commented Jul 22, 2021

gsmetal commented Jul 22, 2021 • edited Loading

boof commented Aug 31, 2021

st0012 commented Aug 31, 2021

boof commented Aug 31, 2021 • edited Loading

gsmetal commented Aug 31, 2021

boof commented Aug 31, 2021

gsmetal commented Aug 31, 2021

boof commented Sep 2, 2021 • edited Loading

gsmetal commented Sep 2, 2021

boof commented Sep 2, 2021

gsmetal commented Sep 9, 2021

boof commented Sep 9, 2021

rails-bot bot commented Dec 8, 2021

ixti commented Jan 6, 2022 • edited Loading

mjy commented Jan 7, 2023

k-kumawat commented Jan 30, 2024

kvokka commented Nov 12, 2020 •

edited

Loading

pauc commented Jan 28, 2021 •

edited

Loading

gsmetal commented Jul 22, 2021 •

edited

Loading

boof commented Aug 31, 2021 •

edited

Loading

boof commented Sep 2, 2021 •

edited

Loading

ixti commented Jan 6, 2022 •

edited

Loading