Error when Upgrading

shawn · April 11, 2016, 7:45am

Our rancher server crashed last night when upgrading to v1.0.0-rc7 and I have spent today trying to get it back up with no luck.

There is a problem with updating the database during:

[main] INFO ConsoleStatus - [6/6] [903ms] [0ms] Starting config.

the initial problem was the following:

14:08:01.464 [main] WARN  o.eclipse.jetty.webapp.WebAppContext - Failed startup of context o.e.j.w.WebAppContext@71067de1{/,file:/usr/share/cattle/9283c067b6f96f5ff1e38fb0ddfd8649/,STARTING}{file:/usr/share/cattle/9283c067b6f96f5ff1e38fb0ddfd8649/}
org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'liquibase-core' defined in URL [jar:file:/usr/share/cattle/9283c067b6f96f5ff1e38fb0ddfd8649/WEB-INF/lib/cattle-app-config-0.5.0-SNAPSHOT.jar!/META-INF/cattle/system/spring-system-context.xml]: Invocation of init method failed; nested exception is liquibase.exception.LockException: Could not acquire change log lock.  Currently locked by 55aeced57945 (fe80:0:0:0:42:acff:fe11:2%4) since 4/10/16 1:46 PM

I solved this by following: https://github.com/rancher/rancher/issues/4202

Namely:
update DATABASECHANGELOGLOCK set LOCKED="", LOCKGRANTED=null,LOCKEDBY=null where ID=1;

However, now my error is as follows:

