Failed liquibase upgrade from 2.3 to 2.4

rkmadsen · November 24, 2015, 11:43pm

Has anyone run into a failed upgrade from 2.3 to 2.4 on a liquibase change set related to 2.0? Has anyone successfully upgraded from 2.3 to 2.4? I deleted the admin@admin.com and default institute and then the change sets failed on the upgrade. So I’m assuming that caused the error. Is there a hard dependency in the change sets to run “Script to map departments and institutes” on a existing 2.3 install with the default admin@admin.com and Institute “i”? That mapping/update should have taken place and then is not needed on an upgrade install.

I redeployed the previously built war for 2.3 and it comes up relatively clean.

Here is the error for the 2.4 upgrade deploy:

SEVERE 11/24/15 3:22 PM: liquibase: classpath:db/db-os-changelog-master-upgrade.xml: db/2.0/migration.xml::Script to map departments and institutes::nmarwaha: Change Set db/2.0/migration.xml::Script to map departments and institutes::nmarwaha failed.  Error: com.mysql.jdbc.exceptions.jdbc4.MySQLIntegrityConstraintViolationException: Column 'INSTITUTE_ID' cannot be null
liquibase.exception.DatabaseException: com.mysql.jdbc.exceptions.jdbc4.MySQLIntegrityConstraintViolationException: Column 'INSTITUTE_ID' cannot be null
	at liquibase.executor.jvm.JdbcExecutor$ExecuteStatementCallback.doInStatement(JdbcExecutor.java:316)
	at liquibase.executor.jvm.JdbcExecutor.execute(JdbcExecutor.java:55)
	at liquibase.executor.jvm.JdbcExecutor.execute(JdbcExecutor.java:122)
	at liquibase.database.AbstractJdbcDatabase.execute(AbstractJdbcDatabase.java:1227)
	at liquibase.database.AbstractJdbcDatabase.executeStatements(AbstractJdbcDatabase.java:1210)
	at liquibase.changelog.ChangeSet.execute(ChangeSet.java:550)
	at liquibase.changelog.visitor.UpdateVisitor.visit(UpdateVisitor.java:43)
	at liquibase.changelog.ChangeLogIterator.run(ChangeLogIterator.java:73)
	at liquibase.Liquibase.update(Liquibase.java:200)
	at liquibase.integration.spring.SpringLiquibase.performUpdate(SpringLiquibase.java:402)
	at liquibase.integration.spring.SpringLiquibase.afterPropertiesSet(SpringLiquibase.java:366)
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeInitMethods(AbstractAutowireCapableBeanFactory.java:1573)
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1511)
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:521)
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:458)
	at org.springframework.beans.factory.support.AbstractBeanFactory$1.getObject(AbstractBeanFactory.java:293)
	at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:223)
	at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:290)
	at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:191)
	at org.springframework.beans.factory.support.DefaultListableBeanFactory.preInstantiateSingletons(DefaultListableBeanFactory.java:636)
	at org.springframework.context.support.AbstractApplicationContext.finishBeanFactoryInitialization(AbstractApplicationContext.java:934)
	at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:479)
	at org.springframework.web.context.ContextLoader.configureAndRefreshWebApplicationContext(ContextLoader.java:410)
	at org.springframework.web.context.ContextLoader.initWebApplicationContext(ContextLoader.java:306)
	at org.springframework.web.context.ContextLoaderListener.contextInitialized(ContextLoaderListener.java:112)
	at org.apache.catalina.core.StandardContext.listenerStart(StandardContext.java:5016)
	at org.apache.catalina.core.StandardContext.startInternal(StandardContext.java:5528)
	at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:150)
	at org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase.java:901)
	at org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:877)
	at org.apache.catalina.core.StandardHost.addChild(StandardHost.java:652)
	at org.apache.catalina.startup.HostConfig.deployWAR(HostConfig.java:1090)
	at org.apache.catalina.startup.HostConfig$DeployWar.run(HostConfig.java:1900)
	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:1142)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
	at java.lang.Thread.run(Thread.java:745)
