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.

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

Duplicate key violations #2429

Closed
dssjoblom opened this issue Feb 21, 2023 · 4 comments · Fixed by #2433
Closed

Duplicate key violations #2429

dssjoblom opened this issue Feb 21, 2023 · 4 comments · Fixed by #2433

Comments

@dssjoblom
Copy link

dssjoblom commented Feb 21, 2023

Steps to reproduce

When upgrading from an older 6.0.0-pre version to 6.1.1, it seems that there are duplicate key violations while rendering the templates. Strangely enough, reloading the page makes the error go away.

Update: I get this also in the admin portion. If I upload an image and use it in an element, the preview always generates the same error. When I reload the preview, the image is there and everything works normally.

Stacktrace:

12:10:22 rails.1   | [127.0.0.1] PG::UniqueViolation: ERROR:  duplicate key value violates unique constraint "index_alchemy_picture_thumbs_on_signature"
12:10:22 rails.1   | DETAIL:  Key (signature)=(e2585c56ff30487fe40757854fd14eb0198f7771) already exists.
12:10:22 rails.1   | 
12:10:22 rails.1   | [127.0.0.1] /home/daniel/.rvm/gems/ruby-3.1.3/gems/activerecord-6.1.7.1/lib/active_record/connection_adapters/postgresql_adapter.rb:672:in `exec_params'
12:10:22 rails.1   | /home/daniel/.rvm/gems/ruby-3.1.3/gems/activerecord-6.1.7.1/lib/active_record/connection_adapters/postgresql_adapter.rb:672:in `block (2 levels) in exec_no_cache'
12:10:22 rails.1   | /home/daniel/.rvm/gems/ruby-3.1.3/gems/activesupport-6.1.7.1/lib/active_support/dependencies/interlock.rb:48:in `block in permit_concurrent_loads'
12:10:22 rails.1   | /home/daniel/.rvm/gems/ruby-3.1.3/gems/activesupport-6.1.7.1/lib/active_support/concurrency/share_lock.rb:187:in `yield_shares'
12:10:22 rails.1   | /home/daniel/.rvm/gems/ruby-3.1.3/gems/activesupport-6.1.7.1/lib/active_support/dependencies/interlock.rb:47:in `permit_concurrent_loads'
12:10:22 rails.1   | /home/daniel/.rvm/gems/ruby-3.1.3/gems/activerecord-6.1.7.1/lib/active_record/connection_adapters/postgresql_adapter.rb:671:in `block in exec_no_cache'
12:10:22 rails.1   | /home/daniel/.rvm/gems/ruby-3.1.3/gems/activerecord-6.1.7.1/lib/active_record/connection_adapters/abstract_adapter.rb:696:in `block (2 levels) in log'
12:10:22 rails.1   | /home/daniel/.rvm/gems/ruby-3.1.3/gems/activesupport-6.1.7.1/lib/active_support/concurrency/load_interlock_aware_monitor.rb:26:in `block (2 levels) in synchronize'
12:10:22 rails.1   | /home/daniel/.rvm/gems/ruby-3.1.3/gems/activesupport-6.1.7.1/lib/active_support/concurrency/load_interlock_aware_monitor.rb:25:in `handle_interrupt'
12:10:22 rails.1   | /home/daniel/.rvm/gems/ruby-3.1.3/gems/activesupport-6.1.7.1/lib/active_support/concurrency/load_interlock_aware_monitor.rb:25:in `block in synchronize'
12:10:22 rails.1   | /home/daniel/.rvm/gems/ruby-3.1.3/gems/activesupport-6.1.7.1/lib/active_support/concurrency/load_interlock_aware_monitor.rb:21:in `handle_interrupt'
12:10:22 rails.1   | /home/daniel/.rvm/gems/ruby-3.1.3/gems/activesupport-6.1.7.1/lib/active_support/concurrency/load_interlock_aware_monitor.rb:21:in `synchronize'
12:10:22 rails.1   | /home/daniel/.rvm/gems/ruby-3.1.3/gems/activerecord-6.1.7.1/lib/active_record/connection_adapters/abstract_adapter.rb:695:in `block in log'
12:10:22 rails.1   | /home/daniel/.rvm/gems/ruby-3.1.3/gems/activesupport-6.1.7.1/lib/active_support/notifications/instrumenter.rb:24:in `instrument'
12:10:22 rails.1   | /home/daniel/.rvm/gems/ruby-3.1.3/gems/activerecord-6.1.7.1/lib/active_record/connection_adapters/abstract_adapter.rb:687:in `log'
12:10:22 rails.1   | /home/daniel/.rvm/gems/ruby-3.1.3/gems/activerecord-6.1.7.1/lib/active_record/connection_adapters/postgresql_adapter.rb:670:in `exec_no_cache'
12:10:22 rails.1   | /home/daniel/.rvm/gems/ruby-3.1.3/gems/activerecord-6.1.7.1/lib/active_record/connection_adapters/postgresql_adapter.rb:649:in `execute_and_clear'
12:10:22 rails.1   | /home/daniel/.rvm/gems/ruby-3.1.3/gems/activerecord-6.1.7.1/lib/active_record/connection_adapters/postgresql/database_statements.rb:55:in `exec_query'
12:10:22 rails.1   | /home/daniel/.rvm/gems/ruby-3.1.3/gems/activerecord-6.1.7.1/lib/active_record/connection_adapters/abstract/database_statements.rb:136:in `exec_insert'
12:10:22 rails.1   | /home/daniel/.rvm/gems/ruby-3.1.3/gems/activerecord-6.1.7.1/lib/active_record/connection_adapters/postgresql/database_statements.rb:93:in `exec_insert'
12:10:22 rails.1   | /home/daniel/.rvm/gems/ruby-3.1.3/gems/activerecord-6.1.7.1/lib/active_record/connection_adapters/abstract/database_statements.rb:171:in `insert'
12:10:22 rails.1   | /home/daniel/.rvm/gems/ruby-3.1.3/gems/activerecord-6.1.7.1/lib/active_record/connection_adapters/abstract/query_cache.rb:22:in `insert'
12:10:22 rails.1   | /home/daniel/.rvm/gems/ruby-3.1.3/gems/activerecord-6.1.7.1/lib/active_record/persistence.rb:375:in `_insert_record'
12:10:22 rails.1   | /home/daniel/.rvm/gems/ruby-3.1.3/gems/activerecord-6.1.7.1/lib/active_record/persistence.rb:929:in `_create_record'
12:10:22 rails.1   | /home/daniel/.rvm/gems/ruby-3.1.3/gems/activerecord-6.1.7.1/lib/active_record/counter_cache.rb:166:in `_create_record'
12:10:22 rails.1   | /home/daniel/.rvm/gems/ruby-3.1.3/gems/activerecord-6.1.7.1/lib/active_record/locking/optimistic.rb:79:in `_create_record'
12:10:22 rails.1   | /home/daniel/.rvm/gems/ruby-3.1.3/gems/activerecord-6.1.7.1/lib/active_record/attribute_methods/dirty.rb:201:in `_create_record'
12:10:22 rails.1   | /home/daniel/.rvm/gems/ruby-3.1.3/gems/activerecord-6.1.7.1/lib/active_record/callbacks.rb:461:in `block in _create_record'
12:10:22 rails.1   | /home/daniel/.rvm/gems/ruby-3.1.3/gems/activesupport-6.1.7.1/lib/active_support/callbacks.rb:98:in `run_callbacks'
12:10:22 rails.1   | /home/daniel/.rvm/gems/ruby-3.1.3/gems/activesupport-6.1.7.1/lib/active_support/callbacks.rb:824:in `_run_create_callbacks'
12:10:22 rails.1   | /home/daniel/.rvm/gems/ruby-3.1.3/gems/activerecord-6.1.7.1/lib/active_record/callbacks.rb:461:in `_create_record'
12:10:22 rails.1   | /home/daniel/.rvm/gems/ruby-3.1.3/gems/activerecord-6.1.7.1/lib/active_record/timestamp.rb:108:in `_create_record'
12:10:22 rails.1   | /home/daniel/.rvm/gems/ruby-3.1.3/gems/activerecord-6.1.7.1/lib/active_record/persistence.rb:900:in `create_or_update'
12:10:22 rails.1   | /home/daniel/.rvm/gems/ruby-3.1.3/gems/activerecord-6.1.7.1/lib/active_record/callbacks.rb:457:in `block in create_or_update'
12:10:22 rails.1   | /home/daniel/.rvm/gems/ruby-3.1.3/gems/activesupport-6.1.7.1/lib/active_support/callbacks.rb:106:in `run_callbacks'
12:10:22 rails.1   | /home/daniel/.rvm/gems/ruby-3.1.3/gems/activesupport-6.1.7.1/lib/active_support/callbacks.rb:824:in `_run_save_callbacks'
12:10:22 rails.1   | /home/daniel/.rvm/gems/ruby-3.1.3/gems/activerecord-6.1.7.1/lib/active_record/callbacks.rb:457:in `create_or_update'
12:10:22 rails.1   | /home/daniel/.rvm/gems/ruby-3.1.3/gems/activerecord-6.1.7.1/lib/active_record/timestamp.rb:126:in `create_or_update'
12:10:22 rails.1   | /home/daniel/.rvm/gems/ruby-3.1.3/gems/activerecord-6.1.7.1/lib/active_record/persistence.rb:507:in `save!'
12:10:22 rails.1   | /home/daniel/.rvm/gems/ruby-3.1.3/gems/activerecord-6.1.7.1/lib/active_record/validations.rb:53:in `save!'
12:10:22 rails.1   | /home/daniel/.rvm/gems/ruby-3.1.3/gems/activerecord-6.1.7.1/lib/active_record/transactions.rb:302:in `block in save!'
12:10:22 rails.1   | /home/daniel/.rvm/gems/ruby-3.1.3/gems/activerecord-6.1.7.1/lib/active_record/transactions.rb:354:in `block in with_transaction_returning_status'
12:10:22 rails.1   | /home/daniel/.rvm/gems/ruby-3.1.3/gems/activerecord-6.1.7.1/lib/active_record/connection_adapters/abstract/database_statements.rb:320:in `block in transaction'
12:10:22 rails.1   | /home/daniel/.rvm/gems/ruby-3.1.3/gems/activerecord-6.1.7.1/lib/active_record/connection_adapters/abstract/transaction.rb:319:in `block in within_new_transaction'
12:10:22 rails.1   | /home/daniel/.rvm/gems/ruby-3.1.3/gems/activesupport-6.1.7.1/lib/active_support/concurrency/load_interlock_aware_monitor.rb:26:in `block (2 levels) in synchronize'
12:10:22 rails.1   | /home/daniel/.rvm/gems/ruby-3.1.3/gems/activesupport-6.1.7.1/lib/active_support/concurrency/load_interlock_aware_monitor.rb:25:in `handle_interrupt'
12:10:22 rails.1   | /home/daniel/.rvm/gems/ruby-3.1.3/gems/activesupport-6.1.7.1/lib/active_support/concurrency/load_interlock_aware_monitor.rb:25:in `block in synchronize'
12:10:22 rails.1   | /home/daniel/.rvm/gems/ruby-3.1.3/gems/activesupport-6.1.7.1/lib/active_support/concurrency/load_interlock_aware_monitor.rb:21:in `handle_interrupt'
12:10:22 rails.1   | /home/daniel/.rvm/gems/ruby-3.1.3/gems/activesupport-6.1.7.1/lib/active_support/concurrency/load_interlock_aware_monitor.rb:21:in `synchronize'
12:10:22 rails.1   | /home/daniel/.rvm/gems/ruby-3.1.3/gems/activerecord-6.1.7.1/lib/active_record/connection_adapters/abstract/transaction.rb:317:in `within_new_transaction'
12:10:22 rails.1   | /home/daniel/.rvm/gems/ruby-3.1.3/gems/activerecord-6.1.7.1/lib/active_record/connection_adapters/abstract/database_statements.rb:320:in `transaction'
12:10:22 rails.1   | /home/daniel/.rvm/gems/ruby-3.1.3/gems/activerecord-6.1.7.1/lib/active_record/transactions.rb:350:in `with_transaction_returning_status'
12:10:22 rails.1   | /home/daniel/.rvm/gems/ruby-3.1.3/gems/activerecord-6.1.7.1/lib/active_record/transactions.rb:302:in `save!'
12:10:22 rails.1   | /home/daniel/.rvm/gems/ruby-3.1.3/gems/activerecord-6.1.7.1/lib/active_record/suppressor.rb:48:in `save!'
12:10:22 rails.1   | /home/daniel/.rvm/gems/ruby-3.1.3/gems/activerecord-6.1.7.1/lib/active_record/persistence.rb:55:in `create!'
12:10:22 rails.1   | /home/daniel/.rvm/gems/ruby-3.1.3/gems/alchemy-dragonfly-s3-6.0.0/lib/alchemy/dragonfly/s3/create_picture_thumb.rb:12:in `call'
12:10:22 rails.1   | /home/daniel/.rvm/gems/ruby-3.1.3/bundler/gems/alchemy_cms-cadcb5a23b09/app/models/alchemy/picture/url.rb:39:in `uid'
12:10:22 rails.1   | /home/daniel/.rvm/gems/ruby-3.1.3/gems/alchemy-dragonfly-s3-6.0.0/app/models/alchemy/picture/s3_url.rb:9:in `call'
12:10:22 rails.1   | /home/daniel/.rvm/gems/ruby-3.1.3/bundler/gems/alchemy_cms-cadcb5a23b09/app/models/alchemy/picture.rb:180:in `url'
12:10:22 rails.1   | /home/daniel/.rvm/gems/ruby-3.1.3/bundler/gems/alchemy_cms-cadcb5a23b09/app/models/concerns/alchemy/picture_thumbnails.rb:40:in `picture_url'