07:18:50.496 [main] INFO  ConsoleStatus - [6/6] [903ms] [0ms] Starting config
2016-04-11 07:18:50,807 INFO    [main] [ConsoleStatus] [1/32] [0ms] [0ms] Loading bootstrap 
2016-04-11 07:18:50,953 INFO    [main] [ConsoleStatus] [2/32] [146ms] [146ms] Loading config-defaults 
2016-04-11 07:18:55,180 WARN    [main] [liquibase] modifyDataType will lose primary key/autoincrement/not null settings for mysql.  Use <sql> and re-specify all configuration if this is the case 
2016-04-11 07:18:55,343 ERROR   [main] [liquibase] classpath:db/changelog.xml: db/core-073.xml::dump1::alena (generated): Change Set db/core-073.xml::dump1::alena (generated) failed.  Error: Error executing SQL ALTER TABLE cattle.instance ADD health_updated datetime(6) NULL: Duplicate column name 'health_updated' liquibase.exception.DatabaseException: Error executing SQL ALTER TABLE cattle.instance ADD health_updated datetime(6) NULL: Duplicate column name 'health_updated'
	at liquibase.executor.jvm.JdbcExecutor.execute(JdbcExecutor.java:61) ~[liquibase-core-3.1.0.jar:na]
	at liquibase.executor.jvm.JdbcExecutor.execute(JdbcExecutor.java:106) ~[liquibase-core-3.1.0.jar:na]
	at liquibase.database.AbstractJdbcDatabase.execute(AbstractJdbcDatabase.java:1189) ~[liquibase-core-3.1.0.jar:na]
	at liquibase.database.AbstractJdbcDatabase.executeStatements(AbstractJdbcDatabase.java:1172) ~[liquibase-core-3.1.0.jar:na]
	at liquibase.changelog.ChangeSet.execute(ChangeSet.java:352) ~[liquibase-core-3.1.0.jar:na]
	at liquibase.changelog.visitor.UpdateVisitor.visit(UpdateVisitor.java:40) [liquibase-core-3.1.0.jar:na]
	at liquibase.changelog.ChangeLogIterator.run(ChangeLogIterator.java:64) [liquibase-core-3.1.0.jar:na]
	at liquibase.Liquibase.update(Liquibase.java:202) [liquibase-core-3.1.0.jar:na]
	at liquibase.Liquibase.update(Liquibase.java:181) [liquibase-core-3.1.0.jar:na]
	at liquibase.integration.spring.SpringLiquibase.performUpdate(SpringLiquibase.java:342) [liquibase-core-3.1.0.jar:na]
	at liquibase.integration.spring.SpringLiquibase.afterPropertiesSet(SpringLiquibase.java:299) [liquibase-core-3.1.0.jar:na]
	at io.cattle.platform.liquibase.Loader.afterPropertiesSet(Loader.java:62) [cattle-framework-db-loader-0.5.0-SNAPSHOT.jar:na]
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeInitMethods(AbstractAutowireCapableBeanFactory.java:1571) [spring-beans-3.2.5.RELEASE.jar:3.2.5.RELEASE]
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1509) [spring-beans-3.2.5.RELEASE.jar:3.2.5.RELEASE]
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:521) [spring-beans-3.2.5.RELEASE.jar:3.2.5.RELEASE]
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:458) [spring-beans-3.2.5.RELEASE.jar:3.2.5.RELEASE]
	at org.springframework.beans.factory.support.AbstractBeanFactory$1.getObject(AbstractBeanFactory.java:296) [spring-beans-3.2.5.RELEASE.jar:3.2.5.RELEASE]
	at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:223) [spring-beans-3.2.5.RELEASE.jar:3.2.5.RELEASE]
	at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:293) [spring-beans-3.2.5.RELEASE.jar:3.2.5.RELEASE]
	at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:194) [spring-beans-3.2.5.RELEASE.jar:3.2.5.RELEASE]
	at org.springframework.beans.factory.support.DefaultListableBeanFactory.preInstantiateSingletons(DefaultListableBeanFactory.java:628) [spring-beans-3.2.5.RELEASE.jar:3.2.5.RELEASE]
	at org.springframework.context.support.AbstractApplicationContext.finishBeanFactoryInitialization(AbstractApplicationContext.java:932) [spring-context-3.2.4.RELEASE.jar:3.2.4.RELEASE]
	at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:479) [spring-context-3.2.4.RELEASE.jar:3.2.4.RELEASE]
	at org.apache.cloudstack.spring.module.model.impl.DefaultModuleDefinitionSet.loadContext(DefaultModuleDefinitionSet.java:184) [cattle-framework-spring-module-0.5.0-SNAPSHOT.jar:na]
	at org.apache.cloudstack.spring.module.model.impl.DefaultModuleDefinitionSet$2.with(DefaultModuleDefinitionSet.java:157) [cattle-framework-spring-module-0.5.0-SNAPSHOT.jar:na]
	at org.apache.cloudstack.spring.module.model.impl.DefaultModuleDefinitionSet.withModule(DefaultModuleDefinitionSet.java:348) [cattle-framework-spring-module-0.5.0-SNAPSHOT.jar:na]
	at org.apache.cloudstack.spring.module.model.impl.DefaultModuleDefinitionSet.withModule(DefaultModuleDefinitionSet.java:358) [cattle-framework-spring-module-0.5.0-SNAPSHOT.jar:na]
	at org.apache.cloudstack.spring.module.model.impl.DefaultModuleDefinitionSet.withModule(DefaultModuleDefinitionSet.java:333) [cattle-framework-spring-module-0.5.0-SNAPSHOT.jar:na]
	at org.apache.cloudstack.spring.module.model.impl.DefaultModuleDefinitionSet.loadContexts(DefaultModuleDefinitionSet.java:152) [cattle-framework-spring-module-0.5.0-SNAPSHOT.jar:na]
	at org.apache.cloudstack.spring.module.model.impl.DefaultModuleDefinitionSet.load(DefaultModuleDefinitionSet.java:97) [cattle-framework-spring-module-0.5.0-SNAPSHOT.jar:na]
	at org.apache.cloudstack.spring.module.factory.ModuleBasedContextFactory.loadModules(ModuleBasedContextFactory.java:37) [cattle-framework-spring-module-0.5.0-SNAPSHOT.jar:na]
	at org.apache.cloudstack.spring.module.factory.CloudStackSpringContext.init(CloudStackSpringContext.java:75) [cattle-framework-spring-module-0.5.0-SNAPSHOT.jar:na]
	at org.apache.cloudstack.spring.module.factory.CloudStackSpringContext.<init>(CloudStackSpringContext.java:56) [cattle-framework-spring-module-0.5.0-SNAPSHOT.jar:na]
	at io.cattle.platform.context.SpringContext.<init>(SpringContext.java:11) [cattle-iaas-system-0.5.0-SNAPSHOT.jar:na]
	at io.cattle.platform.context.WebContextLoaderListener.constructCloudStackSpringContext(WebContextLoaderListener.java:15) [cattle-iaas-system-0.5.0-SNAPSHOT.jar:na]
	at org.apache.cloudstack.spring.module.web.CloudStackContextLoaderListener.contextInitialized(CloudStackContextLoaderListener.java:51) [cattle-framework-spring-module-0.5.0-SNAPSHOT.jar:na]
	at org.eclipse.jetty.server.handler.ContextHandler.callContextInitialized(ContextHandler.java:800) [jetty-server-9.2.11.v20150529.jar:9.2.11.v20150529]
	at org.eclipse.jetty.servlet.ServletContextHandler.callContextInitialized(ServletContextHandler.java:444) [jetty-servlet-9.2.11.v20150529.jar:9.2.11.v20150529]
	at org.eclipse.jetty.server.handler.ContextHandler.startContext(ContextHandler.java:791) [jetty-server-9.2.11.v20150529.jar:9.2.11.v20150529]
	at org.eclipse.jetty.servlet.ServletContextHandler.startContext(ServletContextHandler.java:294) [jetty-servlet-9.2.11.v20150529.jar:9.2.11.v20150529]
	at org.eclipse.jetty.webapp.WebAppContext.startWebapp(WebAppContext.java:1349) [jetty-webapp-9.2.11.v20150529.jar:9.2.11.v20150529]
	at org.eclipse.jetty.webapp.WebAppContext.startContext(WebAppContext.java:1342) [jetty-webapp-9.2.11.v20150529.jar:9.2.11.v20150529]
	at org.eclipse.jetty.server.handler.ContextHandler.doStart(ContextHandler.java:741) [jetty-server-9.2.11.v20150529.jar:9.2.11.v20150529]
	at org.eclipse.jetty.webapp.WebAppContext.doStart(WebAppContext.java:505) [jetty-webapp-9.2.11.v20150529.jar:9.2.11.v20150529]
	at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:68) [jetty-util-9.2.11.v20150529.jar:9.2.11.v20150529]
	at org.eclipse.jetty.util.component.ContainerLifeCycle.start(ContainerLifeCycle.java:132) [jetty-util-9.2.11.v20150529.jar:9.2.11.v20150529]
	at org.eclipse.jetty.server.Server.start(Server.java:387) [jetty-server-9.2.11.v20150529.jar:9.2.11.v20150529]
	at org.eclipse.jetty.util.component.ContainerLifeCycle.doStart(ContainerLifeCycle.java:114) [jetty-util-9.2.11.v20150529.jar:9.2.11.v20150529]
	at org.eclipse.jetty.server.handler.AbstractHandler.doStart(AbstractHandler.java:61) [jetty-server-9.2.11.v20150529.jar:9.2.11.v20150529]
	at org.eclipse.jetty.server.Server.doStart(Server.java:354) [jetty-server-9.2.11.v20150529.jar:9.2.11.v20150529]
	at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:68) [jetty-util-9.2.11.v20150529.jar:9.2.11.v20150529]
	at io.cattle.platform.launcher.jetty.Main.main(Main.java:145) [9283c067b6f96f5ff1e38fb0ddfd8649/:na]
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.7.0_95]
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) ~[na:1.7.0_95]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.7.0_95]
	at java.lang.reflect.Method.invoke(Method.java:606) ~[na:1.7.0_95]
	at io.cattle.platform.launcher.Main.run(Main.java:188) [9283c067b6f96f5ff1e38fb0ddfd8649/:na]
	at io.cattle.platform.launcher.Main.main(Main.java:251) [9283c067b6f96f5ff1e38fb0ddfd8649/:na]
