DSpace upgrade 5 to 6.1 results in Flyway migration error

1,152 views
Skip to first unread message

Tao Zhao

unread,
Sep 22, 2017, 4:53:13 PM9/22/17
to DSpace Technical Support
java.sql.SQLException: Flyway migration error occurred
        at org.dspace.storage.rdbms.DatabaseUtils.updateDatabase(DatabaseUtils.java:666)
        at org.dspace.storage.rdbms.DatabaseUtils.updateDatabase(DatabaseUtils.java:574)
        at org.dspace.storage.rdbms.DatabaseUtils.updateDatabase(DatabaseUtils.java:550)
        at org.dspace.core.Context.<clinit>(Context.java:103)
        at org.dspace.app.util.AbstractDSpaceWebapp.register(AbstractDSpaceWebapp.java:74)
        at org.dspace.app.util.DSpaceWebappListener.contextInitialized(DSpaceWebappListener.java:31)
        at org.apache.catalina.core.StandardContext.listenerStart(StandardContext.java:5118)
        at org.apache.catalina.core.StandardContext.startInternal(StandardContext.java:5634)
        at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:145)
"../log/dspace.log.2017-09-22" 2409L, 329890C

This is becuase some tables are missing some columns, e.g.

2017-09-22 15:17:44,028 FATAL org.dspace.core.Context @ Cannot obtain the bean which provides a database connection. Check previous entries in the dspace.log to find why the db failed to initialize. The schema validator returned: Missing column: uuid in public.bitstream

The similar error also happened to table doi, which is missing column dspace_object.


Have you ever seen this error during upgrading and how did you fix it?

Thanks.

Tao Zhao

unread,
Sep 26, 2017, 12:55:14 PM9/26/17
to DSpace Technical Support
 Forgot to post the complete Flyway exception info which might be useful:

 