Expected behavior

There should be no duplicate key violations. I'd also not expect a GET request to cause database writes (like thumbnail creation), see #2428

Actual behavior

I get a duplicate key violation. It's also mysterious that once the same page is loaded again the error disappears.

System configuration

  • Alchemy Version: 6.1.1
  • Rails Version: 6.1.7.1
@dssjoblom
Copy link
Author

So I did some digging into this. It looks like a classic race-condition. In alchemy-dragonfly-s3:

module Alchemy
  module Dragonfly
    module S3
      class CreatePictureThumb
        def self.call(variant, signature, uid)
          # create the thumb before uploading
          # to prevent db race conditions
          thumb = nil
          if variant.picture.valid?
            thumb = Alchemy::PictureThumb.create!(
              picture: variant.picture,
              signature: signature,
              uid: uid,
            )
          end
          begin
            # fetch and process the image
            image = variant.image
            # upload the processed image
            image.store(path: uid)
          rescue RuntimeError, Excon::Error => e
            ErrorTracking.notification_handler.call(e)
            # destroy the thumb if processing or upload fails
            thumb&.destroy
          end
        end
      end
    end
  end
end

Shouldn't this use something like https://apidock.com/rails/ActiveRecord/Relation/create_or_find_by ?

@tvdeyen
Copy link
Member