Caused by: java.sql.SQLSyntaxErrorException: Duplicate column name 'health_updated'
	at org.mariadb.jdbc.internal.util.ExceptionMapper.get(ExceptionMapper.java:125) ~[mariadb-java-client-1.3.4.jar:na]
	at org.mariadb.jdbc.internal.util.ExceptionMapper.throwException(ExceptionMapper.java:69) ~[mariadb-java-client-1.3.4.jar:na]
	at org.mariadb.jdbc.MariaDbStatement.executeQueryEpilog(MariaDbStatement.java:261) ~[mariadb-java-client-1.3.4.jar:na]
	at org.mariadb.jdbc.MariaDbStatement.execute(MariaDbStatement.java:290) ~[mariadb-java-client-1.3.4.jar:na]
	at org.mariadb.jdbc.MariaDbStatement.execute(MariaDbStatement.java:344) ~[mariadb-java-client-1.3.4.jar:na]
	at org.apache.commons.dbcp.DelegatingStatement.execute(DelegatingStatement.java:264) ~[commons-dbcp-1.4.jar:1.4]
	at org.apache.commons.dbcp.DelegatingStatement.execute(DelegatingStatement.java:264) ~[commons-dbcp-1.4.jar:1.4]
	at liquibase.executor.jvm.JdbcExecutor$ExecuteStatementCallback.doInStatement(JdbcExecutor.java:294) ~[liquibase-core-3.1.0.jar:na]
	at liquibase.executor.jvm.JdbcExecutor.execute(JdbcExecutor.java:54) ~[liquibase-core-3.1.0.jar:na]
	... 57 common frames omitted