Caused by: com.mysql.jdbc.exceptions.jdbc4.MySQLIntegrityConstraintViolationException: Column 'INSTITUTE_ID' cannot be null
	at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
	at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
	at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
	at java.lang.reflect.Constructor.newInstance(Constructor.java:422)
	at com.mysql.jdbc.Util.handleNewInstance(Util.java:408)
	at com.mysql.jdbc.Util.getInstance(Util.java:383)
	at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:1049)
	at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:4226)
	at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:4158)
	at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2615)
	at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2776)
	at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2834)
	at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2783)
	at com.mysql.jdbc.StatementImpl.execute(StatementImpl.java:908)
	at com.mysql.jdbc.StatementImpl.execute(StatementImpl.java:788)
	at org.apache.tomcat.dbcp.dbcp.DelegatingStatement.execute(DelegatingStatement.java:264)
	at org.apache.tomcat.dbcp.dbcp.DelegatingStatement.execute(DelegatingStatement.java:264)
	at liquibase.executor.jvm.JdbcExecutor$ExecuteStatementCallback.doInStatement(JdbcExecutor.java:314)
	... 37 more
INFO 11/24/15 3:22 PM: liquibase: db/2.0/migration.xml::Script to map departments and institutes::nmarwaha: Successfully released change log lock

Here are the INFO liquibase notices for the redeployed 2.3 war. They are all 2.0 errors again on a 2.3 database.

INFO 11/24/15 3:39 PM: liquibase: classpath:db/db-os-changelog-master-fresh.xml: db/2.0/schema.xml::Drop foreign key from CRG column in CATISSUE_USER::nmarwaha: Change set db/2.0/schema.xml::Drop foreign key from CRG column in CATISSUE_USER::nmarwaha failed, but failOnError was false.  Error: com.mysql.jdbc.exceptions.jdbc4.MySQLSyntaxErrorException: Can't DROP 'FKB025CFC7FFA96920'; check that column/key exists
INFO 11/24/15 3:39 PM: liquibase: classpath:db/db-os-changelog-master-fresh.xml: db/2.0/schema.xml::Drop WUSTLKEY column from CATISSUE_USER::nmarwaha: Change set db/2.0/schema.xml::Drop WUSTLKEY column from CATISSUE_USER::nmarwaha failed, but failOnError was false.  Error: com.mysql.jdbc.exceptions.jdbc4.MySQLSyntaxErrorException: Can't DROP 'WUSTLKEY'; check that column/key exists
INFO 11/24/15 3:39 PM: liquibase: classpath:db/db-os-changelog-master-fresh.xml: db/2.0/schema.xml::Updated user view::vpawar: Custom SQL executed
INFO 11/24/15 3:39 PM: liquibase: classpath:db/db-os-changelog-master-fresh.xml: db/2.0/schema.xml::Updated user view::vpawar: ChangeSet db/2.0/schema.xml::Updated user view::vpawar ran successfully in 7ms
INFO 11/24/15 3:39 PM: liquibase: classpath:db/db-os-changelog-master-fresh.xml: db/2.0/schema.xml::Drop UK on csm_user_id from catissue user table::vlonushte: Change set db/2.0/schema.xml::Drop UK on csm_user_id from catissue user table::vlonushte failed, but failOnError was false.  Error: com.mysql.jdbc.exceptions.jdbc4.MySQLSyntaxErrorException: Can't DROP 'CSM_USER_ID_UNIQUE_KEY'; check that column/key

rkmadsen · November 24, 2015, 11:42pm

So there is a disabled catissue_user ‘admin@admin.com_1445895214624’ that is tied to the institution Id of 1 that does’t get deleted when you delete the institution “i” which I think was id “1”. The admin@admin.com_1445895214624 user is also associated with CAT_QF_OWNER_CAT_USR_ID in catissue_query_folders. The foreign key constraint fails if I try to remove the extraneous admin@ admin.com_1445895214624 user.

I didn’t manually manipulate the db when I deleted the active admin@admin.com and i institute. I used the web app, so either there are some transactions that need to be cleaned up on deleting the default institute and user or it’s intended that they stick around in the db. I would consider that a bug and potentially a security risk. Couldn’t we remove the default admin accounts and institute on a deploy?

nitesh_marwaha · November 25, 2015, 2:36pm

Hi @rkmadsen,

Regarding the deployment error. It seems like during deployment you have specified the parameter -adtype upgrade, which needs to be specified as fresh. Set this flag to upgrade only when the database is upgraded from OpenSpecimen-v1.x.

To resolve this please set deployment_type property to fresh in ${TOMCAT_HOME}/webapps/openspecimen/WEB-INF/classes/application.properties file and restart the tomcat.

~Nitesh

nitesh_marwaha · November 25, 2015, 2:39pm

Hi @rkmadsen,

In OpenSpecimen when any object is deleted from UI its activity status is set to ‘Disabled’ and the unique attributes are appended with timestamp. These deleted records remain in the database but are not displayed on the UI.