.rdbms.migration
2017-09-26 11:41:34,298 INFO  org.flywaydb.core.internal.util.VersionPrinter @ Flyway 4.0.3 by Boxfuse
2017-09-26 11:41:34,326 INFO  org.flywaydb.core.internal.dbsupport.DbSupportFactory @ Database: jdbc:postgresql://localhost:5432/dspace2 (PostgreSQL 9.4)
2017-09-26 11:41:34,364 INFO  org.flywaydb.core.internal.metadatatable.MetaDataTableImpl @ Upgrading metadata table "public"."schema_version" to the Flyway 4.0 format ...
2017-09-26 11:41:34,418 INFO  org.flywaydb.core.internal.metadatatable.MetaDataTableImpl @ Updating checksum of 3.0 to -1098885663 ...
2017-09-26 11:41:34,423 INFO  org.flywaydb.core.internal.metadatatable.MetaDataTableImpl @ Updating checksum of 4.0 to 1191833374 ...
2017-09-26 11:41:34,425 INFO  org.flywaydb.core.internal.metadatatable.MetaDataTableImpl @ Updating checksum of 5.0.2014.08.08 to -1208221648 ...
2017-09-26 11:41:34,426 INFO  org.flywaydb.core.internal.metadatatable.MetaDataTableImpl @ Updating checksum of 5.0.2014.09.26 to 1509433410 ...
2017-09-26 11:41:34,427 INFO  org.flywaydb.core.Flyway @ Metadata table schema_version successfully upgraded to the Flyway 4.0 format.
2017-09-26 11:41:34,444 INFO  org.dspace.storage.rdbms.DatabaseUtils @ Pending DSpace database schema migrations:
2017-09-26 11:41:34,444 INFO  org.dspace.storage.rdbms.DatabaseUtils @  5.6.2016.08.23 DS-3097 SQL PENDING
2017-09-26 11:41:34,444 INFO  org.dspace.storage.rdbms.DatabaseUtils @  5.7.2017.04.11 DS-3563 Index metadatavalue resource type id column SQL PENDING
2017-09-26 11:41:34,444 INFO  org.dspace.storage.rdbms.DatabaseUtils @  5.7.2017.05.05 DS 3431 Add Policies for BasicWorkflow JDBC PENDING
2017-09-26 11:41:34,444 INFO  org.dspace.storage.rdbms.DatabaseUtils @  6.0.2015.03.06 DS 2701 Dso Uuid Migration JDBC PENDING
2017-09-26 11:41:34,444 INFO  org.dspace.storage.rdbms.DatabaseUtils @  6.0.2015.03.07 DS-2701 Hibernate migration SQL PENDING
2017-09-26 11:41:34,444 INFO  org.dspace.storage.rdbms.DatabaseUtils @  6.0.2015.08.31 DS 2701 Hibernate Workflow Migration JDBC PENDING
2017-09-26 11:41:34,444 INFO  org.dspace.storage.rdbms.DatabaseUtils @  6.0.2016.01.03 DS-3024 SQL PENDING
2017-09-26 11:41:34,444 INFO  org.dspace.storage.rdbms.DatabaseUtils @  6.0.2016.01.26 DS 2188 Remove DBMS Browse Tables JDBC PENDING
2017-09-26 11:41:34,444 INFO  org.dspace.storage.rdbms.DatabaseUtils @  6.0.2016.02.25 DS-3004-slow-searching-as-admin SQL PENDING
2017-09-26 11:41:34,444 INFO  org.dspace.storage.rdbms.DatabaseUtils @  6.0.2016.04.01 DS-1955 Increase embargo reason SQL PENDING
2017-09-26 11:41:34,444 INFO  org.dspace.storage.rdbms.DatabaseUtils @  6.0.2016.04.04 DS-3086-OAI-Performance-fix SQL PENDING
2017-09-26 11:41:34,444 INFO  org.dspace.storage.rdbms.DatabaseUtils @  6.0.2016.04.14 DS-3125-fix-bundle-bitstream-delete-rights SQL PENDING
2017-09-26 11:41:34,444 INFO  org.dspace.storage.rdbms.DatabaseUtils @  6.0.2016.05.10 DS-3168-fix-requestitem item id column SQL PENDING
2017-09-26 11:41:34,444 INFO  org.dspace.storage.rdbms.DatabaseUtils @  6.0.2016.07.21 DS-2775 SQL PENDING
2017-09-26 11:41:34,444 INFO  org.dspace.storage.rdbms.DatabaseUtils @  6.0.2016.07.26 DS-3277 fix handle assignment SQL PENDING
2017-09-26 11:41:34,445 INFO  org.dspace.storage.rdbms.DatabaseUtils @  6.0.2016.08.23 DS-3097 SQL PENDING
2017-09-26 11:41:34,445 INFO  org.dspace.storage.rdbms.DatabaseUtils @  6.1.2017.01.03 DS 3431 Add Policies for BasicWorkflow JDBC PENDING
2017-09-26 11:41:34,495 FATAL org.dspace.core.Context @ Cannot initialize database via Flyway!

java.sql.SQLException: Flyway migration error occurred
        at org.dspace.storage.rdbms.DatabaseUtils.updateDatabase(DatabaseUtils.java:666)
        at org.dspace.storage.rdbms.DatabaseUtils.updateDatabase(DatabaseUtils.java:574)
        at org.dspace.storage.rdbms.DatabaseUtils.updateDatabase(DatabaseUtils.java:550)
        at org.dspace.core.Context.<clinit>(Context.java:103)
        at org.dspace.app.util.AbstractDSpaceWebapp.register(AbstractDSpaceWebapp.java:74)
        at org.dspace.app.util.DSpaceWebappListener.contextInitialized(DSpaceWebappListener.java:31)
        at org.apache.catalina.core.StandardContext.listenerStart(StandardContext.java:5118)
        at org.apache.catalina.core.StandardContext.startInternal(StandardContext.java:5634)
        at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:145)
        at org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase.java:899)
        at org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:875)
        at org.apache.catalina.core.StandardHost.addChild(StandardHost.java:652)
        at org.apache.catalina.startup.HostConfig.deployDescriptor(HostConfig.java:679)
        at org.apache.catalina.startup.HostConfig$DeployDescriptor.run(HostConfig.java:1966)
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
        at java.util.concurrent.FutureTask.run(FutureTask.java:266)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at java.lang.Thread.run(Thread.java:748)
