Problem with migrating database on 1.10.0

[morgoth]

The latest version included migrations that are updating good jobs table.
However running it on production environment, I got:

remote: I, [2021-06-30T11:22:02.519989 #57]  INFO -- : Migrating to AddActiveJobIdConcurrencyKeyCronKeyToGoodJobs (20210630111308)
remote: == 20210630111308 AddActiveJobIdConcurrencyKeyCronKeyToGoodJobs: migrating ====
remote: -- add_column(:good_jobs, :active_job_id, :uuid)
remote:    -> 0.0070s
remote: -- add_column(:good_jobs, :concurrency_key, :text)
remote:    -> 0.0017s
remote: -- add_column(:good_jobs, :cron_key, :text)
remote:    -> 0.0034s
remote: == 20210630111308 AddActiveJobIdConcurrencyKeyCronKeyToGoodJobs: migrated (0.0167s) 
remote: 
remote: I, [2021-06-30T11:22:02.548025 #57]  INFO -- : Migrating to AddActiveJobIdIndexAndConcurrencyKeyIndexToGoodJobs (20210630111309)
remote: == 20210630111309 AddActiveJobIdIndexAndConcurrencyKeyIndexToGoodJobs: migrating 
remote: -- add_index(:good_jobs, [:active_job_id, :created_at], {:algorithm=>:concurrently, :name=>:index_good_jobs_on_active_job_id_and_created_at})
remote: I, [2021-06-30T11:22:12.585170 #57]  INFO -- : [Rollbar] Scheduling item

remote: rails aborted!
remote: StandardError: An error has occurred, all later migrations canceled:
remote: 
remote: PG::LockNotAvailable: ERROR:  canceling statement due to lock timeout
remote: /app/vendor/bundle/ruby/3.0.0/gems/activerecord-6.1.4/lib/active_record/connection_adapters/postgresql/database_statements.rb:47:in `exec'
remote: /app/vendor/bundle/ruby/3.0.0/gems/activerecord-6.1.4/lib/active_record/connection_adapters/postgresql/database_statements.rb:47:in `block (2 levels) in execute'
remote: /app/vendor/bundle/ruby/3.0.0/gems/activesupport-6.1.4/lib/active_support/dependencies/interlock.rb:48:in `block in permit_concurrent_loads'
remote: /app/vendor/bundle/ruby/3.0.0/gems/activesupport-6.1.4/lib/active_support/concurrency/share_lock.rb:187:in `yield_shares'
remote: /app/vendor/bundle/ruby/3.0.0/gems/activesupport-6.1.4/lib/active_support/dependencies/interlock.rb:47:in `permit_concurrent_loads'
remote: /app/vendor/bundle/ruby/3.0.0/gems/activerecord-6.1.4/lib/active_record/connection_adapters/postgresql/database_statements.rb:46:in `block in execute'
remote: /app/vendor/bundle/ruby/3.0.0/gems/activerecord-6.1.4/lib/active_record/connection_adapters/abstract_adapter.rb:696:in `block (2 levels) in log'
remote: /app/vendor/bundle/ruby/3.0.0/gems/activesupport-6.1.4/lib/active_support/concurrency/load_interlock_aware_monitor.rb:26:in `block (2 levels) in synchronize'
remote: /app/vendor/bundle/ruby/3.0.0/gems/activesupport-6.1.4/lib/active_support/concurrency/load_interlock_aware_monitor.rb:25:in `handle_interrupt'
remote: /app/vendor/bundle/ruby/3.0.0/gems/activesupport-6.1.4/lib/active_support/concurrency/load_interlock_aware_monitor.rb:25:in `block in synchronize'
remote: /app/vendor/bundle/ruby/3.0.0/gems/activesupport-6.1.4/lib/active_support/concurrency/load_interlock_aware_monitor.rb:21:in `handle_interrupt'
remote: /app/vendor/bundle/ruby/3.0.0/gems/activesupport-6.1.4/lib/active_support/concurrency/load_interlock_aware_monitor.rb:21:in `synchronize'
remote: /app/vendor/bundle/ruby/3.0.0/gems/activerecord-6.1.4/lib/active_record/connection_adapters/abstract_adapter.rb:695:in `block in log'
remote: /app/vendor/bundle/ruby/3.0.0/gems/activesupport-6.1.4/lib/active_support/notifications/instrumenter.rb:24:in `instrument'
remote: /app/vendor/bundle/ruby/3.0.0/gems/activerecord-6.1.4/lib/active_record/connection_adapters/abstract_adapter.rb:687:in `log'
remote: /app/vendor/bundle/ruby/3.0.0/gems/activerecord-6.1.4/lib/active_record/connection_adapters/postgresql/database_statements.rb:45:in `execute'
remote: /app/vendor/bundle/ruby/3.0.0/gems/activerecord-6.1.4/lib/active_record/connection_adapters/postgresql/schema_statements.rb:448:in `add_index'
remote: /app/vendor/bundle/ruby/3.0.0/gems/activerecord-6.1.4/lib/active_record/migration.rb:929:in `block in method_missing'
remote: /app/vendor/bundle/ruby/3.0.0/gems/activerecord-6.1.4/lib/active_record/migration.rb:897:in `block in say_with_time'
remote: /app/vendor/ruby-3.0.1/lib/ruby/3.0.0/benchmark.rb:293:in `measure'
remote: /app/vendor/bundle/ruby/3.0.0/gems/activerecord-6.1.4/lib/active_record/migration.rb:897:in `say_with_time'
remote: /app/vendor/bundle/ruby/3.0.0/gems/activerecord-6.1.4/lib/active_record/migration.rb:918:in `method_missing'
remote: /app/vendor/bundle/ruby/3.0.0/gems/strong_migrations-0.7.7/lib/strong_migrations/migration.rb:13:in `block in method_missing'
remote: /app/vendor/bundle/ruby/3.0.0/gems/strong_migrations-0.7.7/lib/strong_migrations/checker.rb:339:in `perform'
remote: /app/vendor/bundle/ruby/3.0.0/gems/strong_migrations-0.7.7/lib/strong_migrations/migration.rb:12:in `method_missing'
remote: /app/db/migrate/20210630111309_add_active_job_id_index_and_concurrency_key_index_to_good_jobs.rb:19:in `change'
remote: /app/vendor/bundle/ruby/3.0.0/gems/activerecord-6.1.4/lib/active_record/migration.rb:867:in `exec_migration'
remote: /app/vendor/bundle/ruby/3.0.0/gems/activerecord-6.1.4/lib/active_record/migration.rb:851:in `block (2 levels) in migrate'
remote: /app/vendor/ruby-3.0.1/lib/ruby/3.0.0/benchmark.rb:293:in `measure'
remote: /app/vendor/bundle/ruby/3.0.0/gems/activerecord-6.1.4/lib/active_record/migration.rb:850:in `block in migrate'
remote: /app/vendor/bundle/ruby/3.0.0/gems/activerecord-6.1.4/lib/active_record/connection_adapters/abstract/connection_pool.rb:462:in `with_connection'
remote: /app/vendor/bundle/ruby/3.0.0/gems/activerecord-6.1.4/lib/active_record/migration.rb:849:in `migrate'
remote: /app/vendor/bundle/ruby/3.0.0/gems/strong_migrations-0.7.7/lib/strong_migrations/migration.rb:5:in `migrate'
remote: /app/vendor/bundle/ruby/3.0.0/gems/activerecord-6.1.4/lib/active_record/migration.rb:1037:in `migrate'
remote: /app/vendor/bundle/ruby/3.0.0/gems/activerecord-6.1.4/lib/active_record/migration.rb:1329:in `block in execute_migration_in_transaction'
remote: /app/vendor/bundle/ruby/3.0.0/gems/activerecord-6.1.4/lib/active_record/migration.rb:1382:in `ddl_transaction'
remote: /app/vendor/bundle/ruby/3.0.0/gems/activerecord-6.1.4/lib/active_record/migration.rb:1328:in `execute_migration_in_transaction'
remote: /app/vendor/bundle/ruby/3.0.0/gems/activerecord-6.1.4/lib/active_record/migration.rb:1302:in `each'
remote: /app/vendor/bundle/ruby/3.0.0/gems/activerecord-6.1.4/lib/active_record/migration.rb:1302:in `migrate_without_lock'
remote: /app/vendor/bundle/ruby/3.0.0/gems/activerecord-6.1.4/lib/active_record/migration.rb:1251:in `block in migrate'
remote: /app/vendor/bundle/ruby/3.0.0/gems/activerecord-6.1.4/lib/active_record/migration.rb:1401:in `block in with_advisory_lock'
remote: /app/vendor/bundle/ruby/3.0.0/gems/activerecord-6.1.4/lib/active_record/migration.rb:1416:in `block in with_advisory_lock_connection'
remote: /app/vendor/bundle/ruby/3.0.0/gems/activerecord-6.1.4/lib/active_record/connection_adapters/abstract/connection_pool.rb:462:in `with_connection'
remote: /app/vendor/bundle/ruby/3.0.0/gems/activerecord-6.1.4/lib/active_record/migration.rb:1416:in `with_advisory_lock_connection'
remote: /app/vendor/bundle/ruby/3.0.0/gems/activerecord-6.1.4/lib/active_record/migration.rb:1397:in `with_advisory_lock'
remote: /app/vendor/bundle/ruby/3.0.0/gems/activerecord-6.1.4/lib/active_record/migration.rb:1251:in `migrate'
remote: /app/vendor/bundle/ruby/3.0.0/gems/activerecord-6.1.4/lib/active_record/migration.rb:1086:in `up'
remote: /app/vendor/bundle/ruby/3.0.0/gems/activerecord-6.1.4/lib/active_record/migration.rb:1061:in `migrate'
remote: /app/vendor/bundle/ruby/3.0.0/gems/activerecord-6.1.4/lib/active_record/tasks/database_tasks.rb:237:in `migrate'
remote: /app/vendor/bundle/ruby/3.0.0/gems/strong_migrations-0.7.7/lib/strong_migrations/database_tasks.rb:4:in `migrate'
remote: /app/vendor/bundle/ruby/3.0.0/gems/activerecord-6.1.4/lib/active_record/railties/databases.rake:92:in `block (3 levels) in <main>'
remote: /app/vendor/bundle/ruby/3.0.0/gems/activerecord-6.1.4/lib/active_record/railties/databases.rake:90:in `each'
remote: /app/vendor/bundle/ruby/3.0.0/gems/activerecord-6.1.4/lib/active_record/railties/databases.rake:90:in `block (2 levels) in <main>'
remote: /app/vendor/bundle/ruby/3.0.0/gems/rake-13.0.3/lib/rake/task.rb:281:in `block in execute'
remote: /app/vendor/bundle/ruby/3.0.0/gems/rake-13.0.3/lib/rake/task.rb:281:in `each'
remote: /app/vendor/bundle/ruby/3.0.0/gems/rake-13.0.3/lib/rake/task.rb:281:in `execute'
remote: /app/vendor/bundle/ruby/3.0.0/gems/rake-13.0.3/lib/rake/task.rb:219:in `block in invoke_with_call_chain'
remote: /app/vendor/bundle/ruby/3.0.0/gems/rake-13.0.3/lib/rake/task.rb:199:in `synchronize'
remote: /app/vendor/bundle/ruby/3.0.0/gems/rake-13.0.3/lib/rake/task.rb:199:in `invoke_with_call_chain'
remote: /app/vendor/bundle/ruby/3.0.0/gems/rake-13.0.3/lib/rake/task.rb:188:in `invoke'
remote: /app/vendor/bundle/ruby/3.0.0/gems/rake-13.0.3/lib/rake/application.rb:160:in `invoke_task'
remote: /app/vendor/bundle/ruby/3.0.0/gems/rake-13.0.3/lib/rake/application.rb:116:in `block (2 levels) in top_level'
remote: /app/vendor/bundle/ruby/3.0.0/gems/rake-13.0.3/lib/rake/application.rb:116:in `each'
remote: /app/vendor/bundle/ruby/3.0.0/gems/rake-13.0.3/lib/rake/application.rb:116:in `block in top_level'
remote: /app/vendor/bundle/ruby/3.0.0/gems/rake-13.0.3/lib/rake/application.rb:125:in `run_with_threads'
remote: /app/vendor/bundle/ruby/3.0.0/gems/rake-13.0.3/lib/rake/application.rb:110:in `top_level'
remote: /app/vendor/bundle/ruby/3.0.0/gems/railties-6.1.4/lib/rails/commands/rake/rake_command.rb:24:in `block (2 levels) in perform'
remote: /app/vendor/bundle/ruby/3.0.0/gems/rake-13.0.3/lib/rake/application.rb:186:in `standard_exception_handling'
remote: /app/vendor/bundle/ruby/3.0.0/gems/railties-6.1.4/lib/rails/commands/rake/rake_command.rb:24:in `block in perform'
remote: /app/vendor/bundle/ruby/3.0.0/gems/rake-13.0.3/lib/rake/rake_module.rb:59:in `with_application'
remote: /app/vendor/bundle/ruby/3.0.0/gems/railties-6.1.4/lib/rails/commands/rake/rake_command.rb:18:in `perform'
remote: /app/vendor/bundle/ruby/3.0.0/gems/railties-6.1.4/lib/rails/command.rb:50:in `invoke'
remote: /app/vendor/bundle/ruby/3.0.0/gems/railties-6.1.4/lib/rails/commands.rb:18:in `<main>'
remote: /app/vendor/bundle/ruby/3.0.0/gems/bootsnap-1.7.5/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:23:in `require'
remote: /app/vendor/bundle/ruby/3.0.0/gems/bootsnap-1.7.5/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:23:in `block in require_with_bootsnap_lfi'
remote: /app/vendor/bundle/ruby/3.0.0/gems/bootsnap-1.7.5/lib/bootsnap/load_path_cache/loaded_features_index.rb:92:in `register'
remote: /app/vendor/bundle/ruby/3.0.0/gems/bootsnap-1.7.5/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:22:in `require_with_bootsnap_lfi'
remote: /app/vendor/bundle/ruby/3.0.0/gems/bootsnap-1.7.5/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:31:in `require'

BTW, is it fine to run 1.10.0 without this migration? It is easy to miss it

[bensheldon]

@morgoth it's safe to run v1.10.0 without the migration, though you will see a deprecation notice (trying to follow SemVer with migrations is a challenge).

I'm going to dig into this error on the migration. Thank you for reporting it.

[bensheldon]

@morgoth I have a hypothesis. I introduced using FOR UPDATE SKIP LOCKED in addition to the existing advisory locks in the locking SQL. Which I think had the effect of causing lock contention on the good_jobs table. I'm removing the FOR UPDATE SKIP LOCKED statement in #288, which I believe should make that migration run cleanly. Alternatively, you could stop the job workers before running the update, but it was my intention that doing so should not be necessary.

[bensheldon]

@morgoth I just released v1.10.1. Could you see if it lets the migration complete successfully for you?

[morgoth]

I'll try it tomorrow, thanks

[morgoth]

This time migration went fine.
Thank you.