Note: This is a beta release of Red Hat Bugzilla 5.0. The data contained within is a snapshot of the live data so any changes you make will not be reflected in the production Bugzilla. Also email is disabled so feel free to test any aspect of the site that you want. File any problems you find or give feedback here.
Bug 1515376 - DB Migration script failing with Error on AddDeletedOnToContainerQuotaAndItems
Summary: DB Migration script failing with Error on AddDeletedOnToContainerQuotaAndItems
Keywords:
Status: CLOSED CURRENTRELEASE
Alias: None
Product: Red Hat CloudForms Management Engine
Classification: Red Hat
Component: Appliance
Version: 5.9.0
Hardware: Unspecified
OS: Unspecified
high
high
Target Milestone: GA
: 5.10.0
Assignee: Jason Frey
QA Contact: luke couzens
URL:
Whiteboard: black:upgrade:migration
Depends On:
Blocks: 1517840
TreeView+ depends on / blocked
 
Reported: 2017-11-20 17:27 UTC by Jerome Marc
Modified: 2019-02-11 13:54 UTC (History)
5 users (show)

Fixed In Version: 5.10.0.0
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
: 1517840 (view as bug list)
Environment:
Last Closed: 2019-02-11 13:54:54 UTC
Category: ---
Cloudforms Team: ---


Attachments (Terms of Use)

Description Jerome Marc 2017-11-20 17:27:56 UTC
Description of problem:
The migration script (bin/rake db:migrate) fails when updating a CF4.5 DB dump to CF4.6.

Version-Release number of selected component (if applicable):
[root@localhost vmdb]# rpm -qa | grep cfme
rh-ruby23-rubygem-redhat_access_cfme-2.0.1-1.el7cf.noarch
cfme-appliance-common-5.9.0.9-1.el7cf.x86_64
cfme-appliance-5.9.0.9-1.el7cf.x86_64
cfme-5.9.0.9-1.el7cf.x86_64
cfme-appliance-tools-5.9.0.9-1.el7cf.x86_64
cfme-gemset-5.9.0.9-1.el7cf.x86_64

How reproducible:
Always (have been trying twice)

Steps to Reproduce:
1. Restore CF4.5 database dump
2. Run vmdb and bin/rake db:migrate

Actual results:
The script ends with an error (see below).

Expected results:
No error.

Additional info:
Running the script a second time succeeds.


== 20171026103833 AddCoresAllocatedRateDetail: migrating ======================
== 20171026103833 AddCoresAllocatedRateDetail: migrated (0.1004s) =============

== 20171026114327 AddDeletedOnToContainerQuotaAndItems: migrating =============
-- add_column(:container_quotas, :deleted_on, :datetime)
   -> 0.0011s
-- add_index(:container_quotas, :deleted_on)
   -> 0.0031s
-- add_timestamps(:container_quota_items, {:null=>true})
   -> 0.0007s
-- Backfilling container_quota_items timestamps from parent quotas
   -> 0.0426s
-- change_column_null(:container_quota_items, :created_at, false)
rake aborted!
StandardError: An error has occurred, this and all later migrations canceled:

PG::NotNullViolation: ERROR:  column "created_at" contains null values
: ALTER TABLE "container_quota_items" ALTER "created_at" SET NOT NULL
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/connection_adapters/postgresql/database_statements.rb:98:in `async_exec'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/connection_adapters/postgresql/database_statements.rb:98:in `block in execute'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/connection_adapters/abstract_adapter.rb:590:in `block in log'
/opt/rh/cfme-gemset/gems/activesupport-5.0.6/lib/active_support/notifications/instrumenter.rb:21:in `instrument'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/connection_adapters/abstract_adapter.rb:583:in `log'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/connection_adapters/postgresql/database_statements.rb:97:in `execute'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/connection_adapters/postgresql/schema_statements.rb:534:in `change_column_null'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/migration.rb:846:in `block in method_missing'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/migration.rb:815:in `block in say_with_time'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/migration.rb:815:in `say_with_time'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/migration.rb:835:in `method_missing'
/opt/rh/cfme-gemset/bundler/gems/manageiq-schema-828d50c74f4b/db/migrate/20171026114327_add_deleted_on_to_container_quota_and_items.rb:26:in `change'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/migration.rb:789:in `exec_migration'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/migration.rb:773:in `block (2 levels) in migrate'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/migration.rb:772:in `block in migrate'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/connection_adapters/abstract/connection_pool.rb:398:in `with_connection'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/migration.rb:771:in `migrate'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/migration.rb:951:in `migrate'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/migration.rb:1232:in `block in execute_migration_in_transaction'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/migration.rb:1300:in `block in ddl_transaction'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/connection_adapters/abstract/database_statements.rb:232:in `block in transaction'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/connection_adapters/abstract/transaction.rb:189:in `within_new_transaction'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/connection_adapters/abstract/database_statements.rb:232:in `transaction'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/transactions.rb:211:in `transaction'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/migration.rb:1300:in `ddl_transaction'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/migration.rb:1231:in `execute_migration_in_transaction'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/migration.rb:1203:in `block in migrate_without_lock'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/migration.rb:1202:in `each'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/migration.rb:1202:in `migrate_without_lock'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/migration.rb:1150:in `block in migrate'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/migration.rb:1319:in `with_advisory_lock'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/migration.rb:1150:in `migrate'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/migration.rb:1006:in `up'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/migration.rb:984:in `migrate'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/tasks/database_tasks.rb:163:in `migrate'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/railties/databases.rake:58:in `block (2 levels) in <top (required)>'

Caused by:
ActiveRecord::StatementInvalid: PG::NotNullViolation: ERROR:  column "created_at" contains null values
: ALTER TABLE "container_quota_items" ALTER "created_at" SET NOT NULL
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/connection_adapters/postgresql/database_statements.rb:98:in `async_exec'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/connection_adapters/postgresql/database_statements.rb:98:in `block in execute'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/connection_adapters/abstract_adapter.rb:590:in `block in log'
/opt/rh/cfme-gemset/gems/activesupport-5.0.6/lib/active_support/notifications/instrumenter.rb:21:in `instrument'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/connection_adapters/abstract_adapter.rb:583:in `log'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/connection_adapters/postgresql/database_statements.rb:97:in `execute'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/connection_adapters/postgresql/schema_statements.rb:534:in `change_column_null'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/migration.rb:846:in `block in method_missing'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/migration.rb:815:in `block in say_with_time'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/migration.rb:815:in `say_with_time'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/migration.rb:835:in `method_missing'
/opt/rh/cfme-gemset/bundler/gems/manageiq-schema-828d50c74f4b/db/migrate/20171026114327_add_deleted_on_to_container_quota_and_items.rb:26:in `change'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/migration.rb:789:in `exec_migration'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/migration.rb:773:in `block (2 levels) in migrate'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/migration.rb:772:in `block in migrate'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/connection_adapters/abstract/connection_pool.rb:398:in `with_connection'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/migration.rb:771:in `migrate'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/migration.rb:951:in `migrate'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/migration.rb:1232:in `block in execute_migration_in_transaction'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/migration.rb:1300:in `block in ddl_transaction'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/connection_adapters/abstract/database_statements.rb:232:in `block in transaction'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/connection_adapters/abstract/transaction.rb:189:in `within_new_transaction'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/connection_adapters/abstract/database_statements.rb:232:in `transaction'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/transactions.rb:211:in `transaction'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/migration.rb:1300:in `ddl_transaction'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/migration.rb:1231:in `execute_migration_in_transaction'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/migration.rb:1203:in `block in migrate_without_lock'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/migration.rb:1202:in `each'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/migration.rb:1202:in `migrate_without_lock'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/migration.rb:1150:in `block in migrate'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/migration.rb:1319:in `with_advisory_lock'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/migration.rb:1150:in `migrate'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/migration.rb:1006:in `up'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/migration.rb:984:in `migrate'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/tasks/database_tasks.rb:163:in `migrate'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/railties/databases.rake:58:in `block (2 levels) in <top (required)>'

Caused by:
PG::NotNullViolation: ERROR:  column "created_at" contains null values
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/connection_adapters/postgresql/database_statements.rb:98:in `async_exec'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/connection_adapters/postgresql/database_statements.rb:98:in `block in execute'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/connection_adapters/abstract_adapter.rb:590:in `block in log'
/opt/rh/cfme-gemset/gems/activesupport-5.0.6/lib/active_support/notifications/instrumenter.rb:21:in `instrument'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/connection_adapters/abstract_adapter.rb:583:in `log'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/connection_adapters/postgresql/database_statements.rb:97:in `execute'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/connection_adapters/postgresql/schema_statements.rb:534:in `change_column_null'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/migration.rb:846:in `block in method_missing'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/migration.rb:815:in `block in say_with_time'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/migration.rb:815:in `say_with_time'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/migration.rb:835:in `method_missing'
/opt/rh/cfme-gemset/bundler/gems/manageiq-schema-828d50c74f4b/db/migrate/20171026114327_add_deleted_on_to_container_quota_and_items.rb:26:in `change'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/migration.rb:789:in `exec_migration'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/migration.rb:773:in `block (2 levels) in migrate'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/migration.rb:772:in `block in migrate'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/connection_adapters/abstract/connection_pool.rb:398:in `with_connection'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/migration.rb:771:in `migrate'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/migration.rb:951:in `migrate'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/migration.rb:1232:in `block in execute_migration_in_transaction'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/migration.rb:1300:in `block in ddl_transaction'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/connection_adapters/abstract/database_statements.rb:232:in `block in transaction'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/connection_adapters/abstract/transaction.rb:189:in `within_new_transaction'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/connection_adapters/abstract/database_statements.rb:232:in `transaction'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/transactions.rb:211:in `transaction'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/migration.rb:1300:in `ddl_transaction'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/migration.rb:1231:in `execute_migration_in_transaction'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/migration.rb:1203:in `block in migrate_without_lock'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/migration.rb:1202:in `each'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/migration.rb:1202:in `migrate_without_lock'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/migration.rb:1150:in `block in migrate'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/migration.rb:1319:in `with_advisory_lock'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/migration.rb:1150:in `migrate'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/migration.rb:1006:in `up'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/migration.rb:984:in `migrate'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/tasks/database_tasks.rb:163:in `migrate'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/railties/databases.rake:58:in `block (2 levels) in <top (required)>'
Tasks: TOP => db:migrate
(See full trace by running task with --trace)

Comment 2 Jason Frey 2017-11-20 20:44:17 UTC
I can confirm I hit the same error migrating the 4.5 MBU Lab database.

Comment 3 Dave Johnson 2017-11-20 21:39:16 UTC
Luke, please work with Einat when verifying this BZ.

Comment 4 Jason Frey 2017-11-21 16:39:05 UTC
I can confirm that if you migrate and the process runs through *both* 20170827091406_change_container_quota_items_columns_to_float.rb and 20171026114327_add_deleted_on_to_container_quota_and_items.rb, then you get this error, but if you run them as separate migration chunks, then it works fine.  This explains why running the script a second time succeeds.

This kind of error is typically a caching error, so I'm continuing to investigate.

Comment 6 CFME Bot 2017-11-21 21:59:29 UTC
New commit detected on ManageIQ/manageiq-schema/master:
https://github.com/ManageIQ/manageiq-schema/commit/ff649d41c71e377d8653f797ef33717c720284e2

commit ff649d41c71e377d8653f797ef33717c720284e2
Author:     Jason Frey <fryguy9@gmail.com>
AuthorDate: Tue Nov 21 14:10:40 2017 -0500
Commit:     Jason Frey <fryguy9@gmail.com>
CommitDate: Tue Nov 21 14:21:39 2017 -0500

    Fix migration column caching.
    
    When this migration is run in the same process as
    20170827091406_change_container_quota_items_columns_to_float.rb, that
    migration does some column caching for its ContainerQuotaItem stub model
    which ends up being inherited by this migration.  The symptom is that
    this migration's stub model does not actually have the created_at
    column, and thus never writes the value.  Later on when
    change_column_null is called, the column has null values in it causing
    that statement to fail.
    
    https://bugzilla.redhat.com/show_bug.cgi?id=1515376

 .../20171026114327_add_deleted_on_to_container_quota_and_items.rb    | 5 ++++-
 1 file changed, 4 insertions(+), 1 deletion(-)

Comment 8 luke couzens 2018-06-20 12:35:36 UTC
Verified in 5.10.0.1


Note You need to log in before you can comment on or make changes to this bug.