Caused by: org.flywaydb.core.api.FlywayException: Validate failed: Detected applied migration not resolved locally: 5.0.2014.11.04
        at org.flywaydb.core.Flyway.doValidate(Flyway.java:1008)
        at org.flywaydb.core.Flyway.access$100(Flyway.java:72)
        at org.flywaydb.core.Flyway$1.execute(Flyway.java:921)
        at org.flywaydb.core.Flyway$1.execute(Flyway.java:917)
        at org.flywaydb.core.Flyway.execute(Flyway.java:1373)
        at org.flywaydb.core.Flyway.migrate(Flyway.java:917)
        at org.dspace.storage.rdbms.DatabaseUtils.updateDatabase(DatabaseUtils.java:655)
        ... 18 more
2017-09-26 11:41:34,512 INFO  org.dspace.event.EventServiceImpl @ EventService dispatcher pool initialized
2017-09-26 11:41:34,708 INFO  org.hibernate.annotations.common.Version @ HCANN000001: Hibernate Commons Annotations {4.0.2.Final}
2017-09-26 11:41:34,716 INFO  org.hibernate.Version @ HHH000412: Hibernate Core {4.2.21.Final}
2017-09-26 11:41:34,723 INFO  org.hibernate.cfg.Environment @ HHH000206: hibernate.properties not found
2017-09-26 11:41:34,724 INFO  org.hibernate.cfg.Environment @ HHH000021: Bytecode provider name : javassist
2017-09-26 11:41:34,742 INFO  org.hibernate.cfg.Configuration @ HHH000044: Configuring from URL: file:/srv/oulib/dspace//config/hibernate.cfg.xml
2017-09-26 11:41:34,786 INFO  org.hibernate.cfg.Configuration @ HHH000041: Configured SessionFactory: null
2017-09-26 11:41:34,984 INFO  org.hibernate.dialect.Dialect @ HHH000400: Using dialect: org.dspace.storage.rdbms.hibernate.postgres.DSpacePostgreSQL82Dialect
2017-09-26 11:41:35,020 INFO  org.hibernate.engine.jdbc.internal.LobCreatorBuilder @ HHH000424: Disabling contextual LOB creation as createClob() method threw error : java.lang.reflect.InvocationTargetException
2017-09-26 11:41:35,024 INFO  org.hibernate.type.BasicTypeRegistry @ HHH000270: Type registration [pg-uuid] overrides previous : org.hibernate.type.PostgresUUIDType@111072c7
2017-09-26 11:41:35,024 INFO  org.hibernate.type.BasicTypeRegistry @ HHH000270: Type registration [java.util.UUID] overrides previous : org.hibernate.type.UUIDBinaryType@454ce990
2017-09-26 11:41:35,311 INFO  org.hibernate.engine.transaction.internal.TransactionFactoryInitiator @ HHH000399: Using default transaction strategy (direct JDBC transactions)
2017-09-26 11:41:35,314 INFO  org.hibernate.hql.internal.ast.ASTQueryTranslatorFactory @ HHH000397: Using ASTQueryTranslatorFactory
2017-09-26 11:41:35,382 INFO  org.hibernate.cache.spi.UpdateTimestampsCache @ HHH000250: Starting update timestamps cache at region: org.hibernate.cache.spi.UpdateTimestampsCache
2017-09-26 11:41:35,384 INFO  org.hibernate.cache.internal.StandardQueryCache @ HHH000248: Starting query cache at region: org.hibernate.cache.internal.StandardQueryCache
2017-09-26 11:41:36,072 INFO  org.hibernate.tool.hbm2ddl.SchemaValidator @ HHH000229: Running schema validator
2017-09-26 11:41:36,072 INFO  org.hibernate.tool.hbm2ddl.SchemaValidator @ HHH000102: Fetching database metadata
2017-09-26 11:41:36,097 INFO  org.hibernate.tool.hbm2ddl.TableMetadata @ HHH000261: Table found: public.doi
2017-09-26 11:41:36,097 INFO  org.hibernate.tool.hbm2ddl.TableMetadata @ HHH000037: Columns: [resource_type_id, resource_id, doi_id, doi, status]
2017-09-26 11:41:36,099 INFO  org.hibernate.cfg.Configuration @ HHH000044: Configuring from URL: file:/srv/oulib/dspace//config/hibernate.cfg.xml
2017-09-26 11:41:36,102 INFO  org.hibernate.cfg.Configuration @ HHH000041: Configured SessionFactory: null
Message has been deleted

