AlchemyCMS / alchemy_cms

Alchemy is the Open Source Rails CMS framework for the component based web that can be used as classic server side rendered or headless CMS.
https://www.alchemy-cms.com
BSD 3-Clause "New" or "Revised" License
846 stars 314 forks source link

Duplicate key violations #2429

Closed dssjoblom closed 1 year ago

dssjoblom commented 1 year ago

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

dssjoblom commented 1 year ago

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 commented 1 year ago

We only write if the thumbnail does not exist, as you can see here https://github.com/AlchemyCMS/alchemy_cms/blob/0e13375c362a60d1e65eec05f4c357a440fddff8/app/models/alchemy/picture/url.rb#L39

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

tvdeyen commented 1 year ago

@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 commented 1 year ago

@dssjoblom and for alchemy-dragonfly-s3 please use this PR https://github.com/AlchemyCMS/alchemy-dragonfly-s3/pull/20

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