Caused by: org.mariadb.jdbc.internal.util.dao.QueryException: Duplicate column name 'health_updated'
	at org.mariadb.jdbc.internal.protocol.AbstractQueryProtocol.getResult(AbstractQueryProtocol.java:475) ~[mariadb-java-client-1.3.4.jar:na]
	at org.mariadb.jdbc.internal.protocol.AbstractQueryProtocol.result(AbstractQueryProtocol.java:396) ~[mariadb-java-client-1.3.4.jar:na]
	at org.mariadb.jdbc.internal.protocol.AbstractQueryProtocol.executeQuery(AbstractQueryProtocol.java:378) ~[mariadb-java-client-1.3.4.jar:na]
	at org.mariadb.jdbc.internal.protocol.AbstractQueryProtocol.executeQuery(AbstractQueryProtocol.java:334) ~[mariadb-java-client-1.3.4.jar:na]
	at org.mariadb.jdbc.MariaDbStatement.execute(MariaDbStatement.java:280) ~[mariadb-java-client-1.3.4.jar:na]
	... 62 common frames omitted

I have checked the database and db/core-073.xml is not there.

Any help would be awesome It’s a bit scary not having the server up and running.

Cheers,

Shawn

alena · April 12, 2016, 4:37pm

@shawn looks like db upgrade was interrupted; could you check if this query gives you back any data:

select filename from DATABASECHANGELOG where filename='db/core-073.xml';

if not, we would have to rollback changes this file introduced - drop health_updated field from instance table:

alter table instance drop column `health_updated`;

If that was the only problem, server restart afterwards should perform an upgrade again and insert this field successfully. To make sure there are no other missing changes, can you check what is the last entry you have in DATABASECHANGELOG table?

shawn · April 15, 2016, 2:37am

Thanks Alena,

The interrupted update was my probably my impatience When I initially ran the update, It looked like it was hanging on this statement:

2016-04-11 07:18:55,180 WARN [main] [liquibase] modifyDataType will lose primary key/autoincrement/not null settings for mysql. Use and re-specify all configuration if this is the case

when I ran:

select filename from DATABASECHANGELOG where filename='db/core-073.xml';

It was there but the query was empty.

mysql gave me an error when I ran:

alter table instance drop column `health_updated`;

So yesterday I created a fresh database and a fresh install of rancher/server:latest. When I checked a day later everything had updated and the upgraded rancher server was working. It just took a long time.

Topic		Replies	Views
Issue upgrading to v0.31.0 Rancher 1.x	5	2579	August 16, 2016
Issues starting Rancher server Rancher 1.x	1	938	September 10, 2015
Rancher Release - v0.63.1 Announcements	1	1847	March 15, 2016
Failed to acquire lock [SCHEDULED.UPGRADE] Rancher 1.x	1	3182	September 14, 2017
Containers stuck in 'In progress' causing v1.1.2 upgrade to fail Rancher 1.x	1	830	August 19, 2016

Error when Upgrading

Related Topics