Tim Donohue

unread,
Sep 26, 2017, 3:39:47 PM9/26/17
to Tao Zhao, DSpace Technical Support
Hello Tao Zhao,

The important error seems to be this one:

Caused by: org.flywaydb.core.api.FlywayException: Validate failed: Detected applied migration not resolved locally: 5.0.2014.11.04 

That error is noting that you previously (likely when you were running DSpace 5) ran a migration that was named "5.0.2014.11.04", but that same migration cannot be found any longer.

The reason for this is that specific "5.0.2014.11.04" migration is an optional one, which is only run when XMLWorkflows are enabled in DSpace:

If you *re-enable* XMLWorkflows in your DSpace 6.1 site, this error should go away.  See Step #8 Part "d" in the Upgrade instructions at: https://wiki.duraspace.org/display/DSDOC6x/Upgrading+DSpace#UpgradingDSpace-UpgradeSteps

Good luck,

Tim

On Tue, Sep 26, 2017 at 12:25 PM Tao Zhao <tao.zh...@gmail.com> wrote:
I saw exactly the same error and could not fix it by running database repair.
--
You received this message because you are subscribed to the Google Groups "DSpace Technical Support" group.
To unsubscribe from this group and stop receiving emails from it, send an email to dspace-tech...@googlegroups.com.
To post to this group, send email to dspac...@googlegroups.com.
Visit this group at https://groups.google.com/group/dspace-tech.
For more options, visit https://groups.google.com/d/optout.
--
Tim Donohue
Technical Lead for DSpace & DSpaceDirect
DuraSpace.org | DSpace.org | DSpaceDirect.org

Tao Zhao

unread,
Sep 26, 2017, 4:50:04 PM9/26/17
to DSpace Technical Support
Thank you very much Tim.

After I did the configuration, the original error was gone. But now a new error shows up:

/[dspace]/bin/dspace database migrate

Database URL: jdbc:postgresql://localhost:5432/dspace3
Migrating database to latest version... (Check dspace logs for details)
Migration exception:

java.sql.SQLException: Flyway migration error occurred
    at org.dspace.storage.rdbms.DatabaseUtils.updateDatabase(DatabaseUtils.java:666)
    at org.dspace.storage.rdbms.DatabaseUtils.updateDatabase(DatabaseUtils.java:574)
    at org.dspace.storage.rdbms.DatabaseUtils.main(DatabaseUtils.java:222)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:498)
    at org.dspace.app.launcher.ScriptLauncher.runOneCommand(ScriptLauncher.java:229)
    at org.dspace.app.launcher.ScriptLauncher.main(ScriptLauncher.java:81)
Caused by: org.flywaydb.core.internal.dbsupport.FlywaySqlScriptException:
Migration V6.0_2015.03.07__DS-2701_Hibernate_migration.sql failed
-----------------------------------------------------------------
SQL State  : 2BP01
Error Code : 0
Message    : ERROR: cannot drop table item column submitter_id_legacy_id because other objects depend on it
  Detail: rule protect_approval_upd on table workflowitem depends on table item column submitter_id_legacy_id
  Hint: Use DROP ... CASCADE to drop the dependent objects too.
