Foreman-rake db:migrate fails during Katello 4.1 upgrade

mshade · September 15, 2021, 8:57pm

Problem: During Foreman 2.5/Katello 4.1 upgrade, it’s failing during the db:migrate section.
I reverted to the snapshot to start over to make sure I didn’t miss anything. Tried “foreman-rake db:migrate” and it came back clean. Started the upgrade process and foreman-installer again failed with the same error “PG::NotNullViolation: ERROR: column “position” contains null values”

This is my second server to upgrade today, and we keep both relatively the same. The other server updated easily. However, we are upgrading to 4.1 because we had recently performed the pulp3 migration (nightmare!) and upgraded to 4.0. But then we started getting the issues with tasks sitting in “wait” state for pulp to start. As a last resort, I updated the other server to 4.1 and everything is working perfectly…as it was meant to work!
I’m just hoping that with everything I’ve tried to get pulp3 migrated and the 4.0 upgrade hasn’t hosed up something. All appeared to be fine except the “wait” state on many tasks, which essentially stopped any production.

Expected outcome: foreman-installer completes successfully

Foreman and Proxy versions:
Foreman

Distribution and version: CentOS 7

Other relevant data:

2021-09-15 16:09:37 [DEBUG ] [configure] Postgresql::Server::Db[foreman]: The container Class[Foreman::Database::Postgresql] will propagate my refresh event
2021-09-15 16:09:37 [DEBUG ] [configure] Postgresql::Server::Db[foreman]: Evaluated in 0.00 seconds
2021-09-15 16:09:37 [DEBUG ] [configure] Class[Foreman::Database::Postgresql]: Starting to evaluate the resource
2021-09-15 16:09:37 [DEBUG ] [configure] Class[Foreman::Database::Postgresql]: The container Stage[main] will propagate my refresh event
2021-09-15 16:09:37 [DEBUG ] [configure] Class[Foreman::Database::Postgresql]: The container Class[Foreman::Database] will propagate my refresh event
2021-09-15 16:09:37 [DEBUG ] [configure] Class[Foreman::Database::Postgresql]: Scheduling refresh of Foreman::Rake[db:migrate]
2021-09-15 16:09:37 [DEBUG ] [configure] Class[Foreman::Database::Postgresql]: Evaluated in 0.00 seconds
2021-09-15 16:09:37 [DEBUG ] [configure] Foreman::Rake[db:migrate]: Starting to evaluate the resource
2021-09-15 16:09:37 [DEBUG ] [configure] Foreman::Rake[db:migrate]: Scheduling refresh of Exec[foreman-rake-db:migrate]
2021-09-15 16:09:37 [DEBUG ] [configure] Foreman::Rake[db:migrate]: Evaluated in 0.00 seconds
2021-09-15 16:09:37 [DEBUG ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]: Starting to evaluate the resource
2021-09-15 16:09:37 [DEBUG ] [configure] Exec[foreman-rake-db:migrate](provider=posix): Executing check '/usr/sbin/foreman-rake db:abort_if_pending_migrations'
2021-09-15 16:09:37 [DEBUG ] [configure] Executing with uid=foreman: '/usr/sbin/foreman-rake db:abort_if_pending_migrations'
2021-09-15 16:09:51 [DEBUG ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/unless: `/usr/share/foreman` is not writable.
2021-09-15 16:09:51 [DEBUG ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/unless: Bundler will use `/tmp/bundler20210915-105565-17g84r7105565' as your home directory temporarily.
2021-09-15 16:09:51 [DEBUG ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/unless: Rubocop not loaded.
2021-09-15 16:09:51 [DEBUG ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/unless: API controllers newer than Apipie cache! Run apipie:cache rake task to regenerate cache.
2021-09-15 16:09:51 [DEBUG ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/unless: Run `rails db:migrate` to update your database then try again.
2021-09-15 16:09:51 [DEBUG ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/unless: You have 25 pending migrations:
2021-09-15 16:09:51 [DEBUG ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/unless:   20201019074925 CreateOvalPolicy
2021-09-15 16:09:51 [DEBUG ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/unless:   20201020113801 CreateOvalFacet
2021-09-15 16:09:51 [DEBUG ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/unless:   20201021084109 CreateHostgroupOvalFacet
2021-09-15 16:09:51 [DEBUG ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/unless:   20201106080924 CreateOvalContent
2021-09-15 16:09:51 [DEBUG ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/unless:   20201116110256 AddOvalContentToOvalPolicy
2021-09-15 16:09:51 [DEBUG ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/unless:   20201120080329 CreateCves
2021-09-15 16:09:51 [DEBUG ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/unless:   20201217130800 AddHasErrataToCve
2021-09-15 16:09:51 [DEBUG ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/unless:   20201217161511 AddUrlToOvalContent
2021-09-15 16:09:51 [DEBUG ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/unless:   20210115124508 TemplateKindRegistration
2021-09-15 16:09:51 [DEBUG ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/unless:   20210120150019 AddPositionToAnsibleRole
2021-09-15 16:09:51 [DEBUG ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/unless:   20210224160921 RemoveDisabledProductsFromSyncPlans
2021-09-15 16:09:51 [DEBUG ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/unless:   20210302165636 RemoveKatelloPuppetModules
2021-09-15 16:09:51 [DEBUG ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/unless:   20210309160925 CreateKatelloContentViewVersionImportHistories
2021-09-15 16:09:51 [DEBUG ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/unless:   20210312074713 AddProviderInputs
2021-09-15 16:09:51 [DEBUG ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/unless:   20210317090500 AddDisksTotalToHostFacets
2021-09-15 16:09:51 [DEBUG ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/unless:   20210318204533 AddImportTypeToImportHistories
2021-09-15 16:09:51 [DEBUG ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/unless:   20210319123300 AddForeignKeysToImportExportHistories
2021-09-15 16:09:51 [DEBUG ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/unless:   20210322142311 AddAuthUrlTokenToRootRepositories
2021-09-15 16:09:51 [DEBUG ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/unless:   20210331180353 KatelloPoolOrganizationIdNotNullable
2021-09-15 16:09:51 [DEBUG ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/unless:   20210401124332 DropDbPendingMigrationSetting
2021-09-15 16:09:51 [DEBUG ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/unless:   20210409033915 AddCreatedInKatelloToTaxonomy
2021-09-15 16:09:51 [DEBUG ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/unless:   20210409095625 AddOvalPolicyReferenceToCve
2021-09-15 16:09:51 [DEBUG ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/unless:   20210512170039 AddRepoTimestamps
2021-09-15 16:09:51 [DEBUG ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/unless:   20210609093404 DropOverrideTaxonomiesFromFilter
2021-09-15 16:09:51 [DEBUG ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/unless:   2021051713291621250977 AddHostProxyInvocations
2021-09-15 16:09:51 [DEBUG ] [configure] Exec[foreman-rake-db:migrate](provider=posix): Executing '/usr/sbin/foreman-rake db:migrate'
2021-09-15 16:09:51 [DEBUG ] [configure] Executing with uid=foreman: '/usr/sbin/foreman-rake db:migrate'
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: `/usr/share/foreman` is not writable.
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: Bundler will use `/tmp/bundler20210915-106487-1pjzbjn106487' as your home directory temporarily.
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: Rubocop not loaded.
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: API controllers newer than Apipie cache! Run apipie:cache rake task to regenerate cache.
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: rake aborted!
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: StandardError: An error has occurred, this and all later migrations canceled:
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns:
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: PG::NotNullViolation: ERROR:  column "position" contains null values
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: /opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-6.0.3.7/lib/active_record/connection_adapters/postgresql/database_statements.rb:92:in `async_exec'
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: /opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-6.0.3.7/lib/active_record/connection_adapters/postgresql/database_statements.rb:92:in `block (2 levels) in execute'
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: /opt/theforeman/tfm/root/usr/share/gems/gems/activesupport-6.0.3.7/lib/active_support/dependencies/interlock.rb:48:in `block in permit_concurrent_loads'
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: /opt/theforeman/tfm/root/usr/share/gems/gems/activesupport-6.0.3.7/lib/active_support/concurrency/share_lock.rb:187:in `yield_shares'
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: /opt/theforeman/tfm/root/usr/share/gems/gems/activesupport-6.0.3.7/lib/active_support/dependencies/interlock.rb:47:in `permit_concurrent_loads'
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: /opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-6.0.3.7/lib/active_record/connection_adapters/postgresql/database_statements.rb:91:in `block in execute'
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: /opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-6.0.3.7/lib/active_record/connection_adapters/abstract_adapter.rb:722:in `block (2 levels) in log'
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: /opt/theforeman/tfm/root/usr/share/gems/gems/activesupport-6.0.3.7/lib/active_support/concurrency/load_interlock_aware_monitor.rb:26:in `block (2 levels) in synchronize'
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: /opt/theforeman/tfm/root/usr/share/gems/gems/activesupport-6.0.3.7/lib/active_support/concurrency/load_interlock_aware_monitor.rb:25:in `handle_interrupt'
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: /opt/theforeman/tfm/root/usr/share/gems/gems/activesupport-6.0.3.7/lib/active_support/concurrency/load_interlock_aware_monitor.rb:25:in `block in synchronize'
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: /opt/theforeman/tfm/root/usr/share/gems/gems/activesupport-6.0.3.7/lib/active_support/concurrency/load_interlock_aware_monitor.rb:21:in `handle_interrupt'
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: /opt/theforeman/tfm/root/usr/share/gems/gems/activesupport-6.0.3.7/lib/active_support/concurrency/load_interlock_aware_monitor.rb:21:in `synchronize'
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: /opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-6.0.3.7/lib/active_record/connection_adapters/abstract_adapter.rb:721:in `block in log'
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: /opt/theforeman/tfm/root/usr/share/gems/gems/activesupport-6.0.3.7/lib/active_support/notifications/instrumenter.rb:24:in `instrument'
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: /opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-6.0.3.7/lib/active_record/connection_adapters/abstract_adapter.rb:712:in `log'
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: /opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-6.0.3.7/lib/active_record/connection_adapters/postgresql/database_statements.rb:90:in `execute'
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: /opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-6.0.3.7/lib/active_record/connection_adapters/postgresql/schema_statements.rb:417:in `change_column_null'
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: /opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-6.0.3.7/lib/active_record/migration.rb:890:in `block in method_missing'
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: /opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-6.0.3.7/lib/active_record/migration.rb:858:in `block in say_with_time'
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: /opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-6.0.3.7/lib/active_record/migration.rb:858:in `say_with_time'
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: /opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-6.0.3.7/lib/active_record/migration.rb:879:in `method_missing'
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: /opt/theforeman/tfm/root/usr/share/gems/gems/foreman_ansible-6.3.4/db/migrate/20210120150019_add_position_to_ansible_role.rb:8:in `change'
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: /opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-6.0.3.7/lib/active_record/migration.rb:828:in `exec_migration'
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: /opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-6.0.3.7/lib/active_record/migration.rb:812:in `block (2 levels) in migrate'
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: /opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-6.0.3.7/lib/active_record/migration.rb:811:in `block in migrate'
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: /opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-6.0.3.7/lib/active_record/connection_adapters/abstract/connection_pool.rb:471:in `with_connection'
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: /opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-6.0.3.7/lib/active_record/migration.rb:810:in `migrate'
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: /opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-6.0.3.7/lib/active_record/migration.rb:1002:in `migrate'
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: /opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-6.0.3.7/lib/active_record/migration.rb:1310:in `block in execute_migration_in_transaction'
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: /opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-6.0.3.7/lib/active_record/migration.rb:1361:in `block in ddl_transaction'
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: /opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-6.0.3.7/lib/active_record/connection_adapters/abstract/database_statements.rb:280:in `block in transaction'
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: /opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-6.0.3.7/lib/active_record/connection_adapters/abstract/transaction.rb:280:in `block in within_new_transaction'
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: /opt/theforeman/tfm/root/usr/share/gems/gems/activesupport-6.0.3.7/lib/active_support/concurrency/load_interlock_aware_monitor.rb:26:in `block (2 levels) in synchronize'
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: /opt/theforeman/tfm/root/usr/share/gems/gems/activesupport-6.0.3.7/lib/active_support/concurrency/load_interlock_aware_monitor.rb:25:in `handle_interrupt'
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: /opt/theforeman/tfm/root/usr/share/gems/gems/activesupport-6.0.3.7/lib/active_support/concurrency/load_interlock_aware_monitor.rb:25:in `block in synchronize'
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: /opt/theforeman/tfm/root/usr/share/gems/gems/activesupport-6.0.3.7/lib/active_support/concurrency/load_interlock_aware_monitor.rb:21:in `handle_interrupt'
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: /opt/theforeman/tfm/root/usr/share/gems/gems/activesupport-6.0.3.7/lib/active_support/concurrency/load_interlock_aware_monitor.rb:21:in `synchronize'
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: /opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-6.0.3.7/lib/active_record/connection_adapters/abstract/transaction.rb:278:in `within_new_transaction'
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: /opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-6.0.3.7/lib/active_record/connection_adapters/abstract/database_statements.rb:280:in `transaction'
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: /opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-6.0.3.7/lib/active_record/transactions.rb:212:in `transaction'
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: /opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-6.0.3.7/lib/active_record/migration.rb:1361:in `ddl_transaction'
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: /opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-6.0.3.7/lib/active_record/migration.rb:1309:in `execute_migration_in_transaction'
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: /opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-6.0.3.7/lib/active_record/migration.rb:1281:in `block in migrate_without_lock'
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: /opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-6.0.3.7/lib/active_record/migration.rb:1280:in `each'
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: /opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-6.0.3.7/lib/active_record/migration.rb:1280:in `migrate_without_lock'
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: /opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-6.0.3.7/lib/active_record/migration.rb:1229:in `block in migrate'
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: /opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-6.0.3.7/lib/active_record/migration.rb:1382:in `with_advisory_lock'
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: /opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-6.0.3.7/lib/active_record/migration.rb:1229:in `migrate'
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: /opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-6.0.3.7/lib/active_record/migration.rb:1061:in `up'
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: /opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-6.0.3.7/lib/active_record/migration.rb:1036:in `migrate'
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: /opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-6.0.3.7/lib/active_record/tasks/database_tasks.rb:238:in `migrate'
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: /opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-6.0.3.7/lib/active_record/railties/databases.rake:86:in `block (3 levels) in <top (required)>'
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: /opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-6.0.3.7/lib/active_record/railties/databases.rake:84:in `each'
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: /opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-6.0.3.7/lib/active_record/railties/databases.rake:84:in `block (2 levels) in <top (required)>'
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: /opt/rh/rh-ruby27/root/usr/share/gems/gems/rake-13.0.1/exe/rake:27:in `<top (required)>'
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns:
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: Caused by:
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: ActiveRecord::NotNullViolation: PG::NotNullViolation: ERROR:  column "position" contains null values
.
. and that trace repeats twice, then
.
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: Tasks: TOP => db:migrate
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: (See full trace by running task with --trace)
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: == 20201019074925 CreateOvalPolicy: migrating =================================
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: -- create_table(:foreman_openscap_oval_policies)
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns:    -> 0.4377s
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: == 20201019074925 CreateOvalPolicy: migrated (0.4378s) ========================
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns:
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: == 20201020113801 CreateOvalFacet: migrating ==================================
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: -- create_table(:foreman_openscap_oval_facets)
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns:    -> 0.0515s
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: -- add_index(:foreman_openscap_oval_facets, [:host_id], {:unique=>true, :name=>:foreman_openscap_oval_facets_host_id})
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns:    -> 0.0085s
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: -- create_table(:foreman_openscap_oval_facet_oval_policies)
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns:    -> 0.0144s
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: == 20201020113801 CreateOvalFacet: migrated (0.0745s) =========================
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns:
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: == 20201021084109 CreateHostgroupOvalFacet: migrating =========================
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: -- create_table(:foreman_openscap_hostgroup_oval_facets)
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns:    -> 0.0104s
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: -- add_index(:foreman_openscap_hostgroup_oval_facets, [:hostgroup_id], {:unique=>true, :name=>:foreman_openscap_hostgroup_oval_facets_hostgroup_id})
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns:    -> 0.0046s
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: -- create_table(:foreman_openscap_hostgroup_oval_facet_oval_policies)
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns:    -> 0.0197s
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: == 20201021084109 CreateHostgroupOvalFacet: migrated (0.0349s) ================
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns:
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: == 20201106080924 CreateOvalContent: migrating ================================
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: -- create_table(:foreman_openscap_oval_contents)
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns:    -> 0.0078s
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: -- add_index(:foreman_openscap_oval_contents, :name, {:unique=>true})
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns:    -> 0.0138s
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: == 20201106080924 CreateOvalContent: migrated (0.0217s) =======================
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns:
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: == 20201116110256 AddOvalContentToOvalPolicy: migrating =======================
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: -- add_column(:foreman_openscap_oval_policies, :oval_content_id, :integer, {:references=>:oval_content})
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns:    -> 0.0006s
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: == 20201116110256 AddOvalContentToOvalPolicy: migrated (0.0006s) ==============
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns:
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: == 20201120080329 CreateCves: migrating =======================================
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: -- create_table(:foreman_openscap_cves)
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns:    -> 0.0066s
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: -- create_table(:foreman_openscap_host_cves)
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns:    -> 0.0312s
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: == 20201120080329 CreateCves: migrated (0.0379s) ==============================
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns:
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: == 20201217130800 AddHasErrataToCve: migrating ================================
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: -- add_column(:foreman_openscap_cves, :has_errata, :boolean)
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns:    -> 0.0006s
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: -- add_column(:foreman_openscap_cves, :definition_id, :string, {:null=>false})
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns:    -> 0.0004s
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: -- change_column(:foreman_openscap_cves, :ref_id, :string, {:null=>false})
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns:    -> 0.0003s
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: -- change_column(:foreman_openscap_cves, :ref_url, :string, {:null=>false})
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns:    -> 0.0003s
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: == 20201217130800 AddHasErrataToCve: migrated (0.0017s) =======================
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns:
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: == 20201217161511 AddUrlToOvalContent: migrating ==============================
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: -- add_column(:foreman_openscap_oval_contents, :url, :string)
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns:    -> 0.0004s
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: == 20201217161511 AddUrlToOvalContent: migrated (0.0005s) =====================
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns:
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: == 20210115124508 TemplateKindRegistration: migrating =========================
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: == 20210115124508 TemplateKindRegistration: migrated (0.5351s) ================
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns:
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: == 20210120150019 AddPositionToAnsibleRole: migrating =========================
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: -- add_column(:host_ansible_roles, :position, :integer)
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns:    -> 0.0357s
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: -- add_column(:hostgroup_ansible_roles, :position, :integer)
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns:    -> 0.0006s
2021-09-15 16:10:06 [INFO  ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: -- change_column_null(:host_ansible_roles, :position, false)
2021-09-15 16:10:06 [ERROR ] [configure] '/usr/sbin/foreman-rake db:migrate' returned 1 instead of one of [0]
2021-09-15 16:10:06 [ERROR ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/returns: change from 'notrun' to ['0'] failed: '/usr/sbin/foreman-rake db:migrate' returned 1 instead of one of [0]
2021-09-15 16:10:06 [DEBUG ] [configure] Exec[foreman-rake-db:migrate](provider=posix): Executing check '/usr/sbin/foreman-rake db:abort_if_pending_migrations'
2021-09-15 16:10:06 [DEBUG ] [configure] Executing with uid=foreman: '/usr/sbin/foreman-rake db:abort_if_pending_migrations'
2021-09-15 16:10:20 [DEBUG ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/unless: `/usr/share/foreman` is not writable.
2021-09-15 16:10:20 [DEBUG ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/unless: Bundler will use `/tmp/bundler20210915-108817-y5cekj108817' as your home directory temporarily.
2021-09-15 16:10:20 [DEBUG ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/unless: Rubocop not loaded.
2021-09-15 16:10:20 [DEBUG ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/unless: API controllers newer than Apipie cache! Run apipie:cache rake task to regenerate cache.
2021-09-15 16:10:20 [DEBUG ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/unless: Run `rails db:migrate` to update your database then try again.
2021-09-15 16:10:20 [DEBUG ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/unless: You have 16 pending migrations:
2021-09-15 16:10:20 [DEBUG ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/unless:   20210120150019 AddPositionToAnsibleRole
2021-09-15 16:10:20 [DEBUG ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/unless:   20210224160921 RemoveDisabledProductsFromSyncPlans
2021-09-15 16:10:20 [DEBUG ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/unless:   20210302165636 RemoveKatelloPuppetModules
2021-09-15 16:10:20 [DEBUG ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/unless:   20210309160925 CreateKatelloContentViewVersionImportHistories
2021-09-15 16:10:20 [DEBUG ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/unless:   20210312074713 AddProviderInputs
2021-09-15 16:10:20 [DEBUG ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/unless:   20210317090500 AddDisksTotalToHostFacets
2021-09-15 16:10:20 [DEBUG ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/unless:   20210318204533 AddImportTypeToImportHistories
2021-09-15 16:10:20 [DEBUG ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/unless:   20210319123300 AddForeignKeysToImportExportHistories
2021-09-15 16:10:20 [DEBUG ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/unless:   20210322142311 AddAuthUrlTokenToRootRepositories
2021-09-15 16:10:20 [DEBUG ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/unless:   20210331180353 KatelloPoolOrganizationIdNotNullable
2021-09-15 16:10:20 [DEBUG ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/unless:   20210401124332 DropDbPendingMigrationSetting
2021-09-15 16:10:20 [DEBUG ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/unless:   20210409033915 AddCreatedInKatelloToTaxonomy
2021-09-15 16:10:20 [DEBUG ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/unless:   20210409095625 AddOvalPolicyReferenceToCve
2021-09-15 16:10:20 [DEBUG ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/unless:   20210512170039 AddRepoTimestamps
2021-09-15 16:10:20 [DEBUG ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/unless:   20210609093404 DropOverrideTaxonomiesFromFilter
2021-09-15 16:10:20 [DEBUG ] [configure] /Stage[main]/Foreman::Database/Foreman::Rake[db:migrate]/Exec[foreman-rake-db:migrate]/unless:   2021051713291621250977 AddHostProxyInvocations

Marek_Hulan · September 16, 2021, 7:27am

The backtrace shows that there’s a problem with the foreman_ansible (6.3.4) migration. The migration adds the column, then it should fill in the position values and then forbid the null value. For some reason, the position wasn’t saved.

cc @Ondrej_Prazak this seems as a valid bug, not sure why we didn’t see that elsewhere. Perhaps the HostAnsibleRole or HostgroupAnsibleRole update failed since it’s invalid for some reason on this instance.

mshade · September 20, 2021, 4:54am

Anything I can get to help further this? Logs?
I can’t really go anywhere until I can get this resolved. No updates, several repository syncs fail. Can’t even delete those repos…those tasks sit in wait state.

mshade · September 27, 2021, 8:05pm

Anything? I’m kinda stuck here as many tasks still go straight to wait state, including those to sync or even delete repositories.

mshade · September 30, 2021, 5:09pm

Anything @Marek_Hulan @Ondrej_Prazak ?

Ondrej_Prazak · October 4, 2021, 11:52am

I am looking into this, to find out why the migration would fail. One of the possibilities that a host with ansible roles somehow became invalid - I’ll need to test to see if I can simulate that failure.

Ondrej_Prazak · October 12, 2021, 7:24am

I tried all the scenarios I could think of but I had no luck in reproducing the error. I opened https://github.com/theforeman/foreman_ansible/pull/468 which should provide details about why the migration failed.