tvdeyen commented Feb 25, 2023

We only write if the thumbnail does not exist, as you can see here

PictureThumb.generator_class.call(variant, signature, uid)

Maybe there is a more thorough way of doing it? Want to try finding a fix?

tvdeyen added a commit to tvdeyen/alchemy_cms that referenced this issue Feb 26, 2023
In a multi concurrent application server (like Puma) it happens that
a thumb might already exist for a given signature during the very
short timeframe of finding it vs creating it.

Using ARs [create_or_find_by!](https://github.com/rails/rails/blob/8015c2c2cf5c8718449677570f372ceb01318a32/activerecord/lib/active_record/relation.rb#L218) do avoid ActiveRecord::RecordNotUnique errors. ActiveStorage does the
exact same thing to avoid concurrency issues.

Closes AlchemyCMS#2429
tvdeyen added a commit to tvdeyen/alchemy_cms that referenced this issue Feb 26, 2023
In a multi concurrent application server (like Puma) it happens that
a thumb might already exist for a given signature during the very
short timeframe of finding it vs creating it.

Using ARs [create_or_find_by!](https://github.com/rails/rails/blob/8015c2c2cf5c8718449677570f372ceb01318a32/activerecord/lib/active_record/relation.rb#L218) do avoid ActiveRecord::RecordNotUnique errors. ActiveStorage does the
exact same thing to avoid concurrency issues.

Closes AlchemyCMS#2429
@tvdeyen
Copy link
Member

tvdeyen commented Feb 26, 2023

@dssjoblom would please give

# Gemfile
gem "alchemy_cms", git: "https://github.com/tvdeyen/alchemy_cms", branch: "6.1-write-thumbs-on-writing-db"

a try?

tvdeyen added a commit to AlchemyCMS/alchemy-dragonfly-s3 that referenced this issue Feb 26, 2023
In a multi concurrent application server (like Puma) it happens that
a thumb might already exist for a given signature during the very
short timeframe of finding it vs creating it.

Using ARs [create_or_find_by!](https://github.com/rails/rails/blob/8015c2c2cf5c8718449677570f372ceb01318a32/activerecord/lib/active_record/relation.rb#L218) do avoid ActiveRecord::RecordNotUnique errors. ActiveStorage does the
exact same thing to avoid concurrency issues.

Refs AlchemyCMS/alchemy_cms#2429
@tvdeyen tvdeyen added the bug label Feb 26, 2023
@tvdeyen tvdeyen self-assigned this Feb 26, 2023
@tvdeyen
Copy link
Member

tvdeyen commented Feb 26, 2023

@dssjoblom and for alchemy-dragonfly-s3 please use this PR AlchemyCMS/alchemy-dragonfly-s3#20

# Gemfile
gem "alchemy-dragonfly-s3", git: "https://github.com/AlchemyCMS/alchemy-dragonfly-s3", branch: "fix-concurrency-issues"

tvdeyen added a commit to AlchemyCMS/alchemy-dragonfly-s3 that referenced this issue Feb 27, 2023
In a multi concurrent application server (like Puma) it happens that
a thumb might already exist for a given signature during the very
short timeframe of finding it vs creating it.

Using ARs [create_or_find_by!](https://github.com/rails/rails/blob/8015c2c2cf5c8718449677570f372ceb01318a32/activerecord/lib/active_record/relation.rb#L218) do avoid ActiveRecord::RecordNotUnique errors. ActiveStorage does the
exact same thing to avoid concurrency issues.

Refs AlchemyCMS/alchemy_cms#2429
dbwinger pushed a commit to dbwinger/alchemy_cms that referenced this issue Mar 20, 2023
In a multi concurrent application server (like Puma) it happens that
a thumb might already exist for a given signature during the very
short timeframe of finding it vs creating it.

Using ARs [create_or_find_by!](https://github.com/rails/rails/blob/8015c2c2cf5c8718449677570f372ceb01318a32/activerecord/lib/active_record/relation.rb#L218) do avoid ActiveRecord::RecordNotUnique errors. ActiveStorage does the
exact same thing to avoid concurrency issues.

Closes AlchemyCMS#2429
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging a pull request may close this issue.

2 participants