Location   : org/dspace/storage/rdbms/sqlmigration/postgres/V6.0_2015.03.07__DS-2701_Hibernate_migration.sql (/srv/oulib/dspace/config/file:/srv/oulib/dspace/lib/dspace-api-6.1.jar!/org/dspace/storage/rdbms/sqlmigration/postgres/V6.0_2015.03.07__DS-2701_Hibernate_migration.sql)
Line       : 248
Statement  : ALTER TABLE item DROP COLUMN submitter_id_legacy_id

    at org.flywaydb.core.internal.dbsupport.SqlScript.execute(SqlScript.java:117)
    at org.flywaydb.core.internal.resolver.sql.SqlMigrationExecutor.execute(SqlMigrationExecutor.java:71)
    at org.flywaydb.core.internal.command.DbMigrate.doMigrate(DbMigrate.java:352)
    at org.flywaydb.core.internal.command.DbMigrate.access$1100(DbMigrate.java:47)
    at org.flywaydb.core.internal.command.DbMigrate$4.doInTransaction(DbMigrate.java:308)
    at org.flywaydb.core.internal.util.jdbc.TransactionTemplate.execute(TransactionTemplate.java:72)
    at org.flywaydb.core.internal.command.DbMigrate.applyMigration(DbMigrate.java:305)
    at org.flywaydb.core.internal.command.DbMigrate.access$1000(DbMigrate.java:47)
    at org.flywaydb.core.internal.command.DbMigrate$2.doInTransaction(DbMigrate.java:230)
    at org.flywaydb.core.internal.command.DbMigrate$2.doInTransaction(DbMigrate.java:173)
    at org.flywaydb.core.internal.util.jdbc.TransactionTemplate.execute(TransactionTemplate.java:72)
    at org.flywaydb.core.internal.command.DbMigrate.migrate(DbMigrate.java:173)
    at org.flywaydb.core.Flyway$1.execute(Flyway.java:959)

    at org.flywaydb.core.Flyway$1.execute(Flyway.java:917)
    at org.flywaydb.core.Flyway.execute(Flyway.java:1373)
    at org.flywaydb.core.Flyway.migrate(Flyway.java:917)
    at org.dspace.storage.rdbms.DatabaseUtils.updateDatabase(DatabaseUtils.java:655)
    ... 8 more
Caused by: org.postgresql.util.PSQLException: ERROR: cannot drop table item column submitter_id_legacy_id because other objects depend on it
  Detail: rule protect_approval_upd on table workflowitem depends on table item column submitter_id_legacy_id
  Hint: Use DROP ... CASCADE to drop the dependent objects too.
    at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2458)
    at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:2158)
    at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:291)
    at org.postgresql.jdbc.PgStatement.executeInternal(PgStatement.java:432)
    at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:358)
    at org.postgresql.jdbc.PgStatement.executeWithFlags(PgStatement.java:305)
    at org.postgresql.jdbc.PgStatement.executeCachedSql(PgStatement.java:291)
    at org.postgresql.jdbc.PgStatement.executeWithFlags(PgStatement.java:269)
    at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:265)
    at org.apache.commons.dbcp2.DelegatingStatement.execute(DelegatingStatement.java:291)
    at org.apache.commons.dbcp2.DelegatingStatement.execute(DelegatingStatement.java:291)
    at org.flywaydb.core.internal.dbsupport.JdbcTemplate.executeStatement(JdbcTemplate.java:238)
    at org.flywaydb.core.internal.dbsupport.SqlScript.execute(SqlScript.java:114)
    ... 24 more

Tao Zhao

unread,
Sep 26, 2017, 5:47:34 PM9/26/17
to DSpace Technical Support
The migration worked after I dropped the rule protect_approval_upd on table workflowitem. It might be a customized change thought I am not sure.

Thanks,

Tao

Tim Donohue

unread,
Sep 26, 2017, 5:47:51 PM9/26/17
to Tao Zhao, DSpace Technical Support
Hello Tao Zhao,

Now it looks like you have a custom database rule that is blocking the DSpace database migration.  Here's the important error:


Message    : ERROR: cannot drop table item column submitter_id_legacy_id because other objects depend on it
  Detail: rule protect_approval_upd on table workflowitem depends on table item column submitter_id_legacy_id
  Hint: Use DROP ... CASCADE to drop the dependent objects too. 

According to that message you have a rule named "protect_approval_upd" applied on your database.  This seems to be something custom that was added to your database, as it is not something that DSpace comes with out of the box.  You'll need to remove that rule for the database migration to proceed.   If you feel the need, you can always add it back in later on (using the new DSpace database table structure.

- Tim 

Tao Zhao

unread,
Sep 26, 2017, 5:48:56 PM9/26/17
to DSpace Technical Support
That is right. Thank you very much Time.

Tao
Reply all
Reply to author
Forward
0 new messages