Yes you can delete the default admin account and institute after deployment.

~Nitesh

rkmadsen · November 25, 2015, 4:11pm

So I should set it to fresh on an upgrade? Just to clarify I’m upgrading from 2.3 to 2.4 and I should set it to fresh. Correct??

rkmadsen · November 25, 2015, 6:06pm

Ok, I redeployed the app with the install script with “fresh” and it comes up cleanly. Thanks for clarifying. If I could make a few suggestions.

The terms upgrade and fresh are confusing when moving from version to version. I now know the upgrade is intended for 1.x, but perhaps it should be “fresh” for install from scratch, “update” from point version and “upgrade” for major releases.

Another point would be that only fresh versions overwrite server.xml and other tomcat configs. Once I restored and then ran the “fresh” update it clobbered the changes I had made to the tomcat server. It may be good practice to warn folks that the deploy will overwrite configs. As such I set up a stage location to build/stage the war and then I can diff the configs I need to and move the war to the actual tomcat server.

nitesh_marwaha · November 26, 2015, 11:41am

Hi @rkmadsen,

I agree that the current upgrade/fresh terminology is little confusing for the user. We will update the deployment script to make it more clear.

Its a bug in the deployment script that it overwrites the existing tomcat settings. We will fix this in v2.5. For now we have updated the deployment steps by adding the note stating that the upgrade will overwrite the existing tomcat configs.

Thanks for the feedback.

~Nitesh

rkmadsen · December 1, 2015, 12:54am

One more to track down with the 2.3 to 2.4 update. I have another server that is running MySQL 5.7.9 that failed on the schema update from 2.3 to 2.4. Here is the stack trace on the error:

SEVERE 11/30/15 5:14 PM: liquibase: classpath:db/db-os-changelog-master-fresh.xml: db/2.4/schema.xml::User api calls log table::vgaikwad: Change Set db/2.4/schema.xml::User api calls log table::vgaikwad failed.  Error: com.mysql.jdbc.exceptions.jdbc4.MySQLSyntaxErrorException: Invalid default value for 'CALL_END_TIME'
liquibase.exception.DatabaseException: com.mysql.jdbc.exceptions.jdbc4.MySQLSyntaxErrorException: Invalid default value for 'CALL_END_TIME'
	at liquibase.executor.jvm.JdbcExecutor$ExecuteStatementCallback.doInStatement(JdbcExecutor.java:316)
	at liquibase.executor.jvm.JdbcExecutor.execute(JdbcExecutor.java:55)
	at liquibase.executor.jvm.JdbcExecutor.execute(JdbcExecutor.java:122)
	at liquibase.database.AbstractJdbcDatabase.execute(AbstractJdbcDatabase.java:1227)
	at liquibase.database.AbstractJdbcDatabase.executeStatements(AbstractJdbcDatabase.java:1210)
	at liquibase.changelog.ChangeSet.execute(ChangeSet.java:550)
	at liquibase.changelog.visitor.UpdateVisitor.visit(UpdateVisitor.java:43)
	at liquibase.changelog.ChangeLogIterator.run(ChangeLogIterator.java:73)
	at liquibase.Liquibase.update(Liquibase.java:200)
	at liquibase.integration.spring.SpringLiquibase.performUpdate(SpringLiquibase.java:402)
	at liquibase.integration.spring.SpringLiquibase.afterPropertiesSet(SpringLiquibase.java:366)
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeInitMethods(AbstractAutowireCapableBeanFactory.java:1573)
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1511)
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:521)
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:458)
	at org.springframework.beans.factory.support.AbstractBeanFactory$1.getObject(AbstractBeanFactory.java:293)
	at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:223)
	at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:290)
	at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:191)
	at org.springframework.beans.factory.support.DefaultListableBeanFactory.preInstantiateSingletons(DefaultListableBeanFactory.java:636)
	at org.springframework.context.support.AbstractApplicationContext.finishBeanFactoryInitialization(AbstractApplicationContext.java:934)
	at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:479)
	at org.springframework.web.context.ContextLoader.configureAndRefreshWebApplicationContext(ContextLoader.java:410)
	at org.springframework.web.context.ContextLoader.initWebApplicationContext(ContextLoader.java:306)
	at org.springframework.web.context.ContextLoaderListener.contextInitialized(ContextLoaderListener.java:112)
	at org.apache.catalina.core.StandardContext.listenerStart(StandardContext.java:5016)
	at org.apache.catalina.core.StandardContext.startInternal(StandardContext.java:5528)
	at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:150)
	at org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase.java:901)
	at org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:877)
	at org.apache.catalina.core.StandardHost.addChild(StandardHost.java:652)
	at org.apache.catalina.startup.HostConfig.deployWAR(HostConfig.java:1090)
	at org.apache.catalina.startup.HostConfig$DeployWar.run(HostConfig.java:1900)
	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:1142)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
	at java.lang.Thread.run(Thread.java:745)
Caused by: com.mysql.jdbc.exceptions.jdbc4.MySQLSyntaxErrorException: Invalid default value for 'CALL_END_TIME'
	at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
	at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
	at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
	at java.lang.reflect.Constructor.newInstance(Constructor.java:422)
	at com.mysql.jdbc.Util.handleNewInstance(Util.java:408)
	at com.mysql.jdbc.Util.getInstance(Util.java:383)
	at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:1062)
	at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:4226)
	at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:4158)
	at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2615)
	at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2776)
	at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2834)
	at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2783)
	at com.mysql.jdbc.StatementImpl.execute(StatementImpl.java:908)
	at com.mysql.jdbc.StatementImpl.execute(StatementImpl.java:788)
	at org.apache.tomcat.dbcp.dbcp.DelegatingStatement.execute(DelegatingStatement.java:264)
	at org.apache.tomcat.dbcp.dbcp.DelegatingStatement.execute(DelegatingStatement.java:264)
	at liquibase.executor.jvm.JdbcExecutor$ExecuteStatementCallback.doInStatement(JdbcExecutor.java:314)
	... 37 more

The bug comes from a missing or accidentally used oracle format for the timestamp type on that column. Found here on line 25. It’s called when the User api calls log table is created. MySQL 5.6.27 seemed to ignore it when I upgraded that one.

On MySQL 5.6.27 the column where created with defaults correctly:

I think if there is a mysql type for the timestamp liquibase will handle it correctly. Otherwise it may fail going forward with newer versions of MySQL.

github.com

krishagni/openspecimen/blob/OS_v2.4.RC3/WEB-INF/resources/db/2.4/schema.xml#L25


<property name="smallint.type" value="number(5,0)" dbms="oracle" />


<property name="text.type" value="varchar" dbms="mysql" />
<property name="text.type" value="varchar2" dbms="oracle" />


<property name="double.type" value="double"/>


<property name="autoIncrement" value="true" dbms="mysql"/>
<property name="autoIncrement" value="false" dbms="oracle"/>


<property name="timestamp.type" value="timestamp" dbms="oracle" />


<property name="nullable.ts.type" value="timestamp null" dbms="mysql" />
<property name="nullable.ts.type" value="timestamp" dbms="oracle" />


<property name="clob.type" value="text" dbms="mysql"/>
<property name="clob.type" value="clob" dbms="oracle"/>


<property name="decimal.type" value="decimal" dbms="mysql"/>
<property name="decimal.type" value="number" dbms="oracle"/>

nitesh_marwaha · December 1, 2015, 12:11pm

Hi @rkmadsen,

This seems to be bug specific to MySQL-5.7. We have logged a ticket #OPSMN-2668 for this. We will fix this in next release.

Thanks for the feedback.

~Nitesh

rkmadsen · December 4, 2015, 5:53pm

FYI update on the issue: MySQL 5.6 to 5.7.x changes the strict mode of operation of the server. See: http://dev.mysql.com/doc/refman/5.7/en/sql-mode.html#sqlmode_no_zero_date and https://bugs.mysql.com/bug.php?id=75439

So depending on the release you are using of 5.7.x a default zero date will fall on insert, creation of a column or replication from a previous version of MySQL. So either the timestamp will need to be null, or you have to modify the MSQL mode of operation of date restrictions by removing NO_ZERO_DATE and NO_ZERO_IN_DATE if part of a date field contains zeros. I removed those from the @@GLOBAL.sql_mode constants and set as:

set @@GLOBAL.sql_mode=“ONLY_FULL_GROUP_BY,STRICT_TRANS_TABLES,ERROR_FOR_DIVISION_BY_ZERO,NO_AUTO_CREATE_USER,NO_ENGINE_SUBSTITUTION”;

Then the upgrade gets passed the liquibase change set and 2.4 installs on MySQL 5.7.9.

nitesh_marwaha · December 8, 2015, 6:51am

Hi @rkmadsen,

Thanks for the update. We will have a look at this.

~Nitesh